[Bug 35819] New: "No job found" error for BatchUpdateBiblioHoldsQueue (race condition)
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Bug ID: 35819 Summary: "No job found" error for BatchUpdateBiblioHoldsQueue (race condition) Change sponsored?: --- Product: Koha Version: unspecified Hardware: All OS: All Status: NEW Severity: critical Priority: P5 - low Component: Architecture, internals, and plumbing Assignee: koha-bugs@lists.koha-community.org Reporter: jonathan.druart+koha@gmail.com QA Contact: testopia@bugs.koha-community.org Depends on: 29346 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 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=29346 [Bug 29346] Real-time holds queue update -- 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=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |35092 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35092 [Bug 35092] [OMNIBUS] Remaining background job/worker issues -- 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=35819 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |clemens.tubach@kit.edu, | |michaela.sieber@kit.edu -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #1 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- We should have a "retry" mechanism for background jobs, or enqueuing with delay, or both. -- 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=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |dcook@prosentient.com.au, | |m.de.rooy@rijksmuseum.nl, | |tomascohen@gmail.com -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |Needs Signoff -- 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=35819 --- Comment #2 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- Created attachment 161067 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161067&action=edit 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. -- 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=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|koha-bugs@lists.koha-commun |jonathan.druart+koha@gmail. |ity.org |com -- 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=35819 --- Comment #3 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161071 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161071&action=edit Bug 35819: Notify NACK when Job ID not found -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161071|Bug 35819: Notify NACK when |[ALTERNATE] Bug 35819: description|Job ID not found |Notify NACK when Job ID not | |found -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #4 from Tomás Cohen Arazi <tomascohen@gmail.com> --- 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #5 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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 (?) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #6 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- Cannot teat right now but not sure nack will re-enqueue btw -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #7 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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. """ -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #8 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |kyle@bywatersolutions.com, | |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=35819 --- Comment #9 from Nick Clemens <nick@bywatersolutions.com> --- 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 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #10 from Tomás Cohen Arazi <tomascohen@gmail.com> --- 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #11 from Tomás Cohen Arazi <tomascohen@gmail.com> --- (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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Patch complexity|--- |Small patch -- You are receiving this mail because: You are watching all bug changes.
SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161067|0 |1 is obsolete| | Attachment #161071|0 |1 is obsolete| | --- Comment #12 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161139 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161139&action=edit 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: 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%.... -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #13 from Tomás Cohen Arazi <tomascohen@gmail.com> --- 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 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|jonathan.druart+koha@gmail. |tomascohen@gmail.com |com | -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #14 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Hmm Seeing: PRECONDITION_FAILED - unknown delivery tag 1 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #15 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- (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. => ? -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #16 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- (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 ;) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #17 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- 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'. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Signed Off -- You are receiving this mail because: You are watching all bug changes.
SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161139|0 |1 is obsolete| | --- Comment #18 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161172 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161172&action=edit 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: 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%.... Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #19 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161173 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161173&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Signed Off |Failed QA --- Comment #20 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #21 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- Created attachment 161267 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161267&action=edit 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #22 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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". -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #23 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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... -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #24 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- (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? -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #25 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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? :) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #26 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- (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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #27 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- Created attachment 161527 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161527&action=edit 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 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #28 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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" -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |35920 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35920 [Bug 35920] Centralize code from workers -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #29 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- Created attachment 161624 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161624&action=edit Bug 35819: Adjust es_indexer_daemon -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Jonathan Druart <jonathan.druart+koha@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Failed QA |Needs Signoff --- Comment #30 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #31 from Tomás Cohen Arazi <tomascohen@gmail.com> --- (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! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|tomascohen@gmail.com |jonathan.druart+koha@gmail. | |com -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #32 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Comment on attachment 161267 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161267 Bug 35819: nack and not requeue if frame is invalid Review of attachment 161267: --> (https://bugs.koha-community.org/bugzilla3/page.cgi?id=splinter.html&bug=35819&attachment=161267) ----------------------------------------------------------------- ::: 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! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #33 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Comment on attachment 161527 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161527 Bug 35819: Improve logging Review of attachment 161527: --> (https://bugs.koha-community.org/bugzilla3/page.cgi?id=splinter.html&bug=35819&attachment=161527) ----------------------------------------------------------------- ::: 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #34 from Tomás Cohen Arazi <tomascohen@gmail.com> --- 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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Signed Off -- You are receiving this mail because: You are watching all bug changes.
SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161172|0 |1 is obsolete| | Attachment #161173|0 |1 is obsolete| | Attachment #161267|0 |1 is obsolete| | Attachment #161527|0 |1 is obsolete| | Attachment #161624|0 |1 is obsolete| | --- Comment #35 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161682 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161682&action=edit 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: 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%.... Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #36 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161683 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161683&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #37 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161684 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161684&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #38 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161685 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161685&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #39 from Tomás Cohen Arazi <tomascohen@gmail.com> --- Created attachment 161686 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161686&action=edit Bug 35819: Adjust es_indexer_daemon Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Tomás Cohen Arazi <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Signed Off |Passed QA -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #40 from Jonathan Druart <jonathan.druart+koha@gmail.com> --- (In reply to Tomás Cohen Arazi from comment #33)
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.
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. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #41 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- Marcel, could you maybe do a final review here? -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- QA Contact|testopia@bugs.koha-communit |m.de.rooy@rijksmuseum.nl |y.org | Status|Passed QA |Signed Off --- Comment #42 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- (In reply to Katrin Fischer from comment #41)
Marcel, could you maybe do a final review here?
Sure, will do. Changing status -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Signed Off |Passed QA -- You are receiving this mail because: You are watching all bug changes.
SELECT * FROM background_jobs; => FAIL: Notice the job ID mentioned on 2 stands as 'new'.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161682|0 |1 is obsolete| | --- Comment #43 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161752 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161752&action=edit 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: 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%.... 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161683|0 |1 is obsolete| | --- Comment #44 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161753 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161753&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161684|0 |1 is obsolete| | --- Comment #45 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161754 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161754&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161685|0 |1 is obsolete| | --- Comment #46 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161755 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161755&action=edit 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> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Marcel de Rooy <m.de.rooy@rijksmuseum.nl> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #161686|0 |1 is obsolete| | --- Comment #47 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161756 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161756&action=edit 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 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #48 from Marcel de Rooy <m.de.rooy@rijksmuseum.nl> --- Created attachment 161757 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=161757&action=edit Bug 35819: (QA follow-up) Prevent warning on uninitialized retries count Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #49 from 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) -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Katrin Fischer <katrin.fischer@bsz-bw.de> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Passed QA |Pushed to master Version(s)| |24.05.00 released in| | -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 --- Comment #50 from Katrin Fischer <katrin.fischer@bsz-bw.de> --- Pushed for 24.05! Well done everyone, thank you! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Fridolin Somers <fridolin.somers@biblibre.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |fridolin.somers@biblibre.co | |m Version(s)|24.05.00 |24.05.00,23.11.04 released in| | Status|Pushed to master |Pushed to stable --- Comment #51 from Fridolin Somers <fridolin.somers@biblibre.com> --- Pushed to 23.11.x for 23.11.04 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=35819 Lucas Gass <lucas@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Pushed to stable |Pushed to oldstable CC| |lucas@bywatersolutions.com Version(s)|24.05.00,23.11.04 |24.05.00,23.11.04,23.05.10 released in| | --- Comment #52 from Lucas Gass <lucas@bywatersolutions.com> --- Backported to 23.05.x for upcoming 23.05.10 -- You are receiving this mail because: You are watching all bug changes.
participants (1)
-
bugzilla-daemon@bugs.koha-community.org