[Mailman-Users] Outgoing qrunner stops working and outgoingmails get stuck

Tue Feb 5 21:39:43 CET 2008

ippaso wrote:

>SP ha scritto:
>
>> Ok, thanks: I will patch mailman immediately and post here the 'error'
>> log as soon as the error appears again.
>
>Here the relevant part of mailman 'error' log (the time of the last sent
>message is 22.29 and the time of the first message which gets stuck in
>qfiles/out is 22.30):

<snip>

The following are the connect to start sending the last message
successfully sent.

>Feb 03 22:32:14 2008 qrunner(20175): connect:   ('localhost', 25)
>Feb 03 22:32:14 2008 qrunner(20175): connect:   ('localhost', 25)

Qmail is busy here too. Reply to connect takes 41 seconds.

>Feb 03 22:32:55 2008 qrunner(20175): reply:   '220 MYDOMAIN ESMTP\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply: retcode (220); Msg: MYDOMAIN
>ESMTP

And the connect succeeded and we begin to send.

>Feb 03 22:32:55 2008 qrunner(20175): connect:   MYDOMAIN ESMTP
>Feb 03 22:32:55 2008 qrunner(20175): send:   'ehlo www.MYDOMAIN\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250-MYDOMAIN\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250-AUTH LOGIN CRAM-MD5
>PLAIN\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250-AUTH=LOGIN CRAM-MD5
>PLAIN\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250-STARTTLS\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250-PIPELINING\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250 8BITMIME\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply: retcode (250); Msg: MYDOMAIN
>AUTH LOGIN CRAM-MD5 PLAIN
>AUTH=LOGIN CRAM-MD5 PLAIN
>STARTTLS
>PIPELINING
>8BITMIME
>Feb 03 22:32:55 2008 qrunner(20175): send:   'mail
>FROM:<test-bounces at MYDOMAIN>\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250 ok\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply: retcode (250); Msg: ok
>Feb 03 22:32:55 2008 qrunner(20175): send:   'rcpt
>TO:<mailman-test at MYDOMAIN>\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '250 ok\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply: retcode (250); Msg: ok
>Feb 03 22:32:55 2008 qrunner(20175): send:   'data\r\n'
>Feb 03 22:32:55 2008 qrunner(20175): reply:   '354 go ahead\r\n'
>Feb 03 22:32:56 2008 qrunner(20175): reply: retcode (354); Msg: go ahead
>Feb 03 22:32:56 2008 qrunner(20175): data:   (354, 'go ahead')
>Feb 03 22:32:56 2008 qrunner(20175): send:   'Return-Path:
><TESTMAIL at MYDOMAIN>\r\nDelivered-To: MYDOMAIN-test at MYDOMAIN\r\nReceived:
>(qmail 4288 invoked by uid 511); 3 Feb 2008 22:29:12 +0100\r\nDate: 3
>Feb 2008 22:29:12 +0100\r\nMessage-ID:
><20080203212912.4287.qmail at MYDOMAIN>\r\nFrom: TESTMAIL at MYDOMAIN\r\nTo:
>test at MYDOMAIN\r\nSubject: [Test] Test Sun Feb  3 22:29:12 CET
>2008\r\nX-BeenThere: test at MYDOMAIN\r\nX-Mailman-Version:
>2.1.9\r\nPrecedence: list\r\nList-Id:
><test.MYDOMAIN>\r\nList-Unsubscribe:
><http://MYDOMAIN/mailman/listinfo/test>,\r\n\t<mailto:test-request at MYDOMAIN?subject=unsubscribe>\r\nList-Archive: 
>
><http://MYDOMAIN/pipermail/test>\r\nList-Post:
><mailto:test at MYDOMAIN>\r\nList-Help:
><mailto:test-request at MYDOMAIN?subject=help>\r\nList-Subscribe:
><http://MYDOMAIN/mailman/listinfo/test>,\r\n\t<mailto:test-request at MYDOMAIN?subject=subscribe>\r\nMIME-Version: 
>
>1.0\r\nContent-Type: text/plain;
>charset="iso-8859-1"\r\nContent-Transfer-Encoding:
>quoted-printable\r\nSender: test-bounces at MYDOMAIN\r\nErrors-To:
>test-bounces at MYDOMAIN\r\n\r\nSun Feb  3 22:29:12 CET
>2008\r\n_______________________________________________\r\nTest mailing
>list\r\nTest at MYDOMAIN\r\nhttp://MYDOMAIN/mailman/listinfo/test\r\n.\r\n'

Above, we send the message at 22:32:56. We do not receive the reply
below until 22:33:23.  Presumably, Qmail spent most of the 27 seconds
doing the spam scanning.

>Feb 03 22:33:23 2008 qrunner(20175): reply:   '250 ok 1202074403 qp
>5450\r\n'
>Feb 03 22:33:23 2008 qrunner(20175): reply: retcode (250); Msg: ok
>1202074403 qp 5450
>Feb 03 22:33:23 2008 qrunner(20175): data:   (250, 'ok 1202074403 qp 5450')
>Feb 03 22:33:23 2008 qrunner(20175): send:   'quit\r\n'
>Feb 03 22:33:23 2008 qrunner(20175): reply:   '221 MYDOMAIN\r\n'
>Feb 03 22:33:23 2008 qrunner(20175): reply: retcode (221); Msg: MYDOMAIN

Now, the message is sent and accepted and we try to connect again to
send the next message.

>Feb 03 22:33:23 2008 qrunner(20175): connect:   ('localhost', 25)
>Feb 03 22:33:23 2008 qrunner(20175): connect:   ('localhost', 25)

But we receive no reply to our connect and no timeout either, so we are
still waiting.

I'm not sure where the problem is, but it is outside Mailman. The
underlying Python smtplib has issued a tcp/ip connect request to
localhost, port 25 and is waiting for some kind of response, i.e., a
response from the process listening on localhost:25, a tcp/ip refusal
or a tcp/ip timeout. None of these things occur, so we just wait.

I have no idea whether this is an OS issue, a networking issue or a
Qmail issue, but there should eventually be a reply or a timeout.

>Again at the moment of the failure the system load was high since there
>were about 20 simultaneous connections to the smtp server, and
>consequently many spamassassins processes, and from the mailman 'smtp'
>log again it took many time to deliver the last few messages:
>
>
>Feb 03 22:25:10 2008 (20175) <20080203212501.3266.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 3.815 seconds
>Feb 03 22:26:06 2008 (20175) <20080203212602.3363.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 3.451 seconds
>Feb 03 22:31:22 2008 (20175) <20080203212730.3725.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 102.005 seconds
>Feb 03 22:32:14 2008 (20175) <20080203212807.3906.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 52.107 seconds
>Feb 03 22:33:23 2008 (20175) <20080203212912.4287.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 69.000 seconds

68+ of those 69 seconds are in waiting for the initial response to
connect and waiting for reply after sending the message text.

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan