Bug 18725 - process_message_queue.pl sends duplicate emails if message_queue is not writable
Summary: process_message_queue.pl sends duplicate emails if message_queue is not writable
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Notices (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Kyle M Hall
QA Contact: Marcel de Rooy
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-06-03 22:18 UTC by Barton Chittenden
Modified: 2018-10-24 09:13 UTC (History)
9 users (show)

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


Attachments
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.81 KB, patch)
2017-07-05 15:29 UTC, Kyle M Hall
Details | Diff | Splinter Review
[SIGNED OFF] Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.88 KB, patch)
2017-08-08 10:53 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.72 KB, patch)
2017-10-26 13:04 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.80 KB, patch)
2017-10-26 13:06 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.74 KB, patch)
2018-01-22 19:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (1.80 KB, patch)
2018-01-23 13:07 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - check for writability before sending each message (2.45 KB, patch)
2018-01-23 18:33 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (2.03 KB, patch)
2018-01-24 11:10 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (2.08 KB, patch)
2018-03-26 05:43 UTC, M. Tompsett
Details | Diff | Splinter Review
Bug 18725: Tests to trigger canary case (2.09 KB, patch)
2018-03-26 05:43 UTC, M. Tompsett
Details | Diff | Splinter Review
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable. (2.17 KB, patch)
2018-04-06 09:17 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18725: Tests to trigger canary case (1.97 KB, patch)
2018-04-06 09:17 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18725: (QA follow-up) Restore status in Letters, adjust test (3.96 KB, patch)
2018-04-06 09:17 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18725: (QA Follow-up) Use make_column_dirty instead of status change (3.33 KB, patch)
2018-04-13 07:50 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18725: Test return values of make_column_dirty (1.34 KB, patch)
2018-04-16 15:56 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Barton Chittenden 2017-06-03 22:18:02 UTC
Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.
Comment 1 Kyle M Hall 2017-07-05 15:29:52 UTC
Created attachment 64803 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

I have no good idea on how to test this patch so this is what I've got:
Test Plan:
1) Apply this patch
2) prove t/db_dependent/Letters.t
Comment 2 Katrin Fischer 2017-08-08 10:52:47 UTC
I am not sure if it's the right fix, but everything still seems to work alright.
Comment 3 Katrin Fischer 2017-08-08 10:53:50 UTC
Created attachment 65625 [details] [review]
[SIGNED OFF] Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

I have no good idea on how to test this patch so this is what I've got:
Test Plan:
1) Apply this patch
2) prove t/db_dependent/Letters.t

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 4 Jonathan Druart 2017-08-09 17:46:46 UTC
I am not sure this fix is the best one.

I would suggest to test this kind of issue at the beginning of the cronjob instead. What do you think?

By the way, why do you try 10 times?
Comment 5 Marcel de Rooy 2017-08-11 09:57:29 UTC
+    my $lock_sth = $dbh->prepare('LOCK TABLES message_queue WRITE');
+    my $attempts = 0;
+    until ( $sth->execute() ) {
+        $attempts++;
+        die 'Unable to lock message_queue to update message status: ' . $dbh->errstr() if $attempts > 10;
+        sleep 1;
+    }
+
     my $result = $sth->execute( $params->{'status'},
                                 $params->{'message_id'} );

Hey, you are executing on $sth while you probably meant $lock_sth. You only prepare the lock, and start fake updating with two undefs.

Overall, this seems not a good idea to me. We had problems with locking tables already and you should not lock when we run Letters.t since the lock does a commit. Note that we had a test for prove and an env variable KOHA_NO_TABLE_LOCKS.

If the disk is full, a lot of other jobs must fail too btw. Doesnt the job crash on trying the update btw, or did it only send the same one mail each time? If you cant write to disk, perhaps you could try to save this error condition to the cache in memory ??
Note that processing mail will probably soon fail too without much disk space..
Comment 6 Kyle M Hall 2017-10-26 13:04:52 UTC
Created attachment 68602 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

I have no good idea on how to test this patch so this is what I've got:
Test Plan:
1) Apply this patch
2) prove t/db_dependent/Letters.t

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 7 Kyle M Hall 2017-10-26 13:06:10 UTC
Created attachment 68603 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error
Comment 8 David Bourgault 2017-11-03 18:09:16 UTC
It would be easier if you could provide maybe a hint on how to block access to the message_queue table? Not sure how to test this otherwise.
Comment 9 M. Tompsett 2018-01-18 20:03:37 UTC
Bug 18894 broke this easily applying... I'll get around to fixing it later, if Kyle doesn't beat me to it.
Comment 10 M. Tompsett 2018-01-19 00:04:00 UTC
While the rebase was easy enough to do, I still couldn't figure out how to get step 2 to happen.

When I locked the table, the canary code paused the script execution until I unlocked it.

I did try filling the message_queue table. Somewhere around 1.5 million messages, and it complained the table was full in sql. However, that doesn't prevent an update. And the number of records was a function of how much space was left.

I attempted to 'dd' the drive full, and yet I was still able to run the script.
Comment 11 Kyle M Hall 2018-01-22 19:17:08 UTC
Created attachment 70805 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error
Comment 12 Kyle M Hall 2018-01-23 13:07:15 UTC
Created attachment 70826 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 13 Kyle M Hall 2018-01-23 13:08:59 UTC
(In reply to M. Tompsett from comment #10)
> While the rebase was easy enough to do, I still couldn't figure out how to
> get step 2 to happen.
> 
> When I locked the table, the canary code paused the script execution until I
> unlocked it.
> 
> I did try filling the message_queue table. Somewhere around 1.5 million
> messages, and it complained the table was full in sql. However, that doesn't
> prevent an update. And the number of records was a function of how much
> space was left.
> 
> I attempted to 'dd' the drive full, and yet I was still able to run the
> script.

Hmm. Perhaps make the binary db file readonly?
Comment 14 Kyle M Hall 2018-01-23 18:33:40 UTC
Created attachment 70853 [details] [review]
Bug 18725 - check for writability before sending each message

This will mean that if we fill the disk in the middle of
processing the message queue we will not continue to send messages
even if the database was writable at the time of launch.
Comment 15 Kyle M Hall 2018-01-24 11:10:53 UTC
Created attachment 70876 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error
Comment 16 M. Tompsett 2018-03-08 02:20:07 UTC
Oh, I just thought of one way to try to get it to fail as described: apparmor. Changing apparmor settings might all creation of records, and then crashing horribly on update attempts. But I have such an aversion to apparmor, that I am not even going to try.
Comment 17 M. Tompsett 2018-03-26 05:43:13 UTC
Created attachment 73277 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Comment 18 M. Tompsett 2018-03-26 05:43:16 UTC
Created attachment 73278 [details] [review]
Bug 18725: Tests to trigger canary case

Since replicating the conditions necessary for the canary case
proved difficult, tests were written to simulate it.

prove t/db_dependent/Letters.t

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Comment 19 Marcel de Rooy 2018-04-06 07:28:42 UTC
QA: Looking here
Comment 20 Marcel de Rooy 2018-04-06 09:17:04 UTC
Created attachment 73749 [details] [review]
Bug 18725 - Process_message_queue sends duplicate emails if message_queue is not writable.

Last week, we had a database server whose disk filled, causing database writes to fail.

This meant that messages in message_queue marked 'pending' were not marked as 'sent' when they were added to the postfix mail queue; messages were sent every 15 minutes (as specified in the cron job) until the disk space issues were cleared.

I would suggest adding a token write to the start of process_message_queue.pl as a 'canary in the coal mine'. If the database write fails, process_message_queue should stop, because it's not safe to proceed sending emails that may not be marked 'sent'.

Test Plan:
1) Apply this patch
2) Make the message_queue table unwriteable somehow
3) Run process_message_queue.pl
4) Script should die with error

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 21 Marcel de Rooy 2018-04-06 09:17:09 UTC
Created attachment 73750 [details] [review]
Bug 18725: Tests to trigger canary case

Since replicating the conditions necessary for the canary case
proved difficult, tests were written to simulate it.

prove t/db_dependent/Letters.t

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 22 Marcel de Rooy 2018-04-06 09:17:13 UTC
Created attachment 73751 [details] [review]
Bug 18725: (QA follow-up) Restore status in Letters, adjust test

We need to restore the pending status. Otherwise we will loose some
messages. (Just look at the code.)

Correct number of tests, do not rely on number processed.

The return of SendQueuedMessage is unreliable (just look again at
the code). Viewing this as the number of processed/sent messages seems
a bit useless. It merely serves as an indication now if we started
processing.

Test plan:
Run Letters.t again.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 23 Jonathan Druart 2018-04-06 16:57:24 UTC
I do not understand the trick:

1065         # If this fails the database is unwritable and we won't manage to send a message that continues to be marked 'pending'
1066         $message_object->status('processing'); # enum: same as empty string
1067         return unless $message_object->store();
1068         $message_object->status('pending')->store;

Why not simply:

  return unless $message_object->status('pending')->store;

?
Comment 24 Marcel de Rooy 2018-04-09 06:44:33 UTC
(In reply to Jonathan Druart from comment #23)
> Why not simply:
> 
>   return unless $message_object->status('pending')->store;

That does not trigger an update unless you mark a field as 'dirty' (a DBIx method that is not supported by Koha::Object and is not passed thru either).
Comment 25 Jonathan Druart 2018-04-09 13:42:24 UTC
(In reply to Marcel de Rooy from comment #24)
> (In reply to Jonathan Druart from comment #23)
> > Why not simply:
> > 
> >   return unless $message_object->status('pending')->store;
> 
> That does not trigger an update unless you mark a field as 'dirty' (a DBIx
> method that is not supported by Koha::Object and is not passed thru either).

Indeed, but... the tests pass with this change.
Comment 26 Marcel de Rooy 2018-04-10 12:12:50 UTC
(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)
> > > Why not simply:
> > > 
> > >   return unless $message_object->status('pending')->store;
> > 
> > That does not trigger an update unless you mark a field as 'dirty' (a DBIx
> > method that is not supported by Koha::Object and is not passed thru either).
> 
> Indeed, but... the tests pass with this change.

Yeah, we are testing if sub { return; } indeed returns undef ;)
So the test could perhaps be improved. Writing to a readonly database, or whatever? No blocker for me though..
Comment 27 Jonathan Druart 2018-04-11 17:08:17 UTC
If the tests is bad I'd prefer not to have them. It let us think the changes are covered but they are not.

I tried this: https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_tx_read_only

but it does not work.

    $schema->storage->dbh->do(q|SET SESSION tx_read_only='ON'|);
    $schema->storage->txn_do(sub {
        is( C4::Letters::SendQueuedMessages(), undef, 'Bad store should prevent handling any messages.' );
        $queued_msg->discard_changes; # refresh
        is( $queued_msg->status, 'pending', 'Status still pending' );
    });
    $schema->storage->dbh->do(q|SET SESSION tx_read_only='OFF'|);

If someone wants to try...
Comment 28 Marcel de Rooy 2018-04-13 07:49:40 UTC
(In reply to Jonathan Druart from comment #27)
> If the tests is bad I'd prefer not to have them. It let us think the changes
> are covered but they are not.
> 
> I tried this:
> https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.
> html#sysvar_tx_read_only
> 
> but it does not work.
> 
>     $schema->storage->dbh->do(q|SET SESSION tx_read_only='ON'|);
>     $schema->storage->txn_do(sub {
>         is( C4::Letters::SendQueuedMessages(), undef, 'Bad store should
> prevent handling any messages.' );
>         $queued_msg->discard_changes; # refresh
>         is( $queued_msg->status, 'pending', 'Status still pending' );
>     });
>     $schema->storage->dbh->do(q|SET SESSION tx_read_only='OFF'|);
> 
> If someone wants to try...

I tried a few things too but without the desired result.
Will remove the tests but add a follow-up with the make dirty approach in order to overcome the erroneous 'processing' status change.
Comment 29 Marcel de Rooy 2018-04-13 07:50:18 UTC
Created attachment 74143 [details] [review]
Bug 18725: (QA Follow-up) Use make_column_dirty instead of status change

Moving the status to the invalid 'processing' might well have unwanted
side-effects. (The status column will be set to empty string and we have
a problem if it is not processed.)

This patch allows pass-through of DBIX's make_column_dirty in
Koha::Object (simple tests included) and uses it to force an update.
If the update does not return true, it still exits.

Test plan:
[1] Read the changes.
[2] Run t/db_dependent/Koha/Object.t

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 30 Jonathan Druart 2018-04-13 16:23:03 UTC
Marcel, this change makes sense to me.
However we need to return a Koha::Object instead of DBIC one, otherwise we could have weird side-effects when chaining the calls.

Kyle, would you agree with this fix?
Comment 31 Marcel de Rooy 2018-04-14 13:28:37 UTC
(In reply to Jonathan Druart from comment #30)
> Marcel, this change makes sense to me.
> However we need to return a Koha::Object instead of DBIC one, otherwise we
> could have weird side-effects when chaining the calls.

make_column_dirty has no defined return value in DBIC. So cannot be used in chaining. We could write a wrapper that returns a Koha::Object but we would deviate.
Comment 32 Jonathan Druart 2018-04-16 15:56:18 UTC
Created attachment 74247 [details] [review]
Bug 18725: Test return values of make_column_dirty
Comment 33 Jonathan Druart 2018-04-16 17:12:50 UTC
Pushed to master for 18.05, thanks to everybody involved!
Comment 34 Nick Clemens 2018-05-22 11:06:31 UTC
Pushed to stable for 17.11.6
Comment 35 Fridolin SOMERS 2018-05-23 05:15:43 UTC
Pushed to 17.05.x for v17.05.12