Bug 33287 - Race condition in Koha::BackgroundJob?
Summary: Race condition in Koha::BackgroundJob?
Status: RESOLVED DUPLICATE of bug 30172
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: 22.11
Hardware: All All
: P3 major (vote)
Assignee: Bugs List
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-03-20 20:19 UTC by Janusz Kaczmarek
Modified: 2023-03-22 17:44 UTC (History)
3 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Janusz Kaczmarek 2023-03-20 20:19:23 UTC
With 22.11.03, I am experiencing the following: with ES indexing on, some record, sometimes, are not being indexed.  A long time after record insertion I can still find respective entries in Administration > Manage jobs, and also background_jobs entries with status ‘new’, background_jobs.enqueued_on equal to respective action_logs.timestamp entry, background_jobs.started_on == background_jobs.ended_on == NULL.  At the same time, in worker-output.log there is a line like:

[2023/03/20 17:18:10] [WARN] No job found for id=13218 main:: /usr/share/koha/bin/background_jobs_worker.pl (114)

What is worth noting, the timestamp from worker-output.log is identical with those of action_logs.timestamp and background_jobs.enqueued_on.

Closer inspection of rabbitmq shows that the queue is empty.

I wonder if the following scenario could be true:

1. in Koha::BackgroundJob::enqueue, the job description is being stored in DB and the job is enqueued, i.e. sent to rabbitmq

2. the worker process immediately reads the queue element from rabbitmq, getting the job_id as a part of the answer ($args->{job_id})

3. as a consequence, the worker tries to get the job from DB with Koha::BackgroundJobs->find($args->{job_id}), but the DBIx at this very moment Koha::BackgroundJobs does not answer with a job object, because 'store' story has not finished yet (?)

4. as a result, the worker generates the warning "No job found for id=n"

5. unfortunately, the element has already been read from the queue and the worker will never return to it

When I than imitate the worker function with my own script, looking for the unfulfilled background jobs, I get the job objects from Koha::BackgroundJobs and I can successfully call 

$args = $job->json->decode($job->data);
and 
$job->process( $args );

If p. 3 was true, then we would have a race condition here.  Or maybe there is another explanation for this behavior...?

I wonder if anybody is experiencing same problem.
Comment 1 Nick Clemens 2023-03-20 23:10:37 UTC
This should be fixed in 22.11.05+

*** This bug has been marked as a duplicate of bug 30172 ***
Comment 2 Janusz Kaczmarek 2023-03-21 13:10:22 UTC
(In reply to Nick Clemens from comment #1)
> This should be fixed in 22.11.05+
> 
> *** This bug has been marked as a duplicate of bug 30172 ***

Nick, thank you for your reaction.  I have seen the Bug 30172 and checked that it is applied in 22.11 before filing this bug report.  Despite the fact that Bug 30172 is applied I am still experiencing this issue.  What am I missing?
Comment 3 Nick Clemens 2023-03-21 14:30:31 UTC
It may also be this one then:
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=33019

It's another race condition due to the transaction
Comment 4 Janusz Kaczmarek 2023-03-21 15:20:41 UTC
(In reply to Nick Clemens from comment #3)
> It may also be this one then:
> https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=33019
> 
> It's another race condition due to the transaction

Thank you for this hint.  However, it seems that the case reported and patched by Aleisha is still only the tip of the iceberg.  It seems to me that not only creation a new record causes this issue.  Our findings of today are that it happens (i.e. "No job found for id=nnn" in worker-output.log) also when for instance a user renews his checkouts.

What if, in background_jobs_worker.pl, we waited like 500 ms (100 ms?) before calling Koha::BackgroundJobs->find ?

Or maybe, in Koha::BackgroundJob::enqueue, calling in loop ->in_storage after ->store would give us green light to proceed further to call $conn->send_with_receipt ?
Comment 5 Nick Clemens 2023-03-21 15:30:59 UTC
(In reply to Janusz Kaczmarek from comment #4)
> (In reply to Nick Clemens from comment #3)
> > It may also be this one then:
> > https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=33019
> > 
> > It's another race condition due to the transaction
> 
> Thank you for this hint.  However, it seems that the case reported and
> patched by Aleisha is still only the tip of the iceberg.  It seems to me
> that not only creation a new record causes this issue.  Our findings of
> today are that it happens (i.e. "No job found for id=nnn" in
> worker-output.log) also when for instance a user renews his checkouts.
> 
> What if, in background_jobs_worker.pl, we waited like 500 ms (100 ms?)
> before calling Koha::BackgroundJobs->find ?
> 
> Or maybe, in Koha::BackgroundJob::enqueue, calling in loop ->in_storage
> after ->store would give us green light to proceed further to call
> $conn->send_with_receipt ?

I don't like the idea of a delay built in - I think we need to prevent the race condition if we can.

It looks like this is the same issue - AddRenewal is called in a transaction - so we need to index after the transaction is committed. Could you open a new bug for that one?
Comment 6 Janusz Kaczmarek 2023-03-22 17:44:29 UTC
(In reply to Nick Clemens from comment #5)
[...]
> It looks like this is the same issue - AddRenewal is called in a transaction
> - so we need to index after the transaction is committed. Could you open a
> new bug for that one?

OK, Bug 33309 created.