Bug 15854 - Race condition for sending renewal/check-in notices
Summary: Race condition for sending renewal/check-in notices
Status: Pushed to Stable
Alias: None
Product: Koha
Classification: Unclassified
Component: Notices (show other bugs)
Version: master
Hardware: All All
: P5 - low normal (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Whiteboard:
Keywords:
Depends on:
Blocks: 18364
  Show dependency treegraph
 
Reported: 2016-02-18 08:54 UTC by Katrin Fischer
Modified: 2017-05-03 03:48 UTC (History)
12 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Bot Control: ---
When did the bot last check this:
Who signed the patch off:
Text to go in the release notes:


Attachments
Bug 15854: Simplify the code to limit race conditions (4.75 KB, patch)
2017-02-09 11:50 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15854: Use a READ and WRITE LOCK on message_queue (2.25 KB, patch)
2017-02-09 11:50 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15854: Simplify the code to limit race conditions (4.93 KB, patch)
2017-03-03 19:23 UTC, Marc Véron
Details | Diff | Splinter Review
Bug 15854: Use a READ and WRITE LOCK on message_queue (2.42 KB, patch)
2017-03-03 19:25 UTC, Marc Véron
Details | Diff | Splinter Review
Bug 15854: Simplify the code to limit race conditions (4.99 KB, patch)
2017-03-21 19:53 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 15854: Use a READ and WRITE LOCK on message_queue (2.49 KB, patch)
2017-03-21 19:53 UTC, Martin Renvoize
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Katrin Fischer 2016-02-18 08:54:25 UTC
Renewal notices are sent as digests - all renewed items are collected in one e-mail that is sent out with the process_messagequeue. We have a library, where sometimes this doesn't work. Instead of one single e-mail notice to the patron for one 'process_messagequeue' interval, multiple renewal notices are generated. The majority of e-mails is generated correctly.

Looking at the code, this is about how it works:
- AddRenewal is exectuted per item and calls
- SendCirculationAlert which calls 
- C4::Message->find_last_message to help decide if a new notice has to be generated or an existing one can be amended

In order to test this, you need:
- EnhancedMessagingPreferences
- Check-out notice checked for the patron you test with
- RenewalSendNotice activated
- A notice called RENEWAL

As I see no problem in the logic so far, I think it could be a race condition where find_last_message doesn't find an existing notice (yet)?
Comment 1 Katrin Fischer 2017-02-09 08:51:56 UTC
We have one installation with Plack and 3.22.14 now, where this happens a lot - with renewal notices, but also with checkout/check-in notices. Any advice on why this happens and how it could be fixed would be much appreciated.
Comment 2 Katrin Fischer 2017-02-09 10:35:38 UTC
(In reply to Katrin Fischer from comment #1)
> We have one installation with Plack and 3.22.14 now, where this happens a
> lot - with renewal notices, but also with check-in notices. Any
> advice on why this happens and how it could be fixed would be much
> appreciated.

Check-out notices appear to be safe - hard to be so fast.
Comment 3 Jonathan Druart 2017-02-09 11:50:30 UTC
Created attachment 60057 [details] [review]
Bug 15854: Simplify the code to limit race conditions

There is an obvious race condition when CHECKIN and RENEWAL are
generated from circulation.pl calling svc/renew or svc/checkin in AJAX.

The 2 first queries will try to get the id of the last message
(find_last_message) and if it does not exist, they will insert it.
Theorically that could be lead to have several "digest" messages for a
given patron.
I did not recreate more than 2 messages, from the third one at least one
of the two firsts existed in the DB already.

This patch just simplifies the code to make the SELECT and INSERT or
UPDATE closer and limit the race condition possibilities.

Test plan:
0. Set RenewalSendNotice and circ rules to have a lot of renewals available
1. Use batch checkouts (or one by one) to check out several items to a
patron
2. Empty message_queue (at least of this patron)
3. Renew them all at once ("select all" link, "renew or check in"
button)
4. Check the message_queue
Without this patch you have lot of chances to faced a race condition and
get at least 2 messages for the same patron. This is not expected, we
expect 1 digest with all the messages.
With this patch apply you have lot of chances not to face it, but it's
not 100% safe as we do not use a mechanism to lock the table at the DBMS
level.
Comment 4 Jonathan Druart 2017-02-09 11:50:33 UTC
Created attachment 60058 [details] [review]
Bug 15854: Use a READ and WRITE LOCK on message_queue

To make sure we will not never get a race conditions for these kinds of
notices, we need to add a LOCK on the message_queue table.

This does not smell the best way to do that, but I faced deadlock issues
when I tried to use "UPDATE FOR"

https://dev.mysql.com/doc/refman/5.7/en/innodb-locking-reads.html
https://dev.mysql.com/doc/refman/5.7/en/lock-tables.html
https://dev.mysql.com/doc/refman/5.7/en/commit.html

To test this patch, or another solution, you need to apply manually this
change:

         my $message = C4::Message->find_last_message($borrower, $type, $mtt);
         unless ( $message ) {
+            sleep(1);
             C4::Message->enqueue($letter, $borrower, $mtt);
         } else {

And repeat the test plan from first patch.
Do not forget to truncate the message_queue table.
Comment 5 Jonathan Druart 2017-02-09 11:52:13 UTC
Anyone familiar with lock, deadlock and transaction?
Comment 6 Marc Véron 2017-03-03 19:23:46 UTC
Created attachment 60813 [details] [review]
Bug 15854: Simplify the code to limit race conditions

There is an obvious race condition when CHECKIN and RENEWAL are
generated from circulation.pl calling svc/renew or svc/checkin in AJAX.

The 2 first queries will try to get the id of the last message
(find_last_message) and if it does not exist, they will insert it.
Theorically that could be lead to have several "digest" messages for a
given patron.
I did not recreate more than 2 messages, from the third one at least one
of the two firsts existed in the DB already.

This patch just simplifies the code to make the SELECT and INSERT or
UPDATE closer and limit the race condition possibilities.

Test plan:
0. Set RenewalSendNotice and circ rules to have a lot of renewals available
1. Use batch checkouts (or one by one) to check out several items to a
patron
2. Empty message_queue (at least of this patron)
3. Renew them all at once ("select all" link, "renew or check in"
button)
4. Check the message_queue
Without this patch you have lot of chances to faced a race condition and
get at least 2 messages for the same patron. This is not expected, we
expect 1 digest with all the messages.
With this patch apply you have lot of chances not to face it, but it's
not 100% safe as we do not use a mechanism to lock the table at the DBMS
level.

Tested both patches together, works as expected.
Signed-off-by: Marc Véron <veron@veron.ch>
Comment 7 Marc Véron 2017-03-03 19:25:08 UTC
Created attachment 60814 [details] [review]
Bug 15854: Use a READ and WRITE LOCK on message_queue

To make sure we will not never get a race conditions for these kinds of
notices, we need to add a LOCK on the message_queue table.

This does not smell the best way to do that, but I faced deadlock issues
when I tried to use "UPDATE FOR"

https://dev.mysql.com/doc/refman/5.7/en/innodb-locking-reads.html
https://dev.mysql.com/doc/refman/5.7/en/lock-tables.html
https://dev.mysql.com/doc/refman/5.7/en/commit.html

To test this patch, or another solution, you need to apply manually this
change:

         my $message = C4::Message->find_last_message($borrower, $type, $mtt);
         unless ( $message ) {
+            sleep(1);
             C4::Message->enqueue($letter, $borrower, $mtt);
         } else {

And repeat the test plan from first patch.
Do not forget to truncate the message_queue table.

Followed test plans, works as expected.
Signed-off-by: Marc Véron <veron@veron.ch>
Comment 8 Martin Renvoize 2017-03-21 19:53:38 UTC
Created attachment 61421 [details] [review]
Bug 15854: Simplify the code to limit race conditions

There is an obvious race condition when CHECKIN and RENEWAL are
generated from circulation.pl calling svc/renew or svc/checkin in AJAX.

The 2 first queries will try to get the id of the last message
(find_last_message) and if it does not exist, they will insert it.
Theorically that could be lead to have several "digest" messages for a
given patron.
I did not recreate more than 2 messages, from the third one at least one
of the two firsts existed in the DB already.

This patch just simplifies the code to make the SELECT and INSERT or
UPDATE closer and limit the race condition possibilities.

Test plan:
0. Set RenewalSendNotice and circ rules to have a lot of renewals available
1. Use batch checkouts (or one by one) to check out several items to a
patron
2. Empty message_queue (at least of this patron)
3. Renew them all at once ("select all" link, "renew or check in"
button)
4. Check the message_queue
Without this patch you have lot of chances to faced a race condition and
get at least 2 messages for the same patron. This is not expected, we
expect 1 digest with all the messages.
With this patch apply you have lot of chances not to face it, but it's
not 100% safe as we do not use a mechanism to lock the table at the DBMS
level.

Tested both patches together, works as expected.
Signed-off-by: Marc Véron <veron@veron.ch>

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 9 Martin Renvoize 2017-03-21 19:53:41 UTC
Created attachment 61422 [details] [review]
Bug 15854: Use a READ and WRITE LOCK on message_queue

To make sure we will not never get a race conditions for these kinds of
notices, we need to add a LOCK on the message_queue table.

This does not smell the best way to do that, but I faced deadlock issues
when I tried to use "UPDATE FOR"

https://dev.mysql.com/doc/refman/5.7/en/innodb-locking-reads.html
https://dev.mysql.com/doc/refman/5.7/en/lock-tables.html
https://dev.mysql.com/doc/refman/5.7/en/commit.html

To test this patch, or another solution, you need to apply manually this
change:

         my $message = C4::Message->find_last_message($borrower, $type, $mtt);
         unless ( $message ) {
+            sleep(1);
             C4::Message->enqueue($letter, $borrower, $mtt);
         } else {

And repeat the test plan from first patch.
Do not forget to truncate the message_queue table.

Followed test plans, works as expected.
Signed-off-by: Marc Véron <veron@veron.ch>

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 10 Martin Renvoize 2017-03-21 19:54:32 UTC
Well done Jonathan, not a simple one there.

Passing QA.
Comment 11 Brendan Gallagher 2017-03-23 15:51:45 UTC
Pushed to Master - Should be in the 17.05 release.  Thanks!
Comment 12 Katrin Fischer 2017-03-26 21:10:16 UTC
These patches have been pushed to 16.11.x and will be in 16.11.06
.
Comment 13 Julian Maurice 2017-03-31 13:31:15 UTC
Pushed to 3.22.x, will be in 3.22.19
Comment 14 Jonathan Druart 2017-03-31 16:28:10 UTC
" LOCK TABLES is not transaction-safe and implicitly commits any active transaction before attempting to lock the tables. "

This is bad for tests...
Comment 15 Jonathan Druart 2017-03-31 16:39:41 UTC
(In reply to Jonathan Druart from comment #14)
> " LOCK TABLES is not transaction-safe and implicitly commits any active
> transaction before attempting to lock the tables. "
> 
> This is bad for tests...

Will need to be fixed, see bug 18364.
Stable releases should be safe, SendCirculationAlert is not covered by tests
Comment 16 Marcel de Rooy 2017-04-03 08:02:21 UTC
(In reply to Jonathan Druart from comment #15)
> Stable releases should be safe, SendCirculationAlert is not covered by tests

It may not be called directly from a test.
But what about indirect calls? Maybe from AddReturn or AddRenewal or AddIssue ?
Comment 17 Jonathan Druart 2017-04-03 12:35:04 UTC
(In reply to Marcel de Rooy from comment #16)
> (In reply to Jonathan Druart from comment #15)
> > Stable releases should be safe, SendCirculationAlert is not covered by tests
> 
> It may not be called directly from a test.
> But what about indirect calls? Maybe from AddReturn or AddRenewal or
> AddIssue ?

AFAIK we do not have tests covering messaging preferences.
Comment 18 David Cook 2017-04-13 00:07:11 UTC
(In reply to Jonathan Druart from comment #5)
> Anyone familiar with lock, deadlock and transaction?

In PostgreSQL but not with MySQL.
Comment 19 David Cook 2017-04-13 00:19:45 UTC
Why aren't we logging individual events (e.g. checkout, checkin, renew, etc), and then bundling them together before sending out notices if they're digests?

If it's not a digest, you could log it and run generate_notice which puts it into a mail queue.

If it is a digest, you could log it with a digest/delay flag. Then periodically (e.g. every fifteen minutes), you could group_by to get the patron ids for all digests, then iterate through each patron while getting all the digest events for that patron, and then queue an email. 

process_message_queue could then just run like normal.

I think that would be a lot simpler than using locks. 

After all, the message_queue should just be FIFO, right? Once it's in there, it's in there as a finished product ready to go out.
Comment 20 Marcel de Rooy 2017-04-13 06:42:57 UTC
(In reply to David Cook from comment #19)
> After all, the message_queue should just be FIFO, right? Once it's in there,
> it's in there as a finished product ready to go out.

Handling digests differently doesnt sound bad to me.
Comment 21 Jonathan Druart 2017-04-17 13:08:36 UTC
(In reply to Marcel de Rooy from comment #20)
> (In reply to David Cook from comment #19)
> > After all, the message_queue should just be FIFO, right? Once it's in there,
> > it's in there as a finished product ready to go out.
> 
> Handling digests differently doesnt sound bad to me.

Well, the way digests are handled is pretty bad IMO.
But anyway we are looking for a quick solution to fix an important issue, not rethinking the way we are sending messages.
Comment 22 Mason James 2017-05-03 03:48:45 UTC
(In reply to Julian Maurice from comment #13)
> Pushed to 3.22.x, will be in 3.22.19

Pushed to 16.05.x, for 16.05.12 release