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'.
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
I am not sure if it's the right fix, but everything still seems to work alright.
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>
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?
+ 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..
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>
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
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.
Bug 18894 broke this easily applying... I'll get around to fixing it later, if Kyle doesn't beat me to it.
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.
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
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>
(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?
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.
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
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.
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>
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>
QA: Looking here
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>
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>
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>
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; ?
(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).
(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.
(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..
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...
(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.
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>
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?
(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.
Created attachment 74247 [details] [review] Bug 18725: Test return values of make_column_dirty
Pushed to master for 18.05, thanks to everybody involved!
Pushed to stable for 17.11.6
Pushed to 17.05.x for v17.05.12