[Bug 43340] New: Koha's SMTP connection rate can trigger errors
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Bug ID: 43340 Summary: Koha's SMTP connection rate can trigger errors Initiative type: --- Sponsorship --- status: Product: Koha Version: Main Hardware: All OS: All Status: NEW Severity: normal Priority: P5 - low Component: Notices Assignee: koha-bugs@lists.koha-community.org Reporter: kyle@bywatersolutions.com QA Contact: testopia@bugs.koha-community.org CC: martin.renvoize@openfifth.co.uk Target Milestone: --- When sending email, Koha creates a new SMTP connection for each message. Every single notice does a full connect: EHLO => STARTTLS => auth => send => quit A burst of notices means dozens of connections in seconds from one IP. In practice, this seems to trigger Goggole's Google's per-IP connection rate limiting, which responds with 421-4.7.0 at EHLO. Koha doesn't limit simultaneous connections. There's only ever one connection at a time (the cron is a single sequential process). The problem is connection rate, and Koha has no throttle, delay, or connection-reuse. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Eric Swenson <eric@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |eric@bywatersolutions.com --- Comment #1 from Eric Swenson <eric@bywatersolutions.com> --- Yes, I have seen this be an issue for libraries that are trying to use an external SMTP server. The notices don't try again later, they just fail. -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Brendan Lawlor <blawlor@clamsnet.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |blawlor@clamsnet.org -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Kyle M Hall (khall) <kyle@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Summary|Koha's SMTP connection rate |Koha does not gracefully |can trigger errors |handle SMTP 421 responses -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #2 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- I believe I was mistaken about the most basic issue. After more research I remembered we are using Email::Sender::Transport::SMTP::Persistent ( Bug 33964 ) so unless there is a bug in that lib, it's unlikely to be the problem. Be it that or not, the solution is the same. We need to implement an initial and exponential backoff anytime Koha gets a 421 response ( https://mailtester.com/blog/automate-retry-logic-421-4-7-0-try-again-later/ ). -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Kyle M Hall (khall) <kyle@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|koha-bugs@lists.koha-commun |kyle@bywatersolutions.com |ity.org | -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Kyle M Hall (khall) <kyle@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |Needs Signoff -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #3 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208085 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208085&action=edit Bug 43340: Add send_attempts and retry_after columns to message_queue This patch adds two columns to message_queue so Koha can keep track of how many times a temporary SMTP failure prevented a message from being sent, and when it may be tried again. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Note the send_attempts and retry_after columns on message_queue! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #4 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208086 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208086&action=edit Bug 43340: Token delivery endpoint never responds if the OTP message is left pending The send_otp_token controller queues the 2FA_OTP_TOKEN notice, sends it right away with SendQueuedMessages, and then only renders a response if the message ended up 'sent' or 'failed'. A message that is still 'pending' renders nothing at all, so the request hangs until Mojolicious gives up on it. That is what SendQueuedMessages leaves behind when a message domain limit defers the message, and what the following patches leave behind after a temporary SMTP failure. This patch makes the controller treat anything other than 'sent' as not sent and respond with a 400 email_not_sent. Test Plan: 1) Apply this patch 2) prove t/db_dependent/api/v1/two_factor_auth.t -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #5 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208087 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208087&action=edit Bug 43340: Retry with backoff when the SMTP server reports a temporary failure When the mail server answers with a temporary failure, Koha marks the message failed with the failure code SENDMAIL and moves on to the next message. Nothing ever tries that message again unless a librarian notices it and clicks "Resend". Google's SMTP relay in particular will sometimes answer the EHLO with: Net::SMTP=GLOB(0x55eba2c35700)<<< 421-4.7.0 Try again later, closing connection. (EHLO) The throttle only lasts a few seconds, but every remaining message in that run opens a new connection, gets the same 421, and is marked failed. On one busy site the cron logs show bursts of 53, 164 and 248 consecutive failed hold notices inside a single run of process_message_queue.pl, after which the next run 15 minutes later sends everything without a problem. Every one of those notices was lost. This patch makes Koha treat a temporary failure the way an MTA would. A 4xx response from the mail server, or a connection that is refused before Koha gets a response code ( which is what a 421 at the EHLO stage looks like to Email::Sender ), leaves the message pending with a retry_after time and bumps send_attempts. The message is tried again by a later run of process_message_queue.pl after 10 minutes, then 30, 60 and 120 minutes. Only if the fifth attempt also fails is the message marked failed with SENDMAIL as before. Permanent failures are still marked failed right away. Once a server has refused a connection or answered 421 during a run, the remaining messages for that server are deferred without trying to connect, so a server that is rate limiting us sees one connection per run instead of one per message. Resending a message from the notices tab starts the schedule over. Note that an immediate send ( password recovery, for example ) now reports the message as not sent when it was deferred; the message still goes out with the next cron run. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Restart all the things! 4) Point your default SMTP server ( Administration > SMTP servers ) at a host and port where nothing is listening 5) Queue notices for several patrons with email addresses, e.g. check out items with the CHECKOUT notice enabled 6) Run misc/cronjobs/process_message_queue.pl 7) Note a single connection failure in the output followed by a line saying the server is unavailable, and that every notice is still pending! 8) Run process_message_queue.pl again, note the messages are skipped! 9) UPDATE message_queue SET retry_after = NOW() WHERE status = 'pending' 10) Run process_message_queue.pl, note send_attempts is now 2 and retry_after is 30 minutes out! 11) Repeat steps 9 and 10 until the messages are marked failed with "Unhandled email failure" on the patron's Notices tab! 12) Point the SMTP server back at a working mail server 13) Click Resend on a message, run process_message_queue.pl, note the message is sent! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #6 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208088 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208088&action=edit Bug 43340: Add unit tests for retrying after a temporary SMTP failure Patch from commit a6bc23c -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #7 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208089 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208089&action=edit Bug 43340: Add unit tests for SMTP connection reuse when sending SMS Patch from commit ad62ca8 -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #8 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208090 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208090&action=edit Bug 43340: Reuse SMTP connections when sending SMS messages via email Bug 33964 made Koha reuse a single persistent SMTP connection when processing the message queue, but the change missed the code path for SMS messages sent via the Email driver. Each of those messages still opens a brand new SMTP connection and does a full EHLO => STARTTLS => auth => send => quit conversation. A burst of SMS notices means dozens of connections in seconds from one IP, which can trigger the mail server's connection rate limiting. Gmail in particular will start responding with 421-4.7.0 at EHLO. Test Plan: 1) Apply the first patch ( unit tests ) 2) prove t/db_dependent/Letters.t 3) Note the SMTP transport reuse tests fail! 4) Apply this patch 5) prove t/db_dependent/Letters.t 6) Note all tests pass! -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #9 from Kyle M Hall (khall) <kyle@bywatersolutions.com> --- Created attachment 208091 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208091&action=edit Bug 43340: Update Schema files [DO NOT PUSH] Patch from commit ed9db2a -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #10 from Brendan Lawlor <blawlor@clamsnet.org> --- Thanks for working on this Kyle! I will try testing this and let you know if I have any questions. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Brendan Lawlor <blawlor@clamsnet.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Signed Off -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Brendan Lawlor <blawlor@clamsnet.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #208085|0 |1 is obsolete| | Attachment #208086|0 |1 is obsolete| | Attachment #208087|0 |1 is obsolete| | Attachment #208088|0 |1 is obsolete| | Attachment #208089|0 |1 is obsolete| | Attachment #208090|0 |1 is obsolete| | Attachment #208091|0 |1 is obsolete| | -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #11 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208814 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208814&action=edit Bug 43340: Add send_attempts and retry_after columns to message_queue This patch adds two columns to message_queue so Koha can keep track of how many times a temporary SMTP failure prevented a message from being sent, and when it may be tried again. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Note the send_attempts and retry_after columns on message_queue! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #12 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208815 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208815&action=edit Bug 43340: Token delivery endpoint never responds if the OTP message is left pending The send_otp_token controller queues the 2FA_OTP_TOKEN notice, sends it right away with SendQueuedMessages, and then only renders a response if the message ended up 'sent' or 'failed'. A message that is still 'pending' renders nothing at all, so the request hangs until Mojolicious gives up on it. That is what SendQueuedMessages leaves behind when a message domain limit defers the message, and what the following patches leave behind after a temporary SMTP failure. This patch makes the controller treat anything other than 'sent' as not sent and respond with a 400 email_not_sent. Test Plan: 1) Apply this patch 2) prove t/db_dependent/api/v1/two_factor_auth.t Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #13 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208816 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208816&action=edit Bug 43340: Retry with backoff when the SMTP server reports a temporary failure When the mail server answers with a temporary failure, Koha marks the message failed with the failure code SENDMAIL and moves on to the next message. Nothing ever tries that message again unless a librarian notices it and clicks "Resend". Google's SMTP relay in particular will sometimes answer the EHLO with: Net::SMTP=GLOB(0x55eba2c35700)<<< 421-4.7.0 Try again later, closing connection. (EHLO) The throttle only lasts a few seconds, but every remaining message in that run opens a new connection, gets the same 421, and is marked failed. On one busy site the cron logs show bursts of 53, 164 and 248 consecutive failed hold notices inside a single run of process_message_queue.pl, after which the next run 15 minutes later sends everything without a problem. Every one of those notices was lost. This patch makes Koha treat a temporary failure the way an MTA would. A 4xx response from the mail server, or a connection that is refused before Koha gets a response code ( which is what a 421 at the EHLO stage looks like to Email::Sender ), leaves the message pending with a retry_after time and bumps send_attempts. The message is tried again by a later run of process_message_queue.pl after 10 minutes, then 30, 60 and 120 minutes. Only if the fifth attempt also fails is the message marked failed with SENDMAIL as before. Permanent failures are still marked failed right away. Once a server has refused a connection or answered 421 during a run, the remaining messages for that server are deferred without trying to connect, so a server that is rate limiting us sees one connection per run instead of one per message. Resending a message from the notices tab starts the schedule over. Note that an immediate send ( password recovery, for example ) now reports the message as not sent when it was deferred; the message still goes out with the next cron run. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Restart all the things! 4) Point your default SMTP server ( Administration > SMTP servers ) at a host and port where nothing is listening 5) Queue notices for several patrons with email addresses, e.g. check out items with the CHECKOUT notice enabled 6) Run misc/cronjobs/process_message_queue.pl 7) Note a single connection failure in the output followed by a line saying the server is unavailable, and that every notice is still pending! 8) Run process_message_queue.pl again, note the messages are skipped! 9) UPDATE message_queue SET retry_after = NOW() WHERE status = 'pending' 10) Run process_message_queue.pl, note send_attempts is now 2 and retry_after is 30 minutes out! 11) Repeat steps 9 and 10 until the messages are marked failed with "Unhandled email failure" on the patron's Notices tab! 12) Point the SMTP server back at a working mail server 13) Click Resend on a message, run process_message_queue.pl, note the message is sent! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #14 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208817 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208817&action=edit Bug 43340: Add unit tests for retrying after a temporary SMTP failure Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #15 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208819 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208819&action=edit Bug 43340: Add unit tests for SMTP connection reuse when sending SMS Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #16 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208820 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208820&action=edit Bug 43340: Reuse SMTP connections when sending SMS messages via email Bug 33964 made Koha reuse a single persistent SMTP connection when processing the message queue, but the change missed the code path for SMS messages sent via the Email driver. Each of those messages still opens a brand new SMTP connection and does a full EHLO => STARTTLS => auth => send => quit conversation. A burst of SMS notices means dozens of connections in seconds from one IP, which can trigger the mail server's connection rate limiting. Gmail in particular will start responding with 421-4.7.0 at EHLO. Test Plan: 1) Apply the first patch ( unit tests ) 2) prove t/db_dependent/Letters.t 3) Note the SMTP transport reuse tests fail! 4) Apply this patch 5) prove t/db_dependent/Letters.t 6) Note all tests pass! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #17 from Brendan Lawlor <blawlor@clamsnet.org> --- Created attachment 208821 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=208821&action=edit Bug 43340: Update Schema files [DO NOT PUSH] Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #18 from Brendan Lawlor <blawlor@clamsnet.org> --- This is rad! Works as described in the test plans. All tests pass. Also tested that the tests fail without the patches. Helpful testing notes: 1. ktd --smtp up -d 2. Mailpit web interface will be available at http://localhost:8025 3. In Admin > SMTP servers add a bogus server with port 9999 4. Add an email address to a patron and make sure they have message preferences for email 5. Run perl misc/cronjobs/process_message_queue.pl -v - you should see a connection failure 6. check the message status in ktd --dbshell - SELECT message_id, status, send_attempts, retry_after, failure_code FROM message_queue ORDER BY message_id DESC - you should see status pending, and retry_after is set in 10 minutes 7. Update the retry_after so you sojn't have to wait - UPDATE message_queue SET retry_after=NOW() WHERE status='pending' 8. Repeat steps 5-7 to similuate reseding the failed messages - you should see the backoff go up 30, 60, then 120 minutes 9. After the 5th attempt the message status will be failed and in the patron's notice tab you'll see "Unhandled email failure" 7. From the notice on the patron record click Resend 8. Check the message status and confirm send_attempt was reset to 0 9. Change the SMTP server to port 1025 10. Send some notices and see that they reach Mailpit at localhost:8025 You can simulate a run through of multiple attempts with 30 seconds between each try like this. Try fixing the SMTP port while it's running to see a retry attempt succeed. for i in 1 2 3 4; do koha-mysql kohadev -e "UPDATE message_queue SET retry_after=NOW() WHERE status='pending'" perl misc/cronjobs/process_message_queue.pl -v koha-mysql kohadev -e "SELECT message_id,status,send_attempts,retry_after FROM message_queue" echo "--- run $i done, waiting 90s ---" sleep 30 done -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Lisette Scheer <lisette@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- QA Contact|testopia@bugs.koha-communit |martin.renvoize@openfifth.c |y.org |o.uk -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Signed Off |Passed QA Patch complexity|--- |Medium patch --- Comment #19 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- This was rather fun to grok; broke my brain a few times but I'm pretty confident in it now. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #208814|0 |1 is obsolete| | Attachment #208815|0 |1 is obsolete| | Attachment #208816|0 |1 is obsolete| | Attachment #208817|0 |1 is obsolete| | Attachment #208819|0 |1 is obsolete| | Attachment #208820|0 |1 is obsolete| | Attachment #208821|0 |1 is obsolete| | -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #20 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210738 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210738&action=edit Bug 43340: Add send_attempts and retry_after columns to message_queue This patch adds two columns to message_queue so Koha can keep track of how many times a temporary SMTP failure prevented a message from being sent, and when it may be tried again. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Note the send_attempts and retry_after columns on message_queue! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #21 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210739 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210739&action=edit Bug 43340: Token delivery endpoint never responds if the OTP message is left pending The send_otp_token controller queues the 2FA_OTP_TOKEN notice, sends it right away with SendQueuedMessages, and then only renders a response if the message ended up 'sent' or 'failed'. A message that is still 'pending' renders nothing at all, so the request hangs until Mojolicious gives up on it. That is what SendQueuedMessages leaves behind when a message domain limit defers the message, and what the following patches leave behind after a temporary SMTP failure. This patch makes the controller treat anything other than 'sent' as not sent and respond with a 400 email_not_sent. Test Plan: 1) Apply this patch 2) prove t/db_dependent/api/v1/two_factor_auth.t Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #22 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210740 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210740&action=edit Bug 43340: Retry with backoff when the SMTP server reports a temporary failure When the mail server answers with a temporary failure, Koha marks the message failed with the failure code SENDMAIL and moves on to the next message. Nothing ever tries that message again unless a librarian notices it and clicks "Resend". Google's SMTP relay in particular will sometimes answer the EHLO with: Net::SMTP=GLOB(0x55eba2c35700)<<< 421-4.7.0 Try again later, closing connection. (EHLO) The throttle only lasts a few seconds, but every remaining message in that run opens a new connection, gets the same 421, and is marked failed. On one busy site the cron logs show bursts of 53, 164 and 248 consecutive failed hold notices inside a single run of process_message_queue.pl, after which the next run 15 minutes later sends everything without a problem. Every one of those notices was lost. This patch makes Koha treat a temporary failure the way an MTA would. A 4xx response from the mail server, or a connection that is refused before Koha gets a response code ( which is what a 421 at the EHLO stage looks like to Email::Sender ), leaves the message pending with a retry_after time and bumps send_attempts. The message is tried again by a later run of process_message_queue.pl after 10 minutes, then 30, 60 and 120 minutes. Only if the fifth attempt also fails is the message marked failed with SENDMAIL as before. Permanent failures are still marked failed right away. Once a server has refused a connection or answered 421 during a run, the remaining messages for that server are deferred without trying to connect, so a server that is rate limiting us sees one connection per run instead of one per message. Resending a message from the notices tab starts the schedule over. Note that an immediate send ( password recovery, for example ) now reports the message as not sent when it was deferred; the message still goes out with the next cron run. Test Plan: 1) Apply this patch 2) Run updatedatabase.pl 3) Restart all the things! 4) Point your default SMTP server ( Administration > SMTP servers ) at a host and port where nothing is listening 5) Queue notices for several patrons with email addresses, e.g. check out items with the CHECKOUT notice enabled 6) Run misc/cronjobs/process_message_queue.pl 7) Note a single connection failure in the output followed by a line saying the server is unavailable, and that every notice is still pending! 8) Run process_message_queue.pl again, note the messages are skipped! 9) UPDATE message_queue SET retry_after = NOW() WHERE status = 'pending' 10) Run process_message_queue.pl, note send_attempts is now 2 and retry_after is 30 minutes out! 11) Repeat steps 9 and 10 until the messages are marked failed with "Unhandled email failure" on the patron's Notices tab! 12) Point the SMTP server back at a working mail server 13) Click Resend on a message, run process_message_queue.pl, note the message is sent! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #23 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210741 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210741&action=edit Bug 43340: Add unit tests for retrying after a temporary SMTP failure Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #24 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210742 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210742&action=edit Bug 43340: Add unit tests for SMTP connection reuse when sending SMS Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #25 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210743 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210743&action=edit Bug 43340: Reuse SMTP connections when sending SMS messages via email Bug 33964 made Koha reuse a single persistent SMTP connection when processing the message queue, but the change missed the code path for SMS messages sent via the Email driver. Each of those messages still opens a brand new SMTP connection and does a full EHLO => STARTTLS => auth => send => quit conversation. A burst of SMS notices means dozens of connections in seconds from one IP, which can trigger the mail server's connection rate limiting. Gmail in particular will start responding with 421-4.7.0 at EHLO. Test Plan: 1) Apply the first patch ( unit tests ) 2) prove t/db_dependent/Letters.t 3) Note the SMTP transport reuse tests fail! 4) Apply this patch 5) prove t/db_dependent/Letters.t 6) Note all tests pass! Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #26 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210744 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210744&action=edit Bug 43340: Update Schema files [DO NOT PUSH] Signed-off-by: Brendan Lawlor <blawlor@clamsnet.org> Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #27 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210745 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210745&action=edit Bug 43340: (QA follow-up) Don't use up retries of messages that were never tried Once a mail server had turned a connection away, the rest of the messages for it in that run were passed to _retry_message_later, which counts an attempt. A server that stays down for longer than the retry schedule (about 3.7 hours) therefore failed every queued message with SENDMAIL, including ones that never reached the server. Add _defer_message, which only pushes retry_after back and leaves send_attempts alone. Only the message that actually met the failure records an attempt. Test plan: 1. prove t/db_dependent/Letters.t Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #28 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210746 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210746&action=edit Bug 43340: (QA follow-up) Use Koha::Notice::Message for the retry bookkeeping Record attempts and retry_after through Koha::Notice::Message instead of hand-written UPDATE statements, and compare retry_after against a datetime formatted by Koha rather than the database's NOW(), so both sides of the comparison use the same clock. ResendMessage no longer needs a second UPDATE to start the schedule over: _set_message_status takes a reset_retries flag so it happens in the same statement that sets the message back to pending. Test plan: 1. prove t/db_dependent/Letters.t Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #29 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210747 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210747&action=edit Bug 43340: (QA follow-up) Name and pin the check for a temporary SMTP failure Email::Sender::Transport::SMTP gives a failure to connect, including a 421 before EHLO, no response code and no exception class of its own, so the only way to recognise it is its message. That match sat inline in the catch block, undocumented, and would have turned retries back into permanent failures without a sound if the wording ever changed. Move the decisions into _is_temporary_smtp_failure and _is_smtp_server_unavailable, document where the message comes from and that a misconfigured host is retried until the retries run out, and add a test that provokes the failure from the real transport so that a change in Email::Sender's wording is caught. The catch block also takes a copy of the exception before it calls anything else, rather than reading $_ after DBI calls. Test plan: 1. prove t/db_dependent/Letters.t Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #30 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210748 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210748&action=edit Bug 43340: (QA follow-up) Don't retry a one-time 2FA code A 2FA_OTP_TOKEN notice says the code is valid for one minute, but the first retry is ten minutes away. The endpoint answers 400 email_not_sent straight away, so a retried message would only deliver a dead code to a patron who has already been told it was not sent. Add @NO_RETRY_LETTER_CODES, and mark such a notice failed instead of scheduling a retry, both when it meets a temporary failure and when it is pushed back because its server is already known to be down. Test plan: 1. prove t/db_dependent/Letters.t Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #31 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210749 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210749&action=edit Bug 43340: (QA follow-up) Show the retry state of a notice to staff A message waiting to be retried looked like any other pending message, and one that gave up gave no hint that it had been tried several times. Return send_attempts and retry_after from GetMessage and GetQueuedMessages, and show them in the delivery note column of the patron's notices tab: when a pending message will be tried again, and how many temporary failures it has had. Test plan: 1. prove t/db_dependent/Letters.t 2. Queue an email for a patron and make the SMTP server unreachable 3. Run misc/cronjobs/process_message_queue.pl 4. Open the patron's Notices tab and confirm the message is pending and says when sending will be tried again and how many failures it has had Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 --- Comment #32 from Martin Renvoize (ashimema) <martin.renvoize@openfifth.co.uk> --- Created attachment 210750 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=210750&action=edit Bug 43340: (QA follow-up) Log temporary SMTP failures instead of warning A temporary failure is expected while a mail server is busy or down, and the message is tried again, but every one of them was carped, so a cron-run outage mailed the administrator a warning per message plus one per server on every run. Send them to Koha::Logger instead. A failure that gives up on the message is still carped as before. Test plan: 1. prove t/db_dependent/Letters.t Signed-off-by: Martin Renvoize <martin.renvoize@openfifth.co.uk> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43340 Pedro Amorim (ammopt) <pedro.amorim@openfifth.co.uk> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |pedro.amorim@openfifth.co.u | |k Status|Passed QA |Patch doesn't apply -- You are receiving this mail because: You are watching all bug changes.
participants (1)
-
bugzilla-daemon＠bugs.koha-community.org