Random lmtp Timeout and Long Message Processing times
Hello-
We’re seeing a seemingly random issue with message acceptance on our mailman instance where some messages sent from postfix to the lmtp listener timeout. It’s not consistent to any specific list or time of day, and messages are accepted on the next attempt by postfix to deliver the message to the lmtp.
Additionally, there seems to be a similarly random delay in accepting and processing messages before they are sent to the list moderators or list members.
The mailman smtp log snippet shows it stop receiving data prior to the DATA portion of the message after a 15min timeout:
Jan 02 07:56:36 2025 (3601529) Available AUTH mechanisms: LOGIN(builtin) PLAIN(builtin)
Jan 02 07:56:36 2025 (3601529) Peer: ('127.0.0.1', 45574)
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) handling connection
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'220 lists.renci.org GNU Mailman LMTP runner 2.0'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'LHLO lists.renci.org\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'LHLO lists.renci.org'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-lists.renci.org'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-SIZE 33554432'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-8BITMIME'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250 HELP'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) sender: 010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws>
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250 OK'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) recip: adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) << b'250 Ok'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) EOF received
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) connection timeout
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) Connection lost during _handle_client()
Jan 02 08:12:26 2025 (3601529) Available AUTH mechanisms: LOGIN(builtin) PLAIN(builtin)
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) connection lost
Jan 02 08:12:26 2025 (3601529) Peer: ('127.0.0.1', 33138)
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) handling connection
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'220 lists.renci.org GNU Mailman LMTP runner 2.0'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'LHLO lists.renci.org\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'LHLO lists.renci.org'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-lists.renci.org'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-SIZE 33554432'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-8BITMIME'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 HELP'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) sender: 010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 OK'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) recip: adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 Ok'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'DATA\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'DATA'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'354 End data with <CR><LF>.<CR><LF>'
Anyone have any thoughts on next troubleshooting steps on this one?
Thanks
Still stumped on this one, is there a way to increase the lmtp logging beyond debug?
I’m trying to figure out what is causing the hang for incoming messages here:
Jan 09 13:38:32 2025 (342305) ('127.0.0.1', 48466) << b'250 OK'
Jan 09 13:38:32 2025 (342305) _handle_client readline: b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>\r\n'
Jan 09 13:38:32 2025 (342305) ('127.0.0.1', 48466) >> b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) recip: mailman@lists.renci.org<mailto:mailman@lists.renci.org>
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) << b'250 Ok'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) EOF received
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) connection timeout
It just hangs there until a timeout, then retries and immediately succeeds
Jan 09 13:54:22 2025 (342305) _handle_client readline: b'MAIL FROM:drtaber@renci.org<mailto:drtaber@renci.org> SIZE=7364\r\n'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) >> b'MAIL FROM:drtaber@renci.org<mailto:drtaber@renci.org> SIZE=7364'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) sender: drtaber@renci.org<mailto:drtaber@renci.org>
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) << b'250 OK'
Jan 09 13:54:22 2025 (342305) _handle_client readline: b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>\r\n'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) >> b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) recip: mailman@lists.renci.org<mailto:mailman@lists.renci.org>
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) << b'250 Ok'
Jan 09 13:54:22 2025 (342305) _handle_client readline: b'DATA\r\n'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 44778) >> b'DATA'
From: Taber, Douglas R via Mailman-users <mailman-users@mailman3.org> Date: Thursday, January 2, 2025 at 12:05 PM To: mailman-users@mailman3.org <mailman-users@mailman3.org> Subject: [MM3-users] Random lmtp Timeout and Long Message Processing times Hello-
We’re seeing a seemingly random issue with message acceptance on our mailman instance where some messages sent from postfix to the lmtp listener timeout. It’s not consistent to any specific list or time of day, and messages are accepted on the next attempt by postfix to deliver the message to the lmtp.
Additionally, there seems to be a similarly random delay in accepting and processing messages before they are sent to the list moderators or list members.
The mailman smtp log snippet shows it stop receiving data prior to the DATA portion of the message after a 15min timeout:
Jan 02 07:56:36 2025 (3601529) Available AUTH mechanisms: LOGIN(builtin) PLAIN(builtin)
Jan 02 07:56:36 2025 (3601529) Peer: ('127.0.0.1', 45574)
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) handling connection
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'220 lists.renci.org GNU Mailman LMTP runner 2.0'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'LHLO lists.renci.org\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'LHLO lists.renci.org'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-lists.renci.org'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-SIZE 33554432'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250-8BITMIME'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250 HELP'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) sender: 010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws>
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) << b'250 OK'
Jan 02 07:56:36 2025 (3601529) _handle_client readline: b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>\r\n'
Jan 02 07:56:36 2025 (3601529) ('127.0.0.1', 45574) >> b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) recip: adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) << b'250 Ok'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) EOF received
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) connection timeout
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) Connection lost during _handle_client()
Jan 02 08:12:26 2025 (3601529) Available AUTH mechanisms: LOGIN(builtin) PLAIN(builtin)
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 45574) connection lost
Jan 02 08:12:26 2025 (3601529) Peer: ('127.0.0.1', 33138)
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) handling connection
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'220 lists.renci.org GNU Mailman LMTP runner 2.0'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'LHLO lists.renci.org\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'LHLO lists.renci.org'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-lists.renci.org'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-SIZE 33554432'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250-8BITMIME'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 HELP'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'MAIL FROM:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws> SIZE=20254'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) sender: 010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws<mailto:010001942716aa05-637d21f8-9794-473f-9e8b-06ca08025ef1-000000@mail.verify.signin.aws>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 OK'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'RCPT TO:adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) recip: adcircaws@lists.RENCI.org<mailto:adcircaws@lists.RENCI.org>
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'250 Ok'
Jan 02 08:12:26 2025 (3601529) _handle_client readline: b'DATA\r\n'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) >> b'DATA'
Jan 02 08:12:26 2025 (3601529) ('127.0.0.1', 33138) << b'354 End data with <CR><LF>.<CR><LF>'
Anyone have any thoughts on next troubleshooting steps on this one?
Thanks
Mailman-users mailing list -- mailman-users@mailman3.org To unsubscribe send an email to mailman-users-leave@mailman3.org https://lists.mailman3.org/mailman3/lists/mailman-users.mailman3.org/ Archived at: https://lists.mailman3.org/archives/list/mailman-users@mailman3.org/message/...
This message sent to drtaber@renci.org
On 1/9/25 11:05, Taber, Douglas R via Mailman-users wrote:
Still stumped on this one, is there a way to increase the lmtp logging beyond debug?
I’m trying to figure out what is causing the hang for incoming messages here:
Jan 09 13:38:32 2025 (342305) ('127.0.0.1', 48466) << b'250 OK'
Jan 09 13:38:32 2025 (342305) _handle_client readline: b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>\r\n'
Jan 09 13:38:32 2025 (342305) ('127.0.0.1', 48466) >> b'RCPT TO:mailman@lists.renci.org<mailto:mailman@lists.renci.org>'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) recip: mailman@lists.renci.org<mailto:mailman@lists.renci.org>
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) << b'250 Ok'
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) EOF received
Jan 09 13:54:22 2025 (342305) ('127.0.0.1', 48466) connection timeout
It just hangs there until a timeout, then retries and immediately succeeds
All those messages are actually logged by aiosmtpd which does the bulk
of the work of lmtp runner. There are multiple modules involved here.
Mailman's lmtp runner uses the aiosmtpd LMTP class which is a subclass
of the aiosmtpd SMTP class which in turn is a subclass of
asyncio.StreamReaderProtocol which is reading data from the socket
connecting to the incoming MTA. It seems that after the MTA sends the
250 Ok response to the RCPT TO: command the MTA closes the
connection and asyncio.StreamReaderProtocol calls the eof_received
method resulting in the EOF received log message and ultimately the
timeout.
Have you looked at the MTA logs? If there's not an answer there, that's where you should look to increase logging.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
participants (2)
-
Mark Sapiro -
Taber, Douglas R