[bug]: 0.11.1 : Queue event is locked by another process (queue.locked)

[NathanHbt]

What happened?

Since the update, I have a lot of DEBUG errors:

2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226920150541189
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226396711887713
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227422661714853
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227296453010335
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218228488270783475
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218228052205773776
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226014168294214
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226674372715382
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227052065596301
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227635812049841
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226183339254609
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218228047438947279
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227588632421295
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227443605971878
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227172557464469
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227090955182992
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227531822670764
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227102292386705
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227337720767393
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226932001547142
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218228185056158681
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227285593957278
2025-01-08T14:26:35Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218225889173840699

How can we reproduce the problem?

Upgrade to 0.11.1

Version

v0.11.x

What database are you using?

mySQL

What blob storage are you using?

S3-compatible

Where is your directory located?

Internal

What operating system are you using?

Linux

Relevant log output

No response

Code of Conduct

• I agree to follow this project's Code of Conduct

[NathanHbt]

In trace mode :
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 500ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218243326265012227
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 485ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226829012509567
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 485ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226873272902530
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 500ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218226322684519260
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 500ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218243531270004752
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 486ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218225978533487427
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 501ms, total = 2
2025-01-08T14:30:50Z DEBUG Queue event is locked by another process (queue.locked) queueId = 218227998181036249
2025-01-08T14:30:50Z TRACE Write batch operation (store.data-write) elapsed = 501ms, total = 2

[NathanHbt]

Enregistrement.de.l.ecran.2025-01-08.a.15.32.40.mov

There seems to be an issue with queue management, causing an infinite loop and a significant increase in CPU usage.

[NathanHbt]

[NathanHbt]

Enregistrement.de.l.ecran.2025-01-08.a.16.57.37.mov

[NathanHbt]

I found the issue.

I disabled all the options in the ‘Spam Filter,’ one by one.
Once all the options were disabled => CPU dropped to 30%, and the number of mysql connections to 30.
No more queue-related error messages in the logs.

From the interface, I went into ‘Spam Filter,’ and for each subcategory, I disabled everything.

I then restarted the Stalwart servers on each node (not just a reload, as that wasn’t sufficient).

The problem therefore seems to originate from the ‘Spam Filter.’

The issue is therefore the same for the bug. : #1066

[mdecimus]

Those are debugging messages, not errors. Multiple servers are accessing the same queue and that message just indicates that another node has locked the message in order to deliver it.

[NathanHbt]

Thank you for your feedback. However, I invite you to check my latest response.
The issue I’ve been encountering all day since version 0.11.1 originates from the spam filter.

Feel free to contact me on Discord if you’d like us to identify which specific option is causing the problem.