A BatchUpdateBiblioHoldsQueue job is triggered from AddRenewal if RealTimeHoldsQueue is set. It is executed inside a transaction and the worker can receive the job to process before the transaction has been committed (and so before the job exists in the DB). The call stack is: opac-renew: AddRenewal In C4::Circulation::AddRenewal 3234 $schema->txn_do(sub{ 3302 $item_object->store({ log_action => 0, skip_record_index => 1 }); In Koha::Item->store 223 Koha::BackgroundJob::BatchUpdateBiblioHoldsQueue->new->enqueue( 224 { 225 biblio_ids => [ $self->biblionumber ] 226 } 227 ) unless $params->{skip_holds_queue} or !C4::Context->preference('RealTimeHoldsQueue'); To recreate: Turn on RealTimeHoldsQueue Check an item in to a patron At the OPAC, renew the checkout => Job 109 not found, or has wrong status main:: /kohadevbox/koha/misc/workers/background_jobs_worker.pl
We should have a "retry" mechanism for background jobs, or enqueuing with delay, or both.
Created attachment 161067 [details] [review] Bug 35819: Retry to fetch job if does not enqueued yet If a job has been enqueued in the middle of a txn, the worker will fetch the job but fail because it's not in the DB yet. The uglier but most effective (as a quick fix and easily backportable fix) is to... wait a bit. This patch suggests to sleep 1sec and retry, 10 times. It should be enough for the majority of the jobs.
Created attachment 161071 [details] [review] [ALTERNATE] Bug 35819: Notify NACK when Job ID not found
I'm not 100% confident with my patch, but sending in case it might open for another options to solve the issue. The idea is to not ACK if the job is not found, making rabbit resend the notification to subscribers.
(In reply to Tomás Cohen Arazi from comment #4) > I'm not 100% confident with my patch, but sending in case it might open for > another options to solve the issue. The idea is to not ACK if the job is not > found, making rabbit resend the notification to subscribers. Shouldnt you have the ack in the catch then? Otherwise the "frame not processed" situation will have the frame reenqueued endlessly (?)
Cannot teat right now but not sure nack will re-enqueue btw
(In reply to Jonathan Druart from comment #6) > Cannot teat right now but not sure nack will re-enqueue btw https://www.rabbitmq.com/stomp.html """ NACK frames can optionally carry the requeue header which controls whether the message will be requeued or discarded/dead lettered. Default value is true. """
The idea of the 2nd patch does attract me more than the sleep/retry. This should serve imo as a temporary bugfix/workaround for backports etc and like we discuss on 35092 that we should move to a less hybrid approach. We should read new jobs from either MQ or DB, not both. See the options in bug 35092 comment7. Current stand shows more people choose option2.
Why not move the enqueue out of the transaction? We can pass "skip_holds_queue" to the store and then handle as we do indexing
Ok, my patch works on my testing. Now writing a good test plan. And researching for a delayed requeue option. Will explain on the commit.
(In reply to Nick Clemens from comment #9) > Why not move the enqueue out of the transaction? We can pass > "skip_holds_queue" to the store and then handle as we do indexing The thing is, you cannot always know something is going to trigger a background job. So coding will become nightmare-ish.
Created attachment 161139 [details] [review] Bug 35819: Notify NACK and requeue when Job ID not found This patch makes the worker reject the incoming frame for putting the message back in the queue, in the event the job id doesn't exist yet. Which is the case when some actions are being triggered inside a transaction which hasn't been commited to the DB yet. To test you will need 3 KTD shells (a) mysql: $ ktd --shell k$ sudo koha-mysql kohadev (b) logs: $ ktd --shell # for restarting the worker and looking at the logs k$ sudo koha-worker --restart kohadev ; tail -f /var/log/koha/kohadev/worker-*.log (c) running the test: $ ktd --shell 1. Have (a), (b) and (c) terminals ready 2. On (c), run: $ perl -MKoha::Database -MKoha::BackgroundJob::BatchUpdateBiblioHoldsQueue -e 'Koha::Database->schema->txn_do( sub { Koha::BackgroundJob::BatchUpdateBiblioHoldsQueue->new->enqueue({ biblio_ids => [ 1 ] }); sleep 1; } );' => FAIL: * (b) shows (once) an error about a job not existing 3. On (a) run: > SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'. 4. Apply this patch 5. Ctrl+c on (b), and re-run to launch the worker with the patch applied 6. Repeat 2 => SUCCESS (partial): The error about the job not existing is displayed many times 7. Repeat 3 => SUCCESS: The job ID mentioned on 6 stands as 'finished'. 8. Sign off :-D Discussion: * The `requeue` header I added is correct, but it is the default behavior anyway. I prefered to make it explicit, though. * To avoid that bunch of retries, we should requeue with some delay. I didn't manage to make it work (yet) but there's a 'delay' plugin for rabbit [1]. We already install the 'stomp' plugin in koha-common.postinst. But this plugin requires downloading it. Which would require further investigation. * As Nick and Marcel pointed, we need to revisit the whole architecture, the need of a MQ (DB polling wouldn't have this problem), etc. But that's for another place. [1] https://hevodata.com/learn/rabbitmq-delayed-message/#:~:text=To%20delay%20a%20message%2C%20the,to%20queues%20or%20other%20exchanges.
FTR: I manually installed the mentioned RabbitMQ plugin [1], and couldn't make it work. [1] v3.8.9 here https://github.com/rabbitmq/rabbitmq-delayed-message-exchange
Hmm Seeing: PRECONDITION_FAILED - unknown delivery tag 1
(In reply to Marcel de Rooy from comment #14) > Hmm Seeing: > PRECONDITION_FAILED - unknown delivery tag 1 "PRECONDITION_FAILED - unknown delivery tag" usually happens because of double ack-ing, ack-ing on wrong channels or ack-ing messages that should not be ack-ed. => ?
(In reply to Marcel de Rooy from comment #15) > (In reply to Marcel de Rooy from comment #14) > > Hmm Seeing: > > PRECONDITION_FAILED - unknown delivery tag 1 > > "PRECONDITION_FAILED - unknown delivery tag" usually happens because of > double ack-ing, ack-ing on wrong channels or ack-ing messages that should > not be ack-ed. > > => ? Cause found in my own changes ;)
https://www.cloudamqp.com/docs/delayed-messages.html Is this a usable pattern? Move it to a 'delayed' queue? Where rabbitmq pushes it back to the work queue when it 'times out'.
Created attachment 161172 [details] [review] Bug 35819: Notify NACK and requeue when Job ID not found This patch makes the worker reject the incoming frame for putting the message back in the queue, in the event the job id doesn't exist yet. Which is the case when some actions are being triggered inside a transaction which hasn't been commited to the DB yet. To test you will need 3 KTD shells (a) mysql: $ ktd --shell k$ sudo koha-mysql kohadev (b) logs: $ ktd --shell # for restarting the worker and looking at the logs k$ sudo koha-worker --restart kohadev ; tail -f /var/log/koha/kohadev/worker-*.log (c) running the test: $ ktd --shell 1. Have (a), (b) and (c) terminals ready 2. On (c), run: $ perl -MKoha::Database -MKoha::BackgroundJob::BatchUpdateBiblioHoldsQueue -e 'Koha::Database->schema->txn_do( sub { Koha::BackgroundJob::BatchUpdateBiblioHoldsQueue->new->enqueue({ biblio_ids => [ 1 ] }); sleep 1; } );' => FAIL: * (b) shows (once) an error about a job not existing 3. On (a) run: > SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'. 4. Apply this patch 5. Ctrl+c on (b), and re-run to launch the worker with the patch applied 6. Repeat 2 => SUCCESS (partial): The error about the job not existing is displayed many times 7. Repeat 3 => SUCCESS: The job ID mentioned on 6 stands as 'finished'. 8. Sign off :-D Discussion: * The `requeue` header I added is correct, but it is the default behavior anyway. I prefered to make it explicit, though. * To avoid that bunch of retries, we should requeue with some delay. I didn't manage to make it work (yet) but there's a 'delay' plugin for rabbit [1]. We already install the 'stomp' plugin in koha-common.postinst. But this plugin requires downloading it. Which would require further investigation. * As Nick and Marcel pointed, we need to revisit the whole architecture, the need of a MQ (DB polling wouldn't have this problem), etc. But that's for another place. [1] https://hevodata.com/learn/rabbitmq-delayed-message/#:~:text=To%20delay%20a%20message%2C%20the,to%20queues%20or%20other%20exchanges. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 161173 [details] [review] Bug 35819: Add simple delay Here I add 500 ms. In my testing with the 1s sleep from the test plan, I might see one or two 'not found' lines. Obviously things depend on the time needed before the txn commits. But it will reduce a flood of these messages. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Re-enqueue is definitely better than the naive sleep approach, great! It is working nicely in my tests. However I think we should: 1. apply this change to misc/workers/es_indexer_daemon.pl (ideally have the duplicated code moved to Koha::BackgroundJobs but that's for another day) 2. remove the "Job not found" warnings from the logs if the job is actually processed later. 3. correctly handle "Frame not processed". If we are enqueuing a job without correctly encoding the data (not JSON) we will never ack or nack and the worker will get stuck.
Created attachment 161267 [details] [review] Bug 35819: nack and not requeue if frame is invalid If a frame cannot be correctly processed (most probably because the body is not valid JSON) then we are not acking or nacking the frame and the worker is stuck. In this specific case we should nack without requeuing the frame. NOTE that requeue must be 'true' or 'false', not 1 or 0, or the default 'true' will be used.
(In reply to Jonathan Druart from comment #20) > 3. correctly handle "Frame not processed". If we are enqueuing a job without > correctly encoding the data (not JSON) we will never ack or nack and the > worker will get stuck. Done in previous patch "nack and not requeue if frame is invalid".
(In reply to Jonathan Druart from comment #20) > 2. remove the "Job not found" warnings from the logs if the job is actually > processed later. Would it make sense to store (in worker memory) the number of tries for a given job? I think so, otherwise we may requeue a job endlessly...
(In reply to Jonathan Druart from comment #23) > (In reply to Jonathan Druart from comment #20) > > 2. remove the "Job not found" warnings from the logs if the job is actually > > processed later. > > Would it make sense to store (in worker memory) the number of tries for a > given job? I think so, otherwise we may requeue a job endlessly... It sounds good. But does it make sense in view of separating the MQ and DB loop as suggested on the omnibus?
(In reply to Marcel de Rooy from comment #24) > (In reply to Jonathan Druart from comment #23) > > (In reply to Jonathan Druart from comment #20) > > > 2. remove the "Job not found" warnings from the logs if the job is actually > > > processed later. > > > > Would it make sense to store (in worker memory) the number of tries for a > > given job? I think so, otherwise we may requeue a job endlessly... > > It sounds good. But does it make sense in view of separating the MQ and DB > loop as suggested on the omnibus? What do you suggest? We keep it buggy? :)
(In reply to Jonathan Druart from comment #25) > (In reply to Marcel de Rooy from comment #24) > > (In reply to Jonathan Druart from comment #23) > > > (In reply to Jonathan Druart from comment #20) > > > > 2. remove the "Job not found" warnings from the logs if the job is actually > > > > processed later. > > > > > > Would it make sense to store (in worker memory) the number of tries for a > > > given job? I think so, otherwise we may requeue a job endlessly... > > > > It sounds good. But does it make sense in view of separating the MQ and DB > > loop as suggested on the omnibus? > > What do you suggest? We keep it buggy? :) LOL As you might be aware, the omnibus was created to resolve an enormous bunch of bugs related to this feature.
Created attachment 161527 [details] [review] Bug 35819: Improve logging Log (warn) if the job will be processed later, but add a debug however. Have a specific log for bad status
(In reply to Jonathan Druart from comment #20) > 2. remove the "Job not found" warnings from the logs if the job is actually > processed later. Done in previous patch "Bug 35819: Improve logging"
Created attachment 161624 [details] [review] Bug 35819: Adjust es_indexer_daemon
(In reply to Jonathan Druart from comment #20) > Re-enqueue is definitely better than the naive sleep approach, great! > > It is working nicely in my tests. > > However I think we should: > 1. apply this change to misc/workers/es_indexer_daemon.pl (ideally have the > duplicated code moved to Koha::BackgroundJobs but that's for another day) Done in "Adjust es_indexer_daemon". Looks like I need to take over here. Ready for testing.
(In reply to Jonathan Druart from comment #20) > Re-enqueue is definitely better than the naive sleep approach, great! > > It is working nicely in my tests. > > However I think we should: > 1. apply this change to misc/workers/es_indexer_daemon.pl (ideally have the > duplicated code moved to Koha::BackgroundJobs but that's for another day) > 2. remove the "Job not found" warnings from the logs if the job is actually > processed later. > 3. correctly handle "Frame not processed". If we are enqueuing a job without > correctly encoding the data (not JSON) we will never ack or nack and the > worker will get stuck. I think I missed a lot on this bug conversation :-P Sorry!
Comment on attachment 161267 [details] [review] Bug 35819: nack and not requeue if frame is invalid Review of attachment 161267 [details] [review]: ----------------------------------------------------------------- ::: misc/workers/background_jobs_worker.pl @@ +125,5 @@ > }; > > + unless ( $args ) { > + Koha::Logger->get({ interface => 'worker' })->warn(sprintf "Frame does not have correct args, ignoring it"); > + $conn->nack( { frame => $frame, requeue => 'false' } ); This is great! I didn't manage to make it work properly!
Comment on attachment 161527 [details] [review] Bug 35819: Improve logging Review of attachment 161527 [details] [review]: ----------------------------------------------------------------- ::: misc/workers/background_jobs_worker.pl @@ +73,4 @@ > $max_processes ||= C4::Context->config('background_jobs_worker')->{max_processes} if C4::Context->config('background_jobs_worker'); > $max_processes ||= 1; > > +my $not_found_retries = {}; This will only work for a single worker, right? I think it is a good compromise approach, and running multiple workers would just make it retry more in the worst case. Just noting it.
This is NSO but the original patch is SO by a QA team member, and has follow-up patches from two QA team members... This shouldn't block our bugs :-D Testing and adding my QA stamp.
Created attachment 161682 [details] [review] Bug 35819: Notify NACK and requeue when Job ID not found This patch makes the worker reject the incoming frame for putting the message back in the queue, in the event the job id doesn't exist yet. Which is the case when some actions are being triggered inside a transaction which hasn't been commited to the DB yet. To test you will need 3 KTD shells (a) mysql: $ ktd --shell k$ sudo koha-mysql kohadev (b) logs: $ ktd --shell # for restarting the worker and looking at the logs k$ sudo koha-worker --restart kohadev ; tail -f /var/log/koha/kohadev/worker-*.log (c) running the test: $ ktd --shell 1. Have (a), (b) and (c) terminals ready 2. On (c), run: $ perl -MKoha::Database -MKoha::BackgroundJob::BatchUpdateBiblioHoldsQueue -e 'Koha::Database->schema->txn_do( sub { Koha::BackgroundJob::BatchUpdateBiblioHoldsQueue->new->enqueue({ biblio_ids => [ 1 ] }); sleep 1; } );' => FAIL: * (b) shows (once) an error about a job not existing 3. On (a) run: > SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'. 4. Apply this patch 5. Ctrl+c on (b), and re-run to launch the worker with the patch applied 6. Repeat 2 => SUCCESS (partial): The error about the job not existing is displayed many times 7. Repeat 3 => SUCCESS: The job ID mentioned on 6 stands as 'finished'. 8. Sign off :-D Discussion: * The `requeue` header I added is correct, but it is the default behavior anyway. I prefered to make it explicit, though. * To avoid that bunch of retries, we should requeue with some delay. I didn't manage to make it work (yet) but there's a 'delay' plugin for rabbit [1]. We already install the 'stomp' plugin in koha-common.postinst. But this plugin requires downloading it. Which would require further investigation. * As Nick and Marcel pointed, we need to revisit the whole architecture, the need of a MQ (DB polling wouldn't have this problem), etc. But that's for another place. [1] https://hevodata.com/learn/rabbitmq-delayed-message/#:~:text=To%20delay%20a%20message%2C%20the,to%20queues%20or%20other%20exchanges. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 161683 [details] [review] Bug 35819: Add simple delay Here I add 500 ms. In my testing with the 1s sleep from the test plan, I might see one or two 'not found' lines. Obviously things depend on the time needed before the txn commits. But it will reduce a flood of these messages. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 161684 [details] [review] Bug 35819: nack and not requeue if frame is invalid If a frame cannot be correctly processed (most probably because the body is not valid JSON) then we are not acking or nacking the frame and the worker is stuck. In this specific case we should nack without requeuing the frame. NOTE that requeue must be 'true' or 'false', not 1 or 0, or the default 'true' will be used. Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 161685 [details] [review] Bug 35819: Improve logging Log (warn) if the job will be processed later, but add a debug however. Have a specific log for bad status Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Created attachment 161686 [details] [review] Bug 35819: Adjust es_indexer_daemon Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
(In reply to Tomás Cohen Arazi from comment #33) > Comment on attachment 161527 [details] [review] [review] > Bug 35819: Improve logging > > Review of attachment 161527 [details] [review] [review]: > ----------------------------------------------------------------- > > ::: misc/workers/background_jobs_worker.pl > @@ +73,4 @@ > > $max_processes ||= C4::Context->config('background_jobs_worker')->{max_processes} if C4::Context->config('background_jobs_worker'); > > $max_processes ||= 1; > > > > +my $not_found_retries = {}; > > This will only work for a single worker, right? > > I think it is a good compromise approach, and running multiple workers would > just make it retry more in the worst case. > > Just noting it. Yes, this is not ideal at all, but I wanted to avoid the wrong warning in the log that would cause confusion. As well as preventing an invalid job (should never happen, right! :D) to block the worker.
Marcel, could you maybe do a final review here?
(In reply to Katrin Fischer from comment #41) > Marcel, could you maybe do a final review here? Sure, will do. Changing status
Created attachment 161752 [details] [review] Bug 35819: Notify NACK and requeue when Job ID not found This patch makes the worker reject the incoming frame for putting the message back in the queue, in the event the job id doesn't exist yet. Which is the case when some actions are being triggered inside a transaction which hasn't been commited to the DB yet. To test you will need 3 KTD shells (a) mysql: $ ktd --shell k$ sudo koha-mysql kohadev (b) logs: $ ktd --shell # for restarting the worker and looking at the logs k$ sudo koha-worker --restart kohadev ; tail -f /var/log/koha/kohadev/worker-*.log (c) running the test: $ ktd --shell 1. Have (a), (b) and (c) terminals ready 2. On (c), run: $ perl -MKoha::Database -MKoha::BackgroundJob::BatchUpdateBiblioHoldsQueue -e 'Koha::Database->schema->txn_do( sub { Koha::BackgroundJob::BatchUpdateBiblioHoldsQueue->new->enqueue({ biblio_ids => [ 1 ] }); sleep 1; } );' => FAIL: * (b) shows (once) an error about a job not existing 3. On (a) run: > SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'. 4. Apply this patch 5. Ctrl+c on (b), and re-run to launch the worker with the patch applied 6. Repeat 2 => SUCCESS (partial): The error about the job not existing is displayed many times 7. Repeat 3 => SUCCESS: The job ID mentioned on 6 stands as 'finished'. 8. Sign off :-D Discussion: * The `requeue` header I added is correct, but it is the default behavior anyway. I prefered to make it explicit, though. * To avoid that bunch of retries, we should requeue with some delay. I didn't manage to make it work (yet) but there's a 'delay' plugin for rabbit [1]. We already install the 'stomp' plugin in koha-common.postinst. But this plugin requires downloading it. Which would require further investigation. * As Nick and Marcel pointed, we need to revisit the whole architecture, the need of a MQ (DB polling wouldn't have this problem), etc. But that's for another place. [1] https://hevodata.com/learn/rabbitmq-delayed-message/#:~:text=To%20delay%20a%20message%2C%20the,to%20queues%20or%20other%20exchanges. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 161753 [details] [review] Bug 35819: Add simple delay Here I add 500 ms. In my testing with the 1s sleep from the test plan, I might see one or two 'not found' lines. Obviously things depend on the time needed before the txn commits. But it will reduce a flood of these messages. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 161754 [details] [review] Bug 35819: nack and not requeue if frame is invalid If a frame cannot be correctly processed (most probably because the body is not valid JSON) then we are not acking or nacking the frame and the worker is stuck. In this specific case we should nack without requeuing the frame. NOTE that requeue must be 'true' or 'false', not 1 or 0, or the default 'true' will be used. Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 161755 [details] [review] Bug 35819: Improve logging Log (warn) if the job will be processed later, but add a debug however. Have a specific log for bad status Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 161756 [details] [review] Bug 35819: Adjust es_indexer_daemon Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> [EDIT] Add forgotten module
Created attachment 161757 [details] [review] Bug 35819: (QA follow-up) Prevent warning on uninitialized retries count Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
No problem for me. Get this further now. WARN misc/workers/background_jobs_worker.pl WARN tidiness The file is less tidy than before (bad/messy lines before: 12, now: 15) WARN misc/workers/es_indexer_daemon.pl WARN tidiness The file is less tidy than before (bad/messy lines before: 19, now: 23)
Pushed for 24.05! Well done everyone, thank you!
Pushed to 23.11.x for 23.11.04
Backported to 23.05.x for upcoming 23.05.10