https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #2 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- I am slightly confused by this one, wasn't the idea of RabbitMQ to avoid just this kind of thing? Having a server dealing with the jobs so nothing would be lost and it all done in due time? It seems strange that we run into limitations so soon. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #4 from David Cook <dcook@prosentient.com.au> --- (In reply to Nick Clemens from comment #0)

We saw this happen several times - a library would queue up 6 batch modifications that would take roughly 6 minutes each.

Is that 1 job for 6 items, or is that 6 different jobs? Why were the jobs taking 6 minutes?

The jobs would process normally, until the 30 minute configured timeout would hit - then the remaining job would fail, and rabbit would disconnect and not reconnect, and jobs would pile up

When you say "rabbit would disconnect and not reconnect", are you talking about the RabbitMQ server disconnecting, and then not allowing the koha-worker to reconnect?

It seems that koha receives all of the jobs immediately, but only acknowledges when complete - so the final job was waiting over 30 minutes for acknowledgement and this caused issues

What do you mean by "koha"? Do you mean "koha-worker"? I think we need more information here. -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Julian Maurice <julian.maurice@biblibre.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |julian.maurice@biblibre.com --- Comment #6 from Julian Maurice <julian.maurice@biblibre.com> --- (In reply to David Cook from comment #3)

According to the RabbitMQ Work Queues tutorial, we're doing the right thing by ACKing after the message has been processed.

According to that tutorial, this allows RabbitMQ to redeliver the message to another worker. But do we really want that ? A background job should not be restarted if it failed, because it might fail forever, or because by running it more than once it might do unwanted modifications to the database. I believe that the background job worker should acknowledge the message as soon as it receives it. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Magnus Enger <magnus@libriotech.no> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |magnus@libriotech.no -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #9 from David Cook <dcook@prosentient.com.au> --- (In reply to Julian Maurice from comment #6)

According to that tutorial, this allows RabbitMQ to redeliver the message to another worker. But do we really want that ?

Theoretically, yes. If you have multiple machines with workers running and 1 machine crashes due to a power outage, you probably want the message to be sent to a different worker on a different machine. A simpler scenario is RabbitMQ delivers a message, the worker is working on it, and a sysadmin reboots the server. When it comes back online, RabbitMQ and the worker should start up, and RabbitMQ should re-deliver the message to the worker.

A background job should not be restarted if it failed, because it might fail forever, or because by running it more than once it might do unwanted modifications to the database.

You make a good point about the failing forever. In practice, that seems to be the most common scenario I've encountered. The worker crashes due to a programming error, and then it is just stuck in an infinite failure loop. Not good. Of course, you could argue that isn't the problem of RabbitMQ, but rather someone coded the worker badly ;). Likewise, unwanted modifications to the database can be avoided by coding the worker better.

I believe that the background job worker should acknowledge the message as soon as it receives it.

That's certainly an option. The downside is that if the worker isn't able to complete handling of the message, then that message is gone forever. That might not be a big deal with Koha, since we have the "database fallback". Of course, that could get you into an infinite failure loop as well. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #11 from David Cook <dcook@prosentient.com.au> --- It's an interesting topic though... https://docs.celeryq.dev/en/latest/faq.html#should-i-use-retry-or-acks-late It looks like Celery workers acknowledge messages when they receive them and then they do work. They provide an "acks_late" option for tasks where crashes would be a problem. -- Maybe it is better to ack early so that we can handle longer running tasks, and then we handle failure scenarios more as edge cases... It's probably more likely that you'll have a long running task than an unexpected crash. I think if there is a crash (say VM power outage rather than a fatal error executing a Perl function), the job should get stuck in "started" state as well? So that would allow sysadmins to then deal with that situation (or we could have a cronjob that "times out" jobs in "started" state if they're in that state for longer than X time. -- In that way, we still have timeouts, but we're putting those timeouts into the application rather than relying on RabbitMQ's... -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #13 from David Cook <dcook@prosentient.com.au> --- (In reply to Nick Clemens from comment #12)

...

...

It seems that koha receives all of the jobs immediately, but only acknowledges when complete - so the final job was waiting over 30 minutes for acknowledgement and this caused issues

Thanks for clarifying, Nick. Your comment also made me re-read the description, and it made me realize that I've had this same problem before on a different project, although it was with AMQP rather than STOMP. Let me see the STOMP way of doing it... The problem is that we're not defining a prefetch size. You can see the problem here in ./misc/background_jobs_worker.pl: $conn->subscribe({ destination => sprintf("/queue/%s-%s", $namespace, $queue), ack => 'client' }); As per the docs, we need to set "'activemq.prefetchSize' => 1" in that subscribe hashref argument: https://metacpan.org/pod/Net::Stomp#activemq.prefetchSize If you/we set that, I would bet that your problem goes away. -- I have a RabbitMQ AMQP worker on another project that consumes many thousands of messages a day, and I was noticing timeouts even though it was blazing through the messages. I changed the prefetch size to 1 and ever since there's been no more timeouts. It's just worked like a beast! -- (Katrin, the above is what I mean about us all being beginning with this stuff.) -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #14 from David Cook <dcook@prosentient.com.au> --- Created attachment 144809 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=144809&action=edit Bug 32481: Limit prefetch size for background jobs worker This patch adds a prefetch size of 1 to the background jobs worker, so that it fetches 1 message at a time. Without this change, the RabbitMQ connection timeout when too many messages for slow tasks are fetched at the same time. To test: 0. Apply patch 1. Run background worker 2. Rapidly enqueue multiple jobs that in total will take longer than 30 minutes to process -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 David Cook <dcook@prosentient.com.au> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|koha-bugs@lists.koha-commun |dcook@prosentient.com.au |ity.org | -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #17 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- And what about the 30 minutes timeout? -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #19 from Nick Clemens <nick@bywatersolutions.com> --- (In reply to Jonathan Druart from comment #18)

I think I recreate the problem this way:

% more /etc/rabbitmq/rabbitmq.conf consumer_timeout = 15000

Add a sleep 10 in Koha::BackgroundJob::BatchUpdateItem->process

Then enqueue several batch item mod jobs.

However: 1. I don't see jobs stuck in "new" (without the patch)

2. I am seeing the following in the rabbitmq logs, with and without the patch

2023-01-04 11:01:03.041 [warning] <0.2774.0> Consumer Q_/queue/koha_kohadev-long_tasks on channel 1 has timed out waiting on consumer acknowledgement. Timeout used: 15000 ms

2023-01-04 11:01:03.041 [error] <0.2774.0> Channel error on connection <0.2764.0> (127.0.0.1:39578 -> 127.0.0.1:61613, vhost: '/', user: 'guest'), channel 1: operation none caused a channel exception precondition_failed: consumer ack timed out on channel 1

2023-01-04 11:01:03.042 [error] <0.2758.0> STOMP error frame sent:

Message: precondition_failed Detail: "PRECONDITION_FAILED - consumer ack timed out on channel 1\n" Server private detail: none 2023-01-04 11:01:03.042 [info] <0.2758.0> closing STOMP connection <0.2758.0> (127.0.0.1:39578 -> 127.0.0.1:61613)

I played with this a bunch, and things seem to sometimes recover and sometimes not Setting rabbitmq.conf with: consumer_timeout = 10000 Adding "sleep 1;" in the Koha/BackgroundJob/UpdateElasticIndex.pm sudo koha-mysql kohadev DELETE FROM biblio WHERE biblionumber=269; DELETE FROM biblio WHERE biblionumber=72; Set SearchEngine syspref to 'Elastic' perl misc/maintenance/touch_all_biblios.pl With or without patch, I get errors like: 2023-01-04 16:49:40.689 [warning] <0.7712.0> Consumer Q_/queue/koha_kohadev-default on channel 1 has timed out waiting on consumer acknowledgement. Timeout used: 10000 ms 2023-01-04 16:49:40.692 [error] <0.7712.0> Channel error on connection <0.7703.0> (127.0.0.1:60178 -> 127.0.0.1:61613, vhost: '/', user: 'guest'), channel 1: operation none caused a channel exception precondition_failed: consumer ack timed out on channel 1 2023-01-04 16:49:40.692 [error] <0.7700.0> STOMP error frame sent: Message: precondition_failed Detail: "PRECONDITION_FAILED - consumer ack timed out on channel 1\n" Server private detail: none 2023-01-04 16:49:40.693 [info] <0.7700.0> closing STOMP connection <0.7700.0> (127.0.0.1:60178 -> 127.0.0.1:61613) 2023-01-04 16:49:41.224 [info] <0.14720.0> accepting STOMP connection <0.14720.0> (127.0.0.1:60376 -> 127.0.0.1:61613) 2023-01-04 16:49:41.235 [error] <0.14732.0> Channel error on connection <0.14723.0> (127.0.0.1:60376 -> 127.0.0.1:61613, vhost: '/', user: 'guest'), channel 1: operation basic.ack caused a channel exception precondition_failed: unknown delivery tag 245 2023-01-04 16:49:41.239 [error] <0.14720.0> STOMP error frame sent: Message: precondition_failed Detail: "PRECONDITION_FAILED - unknown delivery tag 245\n" Server private detail: none 2023-01-04 16:49:41.239 [info] <0.14720.0> closing STOMP connection <0.14720.0> (127.0.0.1:60376 -> 127.0.0.1:61613) 2023-01-04 16:49:42.477 [info] <0.14736.0> accepting STOMP connection <0.14736.0> (127.0.0.1:60388 -> 127.0.0.1:61613) And varied number of jobs that remain in new -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #20 from Jonathan Druart <jonathan.druart+koha@gmail.com> ---

operation basic.ack caused a channel exception precondition_failed: unknown delivery tag 245

I think it's the fork, I removed it and it seems to be ok now. Could someone confirm?

Detail: "PRECONDITION_FAILED - consumer ack timed out on channel 1\n"

I am still seeing this after I removed the fork, which means this patch does not fix the timeout problem. I am also seeing this: ':' expected, at character offset 49 (before "CONNECTED\nserver") at /kohadevbox/koha/misc/background_jobs_worker.pl line 97. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Kyle M Hall <kyle@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |kyle@bywatersolutions.com -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #23 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (In reply to Jonathan Druart from comment #22)

The best solution I found is the 2 patches from bug 32393.

But still not idea, I still get gaps. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #25 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- I am giving up, need help. I wrote this script to help adjusting the worker code and see how things went. To test: Edit /etc/rabbitmq/rabbitmq.conf consumer_timeout = 10000 # Delete existing jobs - not needed but better to track down what's going on MariaDB [koha_kohadev]> delete from background_jobs; # Watch the logs % sudo tail -f /var/log/koha/kohadev/* /var/log/rabbitmq/*.log # Run the script % perl test_bg.pl Wait 100 seconds -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #27 from David Cook <dcook@prosentient.com.au> --- (In reply to Jonathan Druart from comment #25)

I am giving up, need help.

I wrote this script to help adjusting the worker code and see how things went.

To test: Edit /etc/rabbitmq/rabbitmq.conf

consumer_timeout = 10000

# Delete existing jobs - not needed but better to track down what's going on MariaDB [koha_kohadev]> delete from background_jobs;

# Watch the logs % sudo tail -f /var/log/koha/kohadev/* /var/log/rabbitmq/*.log

# Run the script % perl test_bg.pl

Wait 100 seconds

I'm not sure I understand. That timeout is 10 seconds but the problem happens after 100 seconds? I'll give the test a go, since those missing frames are disturbing... -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #29 from David Cook <dcook@prosentient.com.au> --- Ok I see the timeout happening 10 seconds after it probably got the first message on the connection/channel. Although according to the logs it processed 51 tasks. That seems odd... I'm going to dive deeper... 622 2023-01-09 00:14:38.291 [info] <0.2408.0> accepting STOMP connection <0.2408.0> (127.0.0.1:58134 -> 127.0.0.1:61613) 623 2023-01-09 00:15:39.033 [warning] <0.2420.0> Consumer Q_/queue/koha_kohadev-default on channel 1 has timed out waiting on consumer acknowledgement. Timeout used: 10000 ms 624 2023-01-09 00:15:39.170 [error] <0.2420.0> Channel error on connection <0.2411.0> (127.0.0.1:58134 -> 127.0.0.1:61613, vhost: '/', user: 'guest'), channel 1: 625 operation none caused a channel exception precondition_failed: consumer ack timed out on channel 1 626 2023-01-09 00:15:39.182 [error] <0.2408.0> STOMP error frame sent: 627 Message: precondition_failed 628 Detail: "PRECONDITION_FAILED - consumer ack timed out on channel 1\n" 629 Server private detail: none 630 2023-01-09 00:15:39.307 [info] <0.2408.0> closing STOMP connection <0.2408.0> (127.0.0.1:58134 -> 127.0.0.1:61613) -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #31 from David Cook <dcook@prosentient.com.au> --- Created attachment 145134 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=145134&action=edit Bug 32481: Use correct prefetch syntax for RabbitMQ According to https://www.rabbitmq.com/stomp.html the header to use for managing the prefetch is "prefetch-count". You can verify the number of delivered and unacknowledged messages on a channel on a connection by running "rabbitmqctl list_channels" on the RabbitMQ host. This will tell you how many messages have been delivered and are awaiting acknowledgement -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #33 from David Cook <dcook@prosentient.com.au> --- That 3rd patch "Bug 32481: Use correct prefetch syntax for RabbitMQ" uses the correct syntax, so the worker only fetches 1 message at a time ( see https://www.rabbitmq.com/stomp.html#pear.p ) Jonathan's test_bg.pl script completes perfectly with it. No time outs. You can verify it using "rabbitmqctl list_channels" as well. Once testers are happy, I'd suggest obsoleting Jonathan's patch and then squashing my 2 patches together. -- Of course, as I note above, the 30 minute timeout will still be an issue for any 1 job that takes longer than 30 minutes. But now I'm confident that Nick's case of 6 jobs of 6 minutes each will be resolved. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Signed Off -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |32594 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32594 [Bug 32594] Add a dedicated ES indexing background worker -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Nick Clemens <nick@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #145173|0 |1 is obsolete| | --- Comment #35 from Nick Clemens <nick@bywatersolutions.com> --- Created attachment 145208 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=145208&action=edit Bug 32481: Limit prefetch size for background jobs worker This patch adds a prefetch size of 1 to the background jobs worker, so that it fetches 1 message at a time. Without this change, the RabbitMQ connection timeout when too many messages for slow tasks are fetched at the same time. To test: 0. Apply patch 1. Run background worker 2. Rapidly enqueue multiple jobs that in total will take longer than 30 minutes to process Bug 32481: Use correct prefetch syntax for RabbitMQ According to https://www.rabbitmq.com/stomp.html the header to use for managing the prefetch is "prefetch-count". You can verify the number of delivered and unacknowledged messages on a channel on a connection by running "rabbitmqctl list_channels" on the RabbitMQ host. This will tell you how many messages have been delivered and are awaiting acknowledgement Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org> Signed-off-by: Nick Clemens <nick@bywatersolutions.com> -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #36 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Pushed to master for 23.05. Nice work everyone, thanks! -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 --- Comment #37 from Jacob O'Mara <jacob.omara@ptfs-europe.com> --- Nice work, thanks everyone! Pushed to 22.11.x for the next release. -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Arthur Suzuki <arthur.suzuki@biblibre.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Pushed to oldstable |Pushed to oldoldstable Version(s)|23.05.00,22.11.02,22.05.09 |23.05.00,22.11.02,22.05.09, released in| |21.11.16 CC| |arthur.suzuki@biblibre.com --- Comment #39 from Arthur Suzuki <arthur.suzuki@biblibre.com> --- applied to 21.11.x for 21.11.16 -- You are receiving this mail because: You are watching all bug changes.

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=32481 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |35089 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35089 [Bug 35089] Background worker: Should prefetch-count be activemq.prefetchSize ? -- You are receiving this mail because: You are watching all bug changes.