[Koha-bugs] [Bug 33287] New: Race condition in Koha::BackgroundJob?

[bugzilla-daemon at bugs.koha-community.org]

https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=33287

            Bug ID: 33287
           Summary: Race condition in Koha::BackgroundJob?
 Change sponsored?: ---
           Product: Koha
           Version: 22.11
          Hardware: All
                OS: All
            Status: NEW
          Severity: major
          Priority: P3
         Component: Architecture, internals, and plumbing
          Assignee: koha-bugs at lists.koha-community.org
          Reporter: januszop at gmail.com
        QA Contact: testopia at bugs.koha-community.org

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.

-- 
You are receiving this mail because:
You are watching all bug changes.
You are the assignee for the bug.