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

[ippaso]

For some reason my previous posts never reached the mailing list, so I
repost it here, sorry for the delay:


Mark Sapiro ha scritto:

>> Jan 27 13:34:57 2008 (2154) <20080127123401.27408.qmail at MYDOMAIN> smtp
>> to test for 1 recips, completed in 55.860 seconds
>> Jan 27 13:37:21 2008 (2154) <20080127123607.27936.qmail at MYDOMAIN> smtp
>> to test for 1 recips, completed in 63.191 seconds
>
>
> This is highly suspicious. The times above are the time from start to
> finish of the SMTP interaction with Qmail.  These times, particularly
> the last few are HUGE. Why?


After a look at the log of the smtp server (see below), I can guess that
the reason might be an high load on the system due to intense
spamassassin activity: at the time of the error there were 20
connections (the maximum number of allowable concurrent connections) to
the server, which, considering the traffic of our server, highlights a
spamming session.

Is it possible that the reason for the outgoing runner to stop is
related to this huge time or to the system load?



> Somewhere around here (13:37:21 minus 00:01:03.191) OutgoingRunner
> started SMTP delivery of the post to Qmail.


Here is the log from the smtp server for that time, in case it can help:
(qmail is patched to check the 'rcpt to' against a valid addresses list
before accepting a message and to reject during the smtp conversation
the mails which achieve a very high spamassassin spam score)


2008-01-27 13:36:00.396206500 qmail-smtpd: validrcptto RCPT TO:
hovgxnik at MYDOMAIN
2008-01-27 13:36:00.396215500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:03.361324500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM
2008-01-27 13:36:03.613234500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM
2008-01-27 13:36:04.365972500 tcpserver: end 27763 status 256
2008-01-27 13:36:04.365978500 tcpserver: status: 19/20
2008-01-27 13:36:04.365979500 tcpserver: status: 20/20
2008-01-27 13:36:04.365981500 tcpserver: pid 27919 from 202.156.55.133
2008-01-27 13:36:04.365983500 tcpserver: ok 27919 MYDOMAIN:MYDOMAINIP:25
cm133.gamma55.maxonline.com.sg:202.156.55.133::1794
2008-01-27 13:36:04.546585500 tcpserver: end 27792 status 256
2008-01-27 13:36:04.546590500 tcpserver: status: 19/20
2008-01-27 13:36:04.546592500 tcpserver: status: 20/20
2008-01-27 13:36:04.546593500 tcpserver: pid 27920 from 211.158.55.6
2008-01-27 13:36:05.498585500 tcpserver: ok 27920 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::2133
2008-01-27 13:36:05.498591500 tcpserver: end 27920 status 256
2008-01-27 13:36:05.498593500 tcpserver: status: 19/20
2008-01-27 13:36:05.498594500 tcpserver: status: 20/20
2008-01-27 13:36:05.498596500 tcpserver: pid 27921 from 221.146.194.29
2008-01-27 13:36:05.498598500 tcpserver: ok 27921 MYDOMAIN:MYDOMAINIP:25
:221.146.194.29::1074
2008-01-27 13:36:05.498600500 tcpserver: end 27921 status 256
2008-01-27 13:36:05.498601500 tcpserver: status: 19/20
2008-01-27 13:36:05.499279500 tcpserver: status: 20/20
2008-01-27 13:36:05.499286500 tcpserver: pid 27922 from 89.76.17.147
2008-01-27 13:36:05.499287500 tcpserver: ok 27922 MYDOMAIN:MYDOMAINIP:25
chello089076017147.chello.pl:89.76.17.147::62209
2008-01-27 13:36:06.977693500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM
2008-01-27 13:36:07.045020500 qmail-smtpd: validrcptto RCPT TO:
capi-gruppo-owner at MYDOMAIN
2008-01-27 13:36:07.045025500 qmail-smtpd: validrcptto found:
capi-gruppo-owner at MYDOMAIN
2008-01-27 13:36:08.709515500 tcpserver: end 27764 status 256
2008-01-27 13:36:08.709521500 tcpserver: status: 19/20
2008-01-27 13:36:08.709523500 tcpserver: status: 20/20
2008-01-27 13:36:08.709526500 tcpserver: pid 27939 from 58.8.90.161
2008-01-27 13:36:08.709528500 tcpserver: ok 27939 MYDOMAIN:MYDOMAINIP:25
ppp-58-8-90-161.revip2.asianet.co.th:58.8.90.161::23932
2008-01-27 13:36:09.239802500 qmail-smtpd: validrcptto RCPT TO:
gruppo at MYDOMAIN
2008-01-27 13:36:09.239808500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:11.326256500 qmail-smtpd: validrcptto RCPT TO:
hszdzlbsrkvx at MYDOMAIN
2008-01-27 13:36:11.382459500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:12.198188500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM
2008-01-27 13:36:13.033921500 tcpserver: end 27835 status 0
2008-01-27 13:36:13.033926500 tcpserver: status: 19/20
2008-01-27 13:36:13.033927500 tcpserver: status: 20/20
2008-01-27 13:36:13.033929500 tcpserver: pid 27954 from 221.146.194.29
2008-01-27 13:36:13.033931500 tcpserver: ok 27954 MYDOMAIN:MYDOMAINIP:25
:221.146.194.29::1264
2008-01-27 13:36:13.033933500 tcpserver: end 27858 status 256
2008-01-27 13:36:13.033934500 tcpserver: status: 19/20
2008-01-27 13:36:13.033936500 tcpserver: status: 20/20
2008-01-27 13:36:13.033937500 tcpserver: pid 27956 from 211.158.55.6
2008-01-27 13:36:13.598710500 tcpserver: ok 27956 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::1232
2008-01-27 13:36:13.989282500 tcpserver: end 27954 status 256
2008-01-27 13:36:13.989290500 tcpserver: status: 19/20
2008-01-27 13:36:13.989291500 tcpserver: status: 20/20
2008-01-27 13:36:13.989293500 tcpserver: pid 27961 from 77.35.19.197
2008-01-27 13:36:13.989295500 tcpserver: ok 27961 MYDOMAIN:MYDOMAINIP:25
:77.35.19.197::1496
2008-01-27 13:36:15.318137500 tcpserver: end 27788 status 0
2008-01-27 13:36:15.318141500 tcpserver: status: 19/20
2008-01-27 13:36:15.318143500 tcpserver: status: 20/20
2008-01-27 13:36:15.318144500 tcpserver: pid 27962 from 195.91.79.251
2008-01-27 13:36:15.318146500 tcpserver: ok 27962 MYDOMAIN:MYDOMAINIP:25
flasmtp.t-mobile.sk:195.91.79.251::2161
2008-01-27 13:36:16.173859500 qmail-smtpd: validrcptto RCPT TO:
uiakjb at MYDOMAIN
2008-01-27 13:36:16.173866500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:16.606159500 qmail-smtpd: validrcptto RCPT TO:
mailman at MYDOMAIN
2008-01-27 13:36:16.606165500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:16.657140500 qmail-smtpd: validrcptto RCPT TO:
zona at MYDOMAIN
2008-01-27 13:36:16.657145500 qmail-smtpd: validrcptto found: zona at MYDOMAIN
2008-01-27 13:36:21.880761500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM
2008-01-27 13:36:22.482554500 tcpserver: end 27919 status 256
2008-01-27 13:36:22.482560500 tcpserver: status: 19/20
2008-01-27 13:36:22.482562500 tcpserver: status: 20/20
2008-01-27 13:36:22.482564500 tcpserver: pid 27995 from 211.158.55.6
2008-01-27 13:36:27.427176500 tcpserver: ok 27995 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::2179
2008-01-27 13:36:27.427185500 tcpserver: end 27995 status 256
2008-01-27 13:36:27.427187500 tcpserver: status: 19/20
2008-01-27 13:36:27.427189500 tcpserver: status: 20/20
2008-01-27 13:36:27.427191500 tcpserver: pid 27999 from 221.146.194.29
2008-01-27 13:36:27.427192500 tcpserver: ok 27999 MYDOMAIN:MYDOMAINIP:25
:221.146.194.29::1672
2008-01-27 13:36:27.427194500 tcpserver: end 27899 status 256
2008-01-27 13:36:27.427196500 tcpserver: status: 19/20
2008-01-27 13:36:27.427300500 tcpserver: status: 20/20
2008-01-27 13:36:27.427302500 tcpserver: pid 28000 from 211.158.55.6
2008-01-27 13:36:27.427304500 tcpserver: ok 28000 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::2189
2008-01-27 13:36:27.427306500 qmail-smtpd: validrcptto RCPT TO:
cars-owner at MYDOMAIN
2008-01-27 13:36:27.427307500 qmail-smtpd: validrcptto found:
cars-owner at MYDOMAIN
2008-01-27 13:36:28.538834500 qmail-smtpd: validrcptto RCPT TO: fs at MYDOMAIN
2008-01-27 13:36:28.538840500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:31.643714500 tcpserver: end 27854 status 0
2008-01-27 13:36:31.643719500 tcpserver: status: 19/20
2008-01-27 13:36:31.643721500 tcpserver: end 27903 status 0
2008-01-27 13:36:31.643722500 tcpserver: status: 18/20
2008-01-27 13:36:31.643724500 tcpserver: status: 19/20
2008-01-27 13:36:31.643726500 tcpserver: pid 28026 from 211.158.55.6
2008-01-27 13:36:31.643727500 tcpserver: status: 20/20
2008-01-27 13:36:31.643729500 tcpserver: pid 28027 from 211.158.55.6
2008-01-27 13:36:31.643730500 tcpserver: end 27902 status 0
2008-01-27 13:36:31.643732500 tcpserver: status: 19/20
2008-01-27 13:36:31.643836500 tcpserver: status: 20/20
2008-01-27 13:36:31.643839500 tcpserver: pid 28029 from 211.158.55.6
2008-01-27 13:36:31.643840500 tcpserver: ok 28026 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::1217
2008-01-27 13:36:31.643842500 tcpserver: ok 28029 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::2199
2008-01-27 13:36:31.643844500 tcpserver: end 28026 status 256
2008-01-27 13:36:31.643846500 tcpserver: status: 19/20
2008-01-27 13:36:31.643847500 tcpserver: end 28029 status 256
2008-01-27 13:36:31.643868500 tcpserver: status: 18/20
2008-01-27 13:36:31.643870500 tcpserver: status: 19/20
2008-01-27 13:36:31.643871500 tcpserver: pid 28030 from 82.208.178.201
2008-01-27 13:36:31.643873500 tcpserver: status: 20/20
2008-01-27 13:36:31.643874500 tcpserver: pid 28031 from 77.35.19.197
2008-01-27 13:36:31.643876500 tcpserver: ok 28030 MYDOMAIN:MYDOMAINIP:25
home-037715.b.astral.ro:82.208.178.201::3819
2008-01-27 13:36:31.643878500 tcpserver: end 27922 status 0
2008-01-27 13:36:31.644004500 tcpserver: status: 19/20
2008-01-27 13:36:31.644007500 tcpserver: end 28030 status 256
2008-01-27 13:36:31.644009500 tcpserver: status: 18/20
2008-01-27 13:36:31.644014500 tcpserver: status: 19/20
2008-01-27 13:36:31.644015500 tcpserver: pid 28032 from 58.8.90.161
2008-01-27 13:36:31.644017500 tcpserver: ok 28032 MYDOMAIN:MYDOMAINIP:25
ppp-58-8-90-161.revip2.asianet.co.th:58.8.90.161::24427
2008-01-27 13:36:31.644078500 tcpserver: status: 20/20
2008-01-27 13:36:31.644080500 tcpserver: pid 28033 from 211.158.55.6
2008-01-27 13:36:31.661559500 tcpserver: ok 28027 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::1256
2008-01-27 13:36:31.661567500 tcpserver: ok 28031 MYDOMAIN:MYDOMAINIP:25
:77.35.19.197::1502
2008-01-27 13:36:31.661570500 tcpserver: ok 28033 MYDOMAIN:MYDOMAINIP:25
:211.158.55.6::1867
2008-01-27 13:36:31.714273500 tcpserver: end 28027 status 256
2008-01-27 13:36:31.714277500 tcpserver: status: 19/20
2008-01-27 13:36:31.714280500 tcpserver: status: 20/20
2008-01-27 13:36:31.854773500 tcpserver: pid 28037 from 221.146.194.29
2008-01-27 13:36:31.856311500 tcpserver: ok 28037 MYDOMAIN:MYDOMAINIP:25
:221.146.194.29::1533
2008-01-27 13:36:33.784573500 qmail-smtpd: validrcptto RCPT TO:
uweia at MYDOMAIN
2008-01-27 13:36:33.784580500 qmail-smtpd: validrcptto found: @MYDOMAIN
2008-01-27 13:36:34.128424500 qmail-smtpd: validrcptto RCPT TO:
noti-owner at MYDOMAIN
2008-01-27 13:36:34.128432500 qmail-smtpd: validrcptto found:
noti-owner at MYDOMAIN
2008-01-27 13:36:34.254435500 tcpserver: end 27962 status 0
2008-01-27 13:36:34.254440500 tcpserver: status: 19/20
2008-01-27 13:36:34.254442500 tcpserver: status: 20/20
2008-01-27 13:36:34.255429500 tcpserver: pid 28052 from 82.208.178.201
2008-01-27 13:36:34.468302500 X-Antivirus-MYDOMAIN-1.25-st-qms: We have
reasons to believe this mail is SPAM


> Why the discontinuity in timestamps here?


Sorry, my fault: I grep the log for "13:37"... :-)


>> 
procmail:_[28548]_Sun_Jan_27_13:38:32_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.zvb"/procmail:_Couldn't_chdir_to_"/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.zvb"/procmail:_Assigning_"MAILDIR=."/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/procmail-mailman.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/procmail-mailman.log"/did_0+0+1/
>
> What's going on with these procmail entries for mailman? What's in
> /home/vpopmail/domains/MYDOMAIN/procmail-mailman.log?


Our server is hosting two different domains, and this error depends on a
misconfiguration of the other domain settings: procmail is trying to
save the spam mail addressed to a list in a mailbox which,
unfortunately, doesn't exist. I will point out this to the postmaster of
that domain.

Unfortunately procmail is not logging the times of the operations in its
log file, so I can't easily find out the specific log entry for
Sun_Jan_27_13:38:32.
(BTW: someone knows how to add timestamps to procmail logs?)

>
>
>
> Questions?
>
> What's going on with procmail?
>
> What if anything is in Mailman's error and smtp-failure logs?


The only entry from 'error' log (when I copied the logs for the previous
post it wasn't here yet...):

Jan 27 14:17:58 2008 (2154) Cannot connect to SMTP server localhost on
port smtp


And here from 'smtp-failure'


Jan 27 14:17:58 2008 (2154) Low level smtp error: (4, 'Interrupted
system call'), msgid: <20080127123803.28436.qmail at MYDOMAIN>


> To try to debug the SMTP interaction with qmail, see
> <http://www.python.org/cgi-bin/faqw-mm.py?req=show&file=faq04.073.htp>
> for a patch that can be applied to Mailman/Handlers/SMTPDirect.py to
> log additional debug info. You said you have Python 2.4.3 which is
> good - do not use this patch with Python older than 2.4.x.


Ok, thanks: I will patch mailman immediately and post here the 'error'
log as soon as the error appears again.

Thank you,

Paso