Bug 30172 - Background jobs failing due to race condition
Summary: Background jobs failing due to race condition
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Martin Renvoize
URL:
Keywords:
Depends on: 22417
Blocks: 30654 30345 30350
  Show dependency treegraph
 
Reported: 2022-02-23 20:14 UTC by Nick Clemens
Modified: 2022-09-26 18:26 UTC (History)
10 users (show)

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


Attachments
Bug 30172: Prevent race condition when enqueuing a new task (2.82 KB, patch)
2022-02-24 09:44 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Prevent race condition when enqueuing a new task (4.37 KB, patch)
2022-02-24 10:54 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Ensure we can reach the server before inserting the job (1.18 KB, patch)
2022-03-22 13:54 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Prevent race condition when enqueuing a new task (4.35 KB, patch)
2022-03-24 12:59 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Ensure we can reach the server before inserting the job (1.18 KB, patch)
2022-03-24 12:59 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Enqueue the job even if rabbitmq is not reachable (1.30 KB, patch)
2022-03-24 15:23 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Enqueue the job even if rabbitmq is not reachable (1.36 KB, patch)
2022-03-24 15:24 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30172: Prevent race condition when enqueuing a new task (4.40 KB, patch)
2022-03-24 15:50 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 30172: Enqueue the job even if rabbitmq is not reachable (1.42 KB, patch)
2022-03-24 15:51 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 30172: Prevent race condition when enqueuing a new task (4.46 KB, patch)
2022-03-24 17:26 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30172: Enqueue the job even if rabbitmq is not reachable (1.48 KB, patch)
2022-03-24 17:26 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30172: Prevent race condition when enqueuing a new task (4.52 KB, patch)
2022-03-25 12:58 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30172: Enqueue the job even if rabbitmq is not reachable (1.53 KB, patch)
2022-03-25 12:58 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Nick Clemens 2022-02-23 20:14:35 UTC
We are receiving reports from production of background jobs that show as 'new' in the database that are not being processed.

There are no errors or exceptions relating to enqueueing from the broker

We do see in the worker-output.log:
Can't call method "process" on an undefined value at /usr/share/koha/bin/background_jobs_worker.pl line 80.

In Koha/BackGroundJob.pm:
 94 sub enqueue {
...
104     $self->_result->result_source->schema->txn_do(
105         sub {
106             $self->set(
107                 {
108                     status         => 'new',
...
114                 }
115             )->store;
...
121             try {
122                 my $conn = $self->connect;
...
128                 $conn->send_with_receipt( { destination => sprintf("/queue/%s-%s", $namespace, $job_type), body => $json_args } )
129                   or Koha::Exceptions::Exception->throw('Job has not been enqueued');
130             } catch {
...
138     );
^^End of transaction


What appears to be happening is that:
1 - The transaction is begun
2 - Job info is stored internally, but not committed
3 - the job is being sent to Rabbit
4 - Rabbit attempts to process the job, and fails as it cannot find the data in the DB
3 - The transaction completes

We are left with jobs sitting at 'new' with no errors and they are never processed
Comment 1 Liz Rea 2022-02-23 20:38:36 UTC
Noting that the rabbitmq server is external to the Koha frontend, and not on the box like with a standard package install when we see this.
Comment 2 Jonathan Druart 2022-02-23 22:26:19 UTC
Which exact version of Koha?
Some fixes from 21.11 haven't been backported, it may come from that.
Comment 3 David Cook 2022-02-24 02:52:58 UTC
(In reply to Nick Clemens from comment #0)
> What appears to be happening is that:
> 1 - The transaction is begun
> 2 - Job info is stored internally, but not committed
> 3 - the job is being sent to Rabbit
> 4 - Rabbit attempts to process the job, and fails as it cannot find the data
> in the DB
> 3 - The transaction completes
> 

I've had this same problem in non-Koha projects. My background worker was too fast, and would get the message before the monolithic app could commit the data to the database. 

(Note that in my case I didn't actually *need* to do a database call in my background worker, so I just sidestepped the issue.)

(In reply to Jonathan Druart from comment #2)
> Which exact version of Koha?
> Some fixes from 21.11 haven't been backported, it may come from that.

I'm looking at master now, and it looks like it has the same race condition. The "send_with_receipt" should be moved outside and after the "txn_do".
Comment 4 Jonathan Druart 2022-02-24 09:44:29 UTC
Created attachment 131060 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.
Comment 5 Jonathan Druart 2022-02-24 10:54:51 UTC
Created attachment 131061 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.
Comment 6 Jonathan Druart 2022-02-24 10:56:53 UTC
Nick suggested me to set the status to "failed" in case the job was not enqueued.
I am not sure it's the best we can do.

If a job is started but the connection failed, the exception will be thrown but the job will appear in the DB table. If the user already got the error on the UI I don't know if the job should be inserted.
Comment 7 Nick Clemens 2022-02-24 11:34:43 UTC
There is another approach we could try.

In misc/background_jobs_worker.pl we have:
 61         my $job = Koha::BackgroundJobs->find($args->{job_id});
 62 
 63         process_job( $job, $args );
 64         $conn->ack( { frame => $frame } ); # FIXME depending on success?


Perhaps:
 61         my $job = Koha::BackgroundJobs->find($args->{job_id});
 62         $conn->nack({frame=>$frame}) unless $job;
 63             process_job( $job, $args );
 64         $conn->ack( { frame => $frame } ); # FIXME depending on success?

Though could we end up in a loop? The queue should expire eventually - and we could store soemthing in the job about retries when we send nack?
Comment 8 David Cook 2022-02-24 23:40:55 UTC
(In reply to Jonathan Druart from comment #6)
> Nick suggested me to set the status to "failed" in case the job was not
> enqueued.
> I am not sure it's the best we can do.
> 
> If a job is started but the connection failed, the exception will be thrown
> but the job will appear in the DB table. If the user already got the error
> on the UI I don't know if the job should be inserted.

You could test the MQ connection before inserting into the database. 

But if the MQ connection succeeds, you have to insert into the database before sending the message to the MQ. Otherwise that race condition will persist.

If the "send_with_receipt" fails, then I think marking the job as "failed" would be fair. (Alternatively, I suppose you could delete the job after warning the user it failed.)
Comment 9 David Cook 2022-02-24 23:48:25 UTC
(In reply to Nick Clemens from comment #7)
> Perhaps:
>  61         my $job = Koha::BackgroundJobs->find($args->{job_id});
>  62         $conn->nack({frame=>$frame}) unless $job;
>  63             process_job( $job, $args );
>  64         $conn->ack( { frame => $frame } ); # FIXME depending on success?
> 
> Though could we end up in a loop? The queue should expire eventually - and
> we could store soemthing in the job about retries when we send nack?

There's a few problems with that suggestion.

First, you'd need an if/else rather than an unless. Otherwise, you're nacking, then trying to process the job, and then acking. I imagine that was just a typo though.

Second, as you say, you'll end up in a loop if you nack. I don't think the message expires either. (Of course, if the issue is just the race condition, eventually the data should exist, so you'd only loop X times until the database catches up. Not efficient, especially as you'd be blocking other messages being processed, but technically functional.)

--

I think the best bet is just to make sure the data is committed to the database before sending the message. 

(Alternatively, you can make sure that all the data you need is sent in the message itself, so that there is no race condition, but that can be more difficult to manage. In terms of managing the result store, you can generate a UUID, store it in the job table, and use it for storing the result in a result_store table, and then use the UUID to unite the two later, but that would be a big refactor I imagine.)
Comment 10 Jonathan Druart 2022-03-22 13:49:30 UTC
Can we get a signoff on this patch? It should fix the problem initially reported here.
Comment 11 Jonathan Druart 2022-03-22 13:54:11 UTC
Created attachment 132023 [details] [review]
Bug 30172: Ensure we can reach the server before inserting the job
Comment 12 Jonathan Druart 2022-03-22 13:54:45 UTC
This follow-up will ensure the connection can be established before we insert the job.
Comment 13 Tomás Cohen Arazi 2022-03-23 19:51:06 UTC
Something smells here :-D

We have a daemon that runs in two ways: listening to the STOMP protocol, or just polling the DB...

And we have a task initiator (i.e. a call to ->enqueue) that needs to decide if it does through the STOMP protocol or just inserts on the DB...

It feels like the message broker is only adding complexity with no obvious gain?
Comment 14 David Cook 2022-03-24 00:05:51 UTC
(In reply to Tomás Cohen Arazi from comment #13)
> We have a daemon that runs in two ways: listening to the STOMP protocol, or
> just polling the DB...
> 
> And we have a task initiator (i.e. a call to ->enqueue) that needs to decide
> if it does through the STOMP protocol or just inserts on the DB...

Could you re-phrase this? I'm not sure what you're saying here.

Ultimately, the database acts as a result store. The message broker passes the message from the web app to a background worker. The background worker processes the message and updates the result store. The web app exposes the result store to web users.

The same model is used by other task queues like Celery (https://github.com/celery/celery) and Minion (https://metacpan.org/pod/Minion -> https://metacpan.org/release/SRI/Minion-10.23/source/lib/Minion/Backend/Pg.pm#L35). 

While Celery uses message brokers, Minion does poll the database.
Comment 15 David Cook 2022-03-24 00:25:45 UTC
(In reply to Tomás Cohen Arazi from comment #13)
> It feels like the message broker is only adding complexity with no obvious
> gain?

I think the obvious gain is asynchronous background processing (using a language agnostic industry standard message broker). Koha certainly has need for a lot more asynchronous background processing.

That said, there are times where I wish that we'd just used Minion instead as it seems to be a complete solution - whereas we've created a partial bespoke solution around RabbitMQ. (That said, Minion also only supports PostgreSQL out of the box. There's a third-party MySQL backend but it looks a little dodgy.)

One of my hopes with RabbitMQ was that it would allow us to move beyond just Perl (whereas Minion is Perl-only). However, in practice, I don't think we've needed to branch out beyond Perl server-side. Even if we did, there would still be the issue of the result store. We'd need to either use a HTTP API for recording results or build an interface to the result store in whichever language we were using, which would mean some code duplication. 

Pros and cons...

In any case though, I think this particular bug report is just a growing pain.
Comment 16 Jonathan Druart 2022-03-24 06:31:55 UTC
What about the last patch setw David?
Comment 17 Tomás Cohen Arazi 2022-03-24 12:18:08 UTC
My comment was not meant to hijack this bug, which is real and needs to get fixed.

Testing.
Comment 18 Jonathan Druart 2022-03-24 12:59:35 UTC
Created attachment 132140 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.
Comment 19 Jonathan Druart 2022-03-24 12:59:41 UTC
Created attachment 132141 [details] [review]
Bug 30172: Ensure we can reach the server before inserting the job
Comment 20 Jonathan Druart 2022-03-24 13:00:01 UTC
Patches rebased.
Comment 21 Nick Clemens 2022-03-24 13:46:42 UTC
After these patches no jobs are enqueued if you cannot reach the broker

I aded to koha-conf:
 <message_broker>
   <hostname>localhost</hostname>
   <port>61614</port>
   <username>guest</username>
   <password>guest</password>
   <vhost></vhost>
 </message_broker>


Before patches, job added, picked up by SQL polling

After patches:
 Cannot enqueue this job. (The error was: Failed to connect: Error connecting to localhost:61614: Cannot assign requested address at /usr/share/perl5/Net/Stomp.pm line 27.; giving up at /usr/share/perl5/Net/Stomp.pm line 27. . See the Koha logfile for more information).
Comment 22 Jonathan Druart 2022-03-24 13:55:58 UTC
(In reply to Nick Clemens from comment #21)
> After these patches no jobs are enqueued if you cannot reach the broker
> 
> I aded to koha-conf:
>  <message_broker>
>    <hostname>localhost</hostname>
>    <port>61614</port>
>    <username>guest</username>
>    <password>guest</password>
>    <vhost></vhost>
>  </message_broker>
> 
> 
> Before patches, job added, picked up by SQL polling
> 
> After patches:
>  Cannot enqueue this job. (The error was: Failed to connect: Error
> connecting to localhost:61614: Cannot assign requested address at
> /usr/share/perl5/Net/Stomp.pm line 27.; giving up at
> /usr/share/perl5/Net/Stomp.pm line 27. . See the Koha logfile for more
> information).

That's what I understood...
"You could test the MQ connection before inserting into the database. "
Comment 23 Jonathan Druart 2022-03-24 13:58:38 UTC
If the connection fails, the user gets an error. They know that the job hasn't been enqueued.
Comment 24 Nick Clemens 2022-03-24 14:05:52 UTC
(In reply to Jonathan Druart from comment #23)
> If the connection fails, the user gets an error. They know that the job
> hasn't been enqueued.

But we have a backup, we should still  enqueue the job, even it isn't processed

Things are better without second patch, however, we still mark job 'Failed' if we can't connect - it should remain 'new' - marking as failed should happen in the worker or process_job.
Comment 25 Jonathan Druart 2022-03-24 15:23:24 UTC
Created attachment 132176 [details] [review]
Bug 30172: Enqueue the job even if rabbitmq is not reachable
Comment 26 Jonathan Druart 2022-03-24 15:23:51 UTC
I forgot the backup!
Comment 27 Jonathan Druart 2022-03-24 15:24:39 UTC
Created attachment 132177 [details] [review]
Bug 30172: Enqueue the job even if rabbitmq is not reachable
Comment 28 Nick Clemens 2022-03-24 15:50:57 UTC
Created attachment 132181 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 29 Nick Clemens 2022-03-24 15:51:01 UTC
Created attachment 132182 [details] [review]
Bug 30172: Enqueue the job even if rabbitmq is not reachable

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 30 Martin Renvoize 2022-03-24 17:26:27 UTC
Created attachment 132196 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 31 Martin Renvoize 2022-03-24 17:26:32 UTC
Created attachment 132197 [details] [review]
Bug 30172: Enqueue the job even if rabbitmq is not reachable

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 32 Martin Renvoize 2022-03-24 17:28:04 UTC
Agreed that this resolves the race condition and I can't find any regressions now we've resolved the one's pointed out.

I too will admit I'm not sure what benefits RabbitMQ brings us.. but that can be for another bug.

Passing QA
Comment 33 Martin Renvoize 2022-03-24 17:35:29 UTC
(In reply to Martin Renvoize from comment #32)
> I too will admit I'm not sure what benefits RabbitMQ brings us.. but that
> can be for another bug.

I suppose I do understand.. it reduces DB hits by removing the need for DB Polling.. i.e instead of waiting 10s and then polling the DB for jobs.. we sit and wait for a STOMP message to be received.. and then look to the DB if we need to for further detail.. so it does kinda make sense to have both.
Comment 34 David Cook 2022-03-24 23:16:09 UTC
(In reply to Martin Renvoize from comment #33)
> (In reply to Martin Renvoize from comment #32)
> > I too will admit I'm not sure what benefits RabbitMQ brings us.. but that
> > can be for another bug.
> 
> I suppose I do understand.. it reduces DB hits by removing the need for DB
> Polling.. i.e instead of waiting 10s and then polling the DB for jobs.. we
> sit and wait for a STOMP message to be received.. and then look to the DB if
> we need to for further detail.. so it does kinda make sense to have both.

+1
Comment 35 Jonathan Druart 2022-03-25 07:05:28 UTC
We are using a message broker to:
* not rewrite our own task scheduler
* not overload the server (only 1 task at a time, with the default configuration)
* handle load balancing
* run some tasks in the time slot you wish (not implement yet of course but that was a plan)
* more flexibility: have several workers, running on different servers, each could deal with a given job type

Also, we are not strongly tight to RabbitMQ and you are free to provide an alternative implementation (it's less than 20 lines of code). We chose RabbitMQ as it's a reference, light, and working out of the box.
Comment 36 Tomás Cohen Arazi 2022-03-25 12:58:16 UTC
Created attachment 132241 [details] [review]
Bug 30172: Prevent race condition when enqueuing a new task

As we are sending the job to the rabbitmq before in the transaction, the
worker can receive the job to process before the transaction committed.

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 37 Tomás Cohen Arazi 2022-03-25 12:58:20 UTC
Created attachment 132242 [details] [review]
Bug 30172: Enqueue the job even if rabbitmq is not reachable

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 38 Kyle M Hall 2022-04-15 10:24:03 UTC
Doesn't apply to 21.11.x. Please rebase if you'd like this to be backported.
Comment 39 Kyle M Hall 2022-04-18 14:22:51 UTC
Pushed to 21.11.x for 21.11.05
Comment 40 Andrew Fuerste-Henry 2022-04-22 14:31:31 UTC
Pushed to 21.05.x for 21.05.14
Comment 41 Victor Grousset/tuxayo 2022-04-25 20:39:57 UTC
Backported: Pushed to 20.11.x branch for 20.11.18
Comment 42 Magnus Enger 2022-04-29 07:20:40 UTC
Is there a quick way to "kickstart" those jobs that are stuck at "New" in the list of background jobs?
Comment 43 Martin Renvoize 2022-04-29 13:38:02 UTC
With Rabbit there is no way to do it right now as far as I'm aware...

You might be able to kill the worker, then kill rabbit, then start the worker... from memory it will fail to connect to rabbit and fall back to db polling.. that first db polling should find all the new tasks and work through them.

Once you've confirmed all your tasks have run you can start rabbit and then restart your worker again to get it to use rabbit instead.

We really aught to improve that.
Comment 44 Magnus Enger 2022-05-02 11:22:44 UTC
Right you are, this did the trick:

$ sudo koha-worker --stop <instance>
$ sudo service rabbitmq-server stop
$ sudo koha-worker --start <instance>

Thanks!
Comment 45 Liz Rea 2022-09-26 18:26:24 UTC
Just wondering what the solution is for external rabbits that you can't stop the rabbitmq server for - disconnect it from kconf?