SP wrote:

Thanks for the suggestion: this is what I did yesterday. :-) A message is sent to a test list every 2 minutes: the last sent message was that of 13:36 so whatever happened to mailman, it happened between 13:36 and 13:38, the time of the first message which got stuck in qfiles/out.

Here are my logs from mailman and from my MTA (qmail)... unfortunately I can't see anything which can suggest the reason of my problem in any of them, so my only choice is to post them all... I post only logs which have some entry dated today, 27 Jan.

Hope that someone here can find something interesting (and helpful for me!) :-)

=========== BOUNCE ===============

nothing relevant here

=========== POST ===============

<snip>

Jan 27 13:37:21 2008 (2154) post to test from TESTMAIL@MYDOMAIN, size=1236, message-id=<20080127123607.27936.qmail@MYDOMAIN>, success

The last post processed by Mailman. The next one isn't logged as it is still in the queue.

=========== QRUNNER ===============

unfortunately, nothing relevant here.

=========== SMTP ===============

Jan 27 13:20:14 2008 (2154) <20080127122001.25001.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 7.613 seconds Jan 27 13:22:04 2008 (2154) <20080127122201.25176.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 1.817 seconds Jan 27 13:24:05 2008 (2154) <20080127122401.25298.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 1.516 seconds Jan 27 13:26:06 2008 (2154) <20080127122601.25433.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 3.636 seconds Jan 27 13:28:28 2008 (2154) <20080127122808.25870.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 9.563 seconds Jan 27 13:29:26 2008 (2154) <mailman.1099.1201436955.2150.zvb@MYDOMAIN> smtp to zvb for 1 recips, completed in 9.095 seconds Jan 27 13:30:59 2008 (2154) <20080127123017.26417.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 24.989 seconds Jan 27 13:33:01 2008 (2154) <20080127123207.26967.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 42.552 seconds Jan 27 13:34:57 2008 (2154) <20080127123401.27408.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 55.860 seconds Jan 27 13:37:21 2008 (2154) <20080127123607.27936.qmail@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?

=========== VETTE ===============

nothing relevant here

================= ps aux | grep -i mailman ============

mailman 2139 0.0 0.1 13608 724 ? Ss Jan03 0:00 /usr/bin/python /usr/local/mailman/bin/mailmanctl -s -q start mailman 2149 0.0 1.2 15280 6180 ? S Jan03 7:43 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=ArchRunner:0:1 -s mailman 2150 0.0 1.0 14696 5160 ? S Jan03 7:42 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=BounceRunner:0:1 -s mailman 2151 0.0 0.4 14376 2396 ? S Jan03 3:49 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=CommandRunner:0:1 -s mailman 2152 0.0 1.3 15392 6452 ? S Jan03 11:04 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=IncomingRunner:0:1 -s mailman 2153 0.0 0.4 13436 1936 ? S Jan03 5:35 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=NewsRunner:0:1 -s mailman 2154 0.0 1.1 16572 5520 ? S Jan03 7:26 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=OutgoingRunner:0:1 -s

OutgoingRunner appears normal.

mailman 2155 0.0 1.0 14376 5040 ? S Jan03 2:27 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=VirginRunner:0:1 -s mailman 2156 0.0 0.4 14240 1964 ? S Jan03 0:10 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=RetryRunner:0:1 -s

================= QMAIL-SENT ========================= ======= almost all the mail except my test mails are spam

See my comments interspersed in these log entries.

<snip>

2008-01-27 13:36:13.967860500 new msg 232139 2008-01-27 13:36:13.967867500 info msg 232139: bytes 291 from <TESTMAIL@MYDOMAIN> qp 27937 uid 511 2008-01-27 13:36:13.978364500 starting delivery 106841: msg 232139 to local MYDOMAIN-test@MYDOMAIN

The above is the post to your list.

2008-01-27 13:36:13.978372500 status: local 3/10 remote 3/200 2008-01-27 13:36:15.843941500 delivery 106838: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:15.843950500 status: local 2/10 remote 3/200 2008-01-27 13:36:15.843952500 end msg 232130 2008-01-27 13:36:16.764732500 delivery 106841: success: did_0+0+1/ 2008-01-27 13:36:16.764740500 status: local 1/10 remote 3/200 2008-01-27 13:36:16.764742500 end msg 232139

And the completion of its delivery.

2008-01-27 13:36:16.786087500 delivery 106836: success: did_0+0+1/ 2008-01-27 13:36:16.786093500 status: local 0/10 remote 3/200 2008-01-27 13:36:16.786095500 end msg 232129

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

2008-01-27 13:36:20.801466500 delivery 106837: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801474500 status: local 0/10 remote 2/200 2008-01-27 13:36:20.801476500 delivery 106839: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801478500 status: local 0/10 remote 1/200 2008-01-27 13:36:20.801480500 delivery 106840: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801482500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.417035500 new msg 232139 2008-01-27 13:36:28.417042500 info msg 232139: bytes 4895 from <jrapp314@cedarville.edu> qp 27992 uid 509 2008-01-27 13:36:28.467668500 starting delivery 106842: msg 232139 to local MYDOMAIN-hszdzlbsrkvx@MYDOMAIN 2008-01-27 13:36:28.467676500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.483611500 new msg 232141 2008-01-27 13:36:28.483618500 info msg 232141: bytes 5000 from <jrapp314@cedarville.edu> qp 27998 uid 509 2008-01-27 13:36:28.520522500 starting delivery 106843: msg 232141 to local MYDOMAIN-gonzalesenrika@MYDOMAIN 2008-01-27 13:36:28.520529500 status: local 2/10 remote 0/200 2008-01-27 13:36:28.536605500 delivery 106842: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.536612500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.536614500 end msg 232139 2008-01-27 13:36:28.544080500 new msg 232146 2008-01-27 13:36:28.544086500 info msg 232146: bytes 4907 from <jrafert471@hersheys.com> qp 28003 uid 509 2008-01-27 13:36:28.576432500 starting delivery 106844: msg 232146 to local MYDOMAIN-hovgxnik@MYDOMAIN 2008-01-27 13:36:28.576438500 status: local 2/10 remote 0/200 2008-01-27 13:36:28.624391500 delivery 106843: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.624401500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.624403500 end msg 232141 2008-01-27 13:36:28.660295500 delivery 106844: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.660303500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.660305500 end msg 232146 2008-01-27 13:36:28.665366500 new msg 232150 2008-01-27 13:36:28.665374500 info msg 232150: bytes 4980 from <jrapp314@cedarville.edu> qp 28007 uid 509 2008-01-27 13:36:28.674495500 starting delivery 106845: msg 232150 to local MYDOMAIN-gruppo@MYDOMAIN 2008-01-27 13:36:28.674504500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.739182500 delivery 106845: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.739191500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.739193500 end msg 232150 2008-01-27 13:36:33.833645500 new msg 232137 2008-01-27 13:36:33.833651500 info msg 232137: bytes 4876 from <jqyay@travelgolf.com> qp 28040 uid 509 2008-01-27 13:36:33.963488500 starting delivery 106846: msg 232137 to local MYDOMAIN-mailman@MYDOMAIN 2008-01-27 13:36:33.963493500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.560879500 delivery 106846: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.560885500 status: local 0/10 remote 0/200 2008-01-27 13:36:43.560887500 end msg 232137 2008-01-27 13:36:43.570897500 new msg 232139 2008-01-27 13:36:43.570905500 info msg 232139: bytes 5011 from <jrafert471@hersheys.com> qp 28045 uid 509 2008-01-27 13:36:43.645354500 starting delivery 106847: msg 232139 to local MYDOMAIN-hszdzlbsrkvx@MYDOMAIN 2008-01-27 13:36:43.645361500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.645363500 new msg 232149 2008-01-27 13:36:43.645364500 info msg 232149: bytes 5169 from <jrakers@mtco.com> qp 28081 uid 509 2008-01-27 13:36:43.696390500 starting delivery 106848: msg 232149 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:36:43.696400500 status: local 2/10 remote 0/200 2008-01-27 13:36:43.696402500 delivery 106847: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.696404500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.696406500 end msg 232139 2008-01-27 13:36:43.754748500 delivery 106848: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.754755500 status: local 0/10 remote 0/200 2008-01-27 13:36:43.754757500 end msg 232149 2008-01-27 13:36:56.100050500 new msg 232139 2008-01-27 13:36:56.100371500 info msg 232139: bytes 4743 from <jramos@20minutos.es> qp 28123 uid 509 2008-01-27 13:36:56.116975500 starting delivery 106849: msg 232139 to local MYDOMAIN-uiakjb@MYDOMAIN 2008-01-27 13:36:56.117266500 status: local 1/10 remote 0/200 2008-01-27 13:36:56.132433500 new msg 232129 2008-01-27 13:36:56.132800500 info msg 232129: bytes 5136 from <jrakers@mtco.com> qp 28116 uid 509 2008-01-27 13:36:56.158337500 starting delivery 106850: msg 232129 to local MYDOMAIN-ga@MYDOMAIN 2008-01-27 13:36:56.158790500 status: local 2/10 remote 0/200 2008-01-27 13:36:56.172853500 delivery 106849: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:56.173395500 status: local 1/10 remote 0/200 2008-01-27 13:36:56.173936500 end msg 232139 2008-01-27 13:36:56.187853500 delivery 106850: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:56.188417500 status: local 0/10 remote 0/200 2008-01-27 13:36:56.188921500 end msg 232129

Why the discontinuity in timestamps here?

2008-01-27 13:13:37.440653500 new msg 232140 2008-01-27 13:13:37.440661500 info msg 232140: bytes 4933 from <jraqn@hq.com> qp 23956 uid 509 2008-01-27 13:13:37.477036500 starting delivery 106595: msg 232140 to local MYDOMAIN-freeradius-devel-owotyv@MYDOMAIN 2008-01-27 13:13:37.477081500 status: local 2/10 remote 0/200 2008-01-27 13:13:37.522920500 delivery 106594: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:37.541620500 status: local 1/10 remote 0/200 2008-01-27 13:13:37.541626500 end msg 232128 2008-01-27 13:13:37.542810500 delivery 106595: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:37.542818500 status: local 0/10 remote 0/200 2008-01-27 13:13:37.542820500 end msg 232140 2008-01-27 13:13:37.547397500 new msg 231316 2008-01-27 13:13:37.547405500 info msg 231316: bytes 3678 from <mailman-bounces@MYDOMAIN> qp 23965 uid 509 2008-01-27 13:13:37.555521500 starting delivery 106596: msg 231316 to local MYDOMAIN-mc@MYDOMAIN 2008-01-27 13:13:37.555529500 status: local 1/10 remote 0/200 2008-01-27 13:13:37.695498500 delivery 106596: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[23973]_Sun_Jan_27_13:13:37_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/mc/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/mc/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/mc/procmail.log"/did_0+0+1/ 2008-01-27 13:13:37.695507500 status: local 0/10 remote 0/200 2008-01-27 13:13:37.695509500 end msg 231316

End timstamps out of sequence.

2008-01-27 13:37:00.390197500 new msg 232130 2008-01-27 13:37:00.390202500 info msg 232130: bytes 4949 from <jrafert471@hersheys.com> qp 28145 uid 509 2008-01-27 13:37:00.426136500 starting delivery 106851: msg 232130 to local MYDOMAIN-infod@MYDOMAIN 2008-01-27 13:37:00.426145500 status: local 1/10 remote 0/200 2008-01-27 13:37:00.542765500 delivery 106851: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:00.542773500 status: local 0/10 remote 0/200 2008-01-27 13:37:00.542775500 end msg 232130 2008-01-27 13:37:00.747076500 new msg 232139 2008-01-27 13:37:00.747082500 info msg 232139: bytes 1395 from <adventistve9389@creative-plane.com> qp 28149 uid 509 2008-01-27 13:37:00.797468500 starting delivery 106852: msg 232139 to local MYDOMAIN-sebvgc@MYDOMAIN 2008-01-27 13:37:00.797475500 status: local 1/10 remote 0/200 2008-01-27 13:37:00.826458500 delivery 106852: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:00.826465500 status: local 0/10 remote 0/200 2008-01-27 13:37:00.826467500 end msg 232139 2008-01-27 13:37:02.845422500 new msg 232130 2008-01-27 13:37:02.845430500 info msg 232130: bytes 4894 from <jrafert471@hersheys.com> qp 28165 uid 509 2008-01-27 13:37:02.867282500 starting delivery 106853: msg 232130 to local MYDOMAIN-gmhu@MYDOMAIN 2008-01-27 13:37:02.867289500 status: local 1/10 remote 0/200 2008-01-27 13:37:02.893949500 delivery 106853: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:02.893957500 status: local 0/10 remote 0/200 2008-01-27 13:37:02.893959500 end msg 232130 2008-01-27 13:37:02.904499500 new msg 232128 2008-01-27 13:37:02.904504500 info msg 232128: bytes 5097 from <jquinn@prudentialdoss.com> qp 28161 uid 509 2008-01-27 13:37:02.919415500 starting delivery 106854: msg 232128 to local MYDOMAIN-climmichiel@MYDOMAIN 2008-01-27 13:37:02.919423500 status: local 1/10 remote 0/200 2008-01-27 13:37:02.949425500 delivery 106854: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:02.949433500 status: local 0/10 remote 0/200 2008-01-27 13:37:02.949435500 end msg 232128 2008-01-27 13:37:17.973957500 new msg 232140 2008-01-27 13:37:17.973964500 info msg 232140: bytes 5004 from <jrapp314@cedarville.edu> qp 28220 uid 509 2008-01-27 13:37:18.024843500 starting delivery 106855: msg 232140 to local MYDOMAIN-gmhu@MYDOMAIN 2008-01-27 13:37:18.024851500 status: local 1/10 remote 0/200 2008-01-27 13:37:19.187835500 delivery 106855: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:19.187841500 status: local 0/10 remote 0/200 2008-01-27 13:37:19.200568500 starting delivery 106856: msg 229708 to remote HIDDEN_EXTERNAL_ADDRESS 2008-01-27 13:37:19.200580500 status: local 0/10 remote 1/200 2008-01-27 13:37:19.200581500 end msg 232140 2008-01-27 13:37:19.211720500 new msg 232144 2008-01-27 13:37:19.211727500 info msg 232144: bytes 4921 from <jqsvd@ter.com> qp 28225 uid 509 2008-01-27 13:37:19.297540500 starting delivery 106857: msg 232144 to local MYDOMAIN-zvb-owner@MYDOMAIN 2008-01-27 13:37:19.297547500 status: local 1/10 remote 1/200 2008-01-27 13:37:20.579956500 delivery 106856: deferral: 206.190.53.191_failed_after_I_sent_the_message./Remote_host_said:_451_Message_temporarily_deferred_-_[70]/ 2008-01-27 13:37:20.579962500 status: local 1/10 remote 0/200 2008-01-27 13:37:20.826018500 new msg 232141 2008-01-27 13:37:20.826027500 info msg 232141: bytes 5026 from <jragland@fuse.net> qp 28223 uid 509 2008-01-27 13:37:20.878151500 starting delivery 106858: msg 232141 to local MYDOMAIN-millsaimerisa@MYDOMAIN 2008-01-27 13:37:20.878158500 status: local 2/10 remote 0/200 2008-01-27 13:37:20.882654500 delivery 106858: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:20.882662500 status: local 1/10 remote 0/200 2008-01-27 13:37:20.882664500 end msg 232141 2008-01-27 13:37:21.157840500 delivery 106857: success: did_0+0+1/ 2008-01-27 13:37:21.157849500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.157850500 end msg 232144

Here, Qmail logs the start of the delivery of the post from the list, but the SMTP connect was issued by Mailman over a minute ago.

2008-01-27 13:37:21.163382500 new msg 232128 2008-01-27 13:37:21.163389500 info msg 232128: bytes 1895 from <test-bounces@MYDOMAIN> qp 28246 uid 509 2008-01-27 13:37:21.185407500 starting delivery 106859: msg 232128 to local MYDOMAIN-mailman-test@MYDOMAIN 2008-01-27 13:37:21.185414500 status: local 1/10 remote 0/200 2008-01-27 13:37:21.185416500 delivery 106859: success: did_0+0+1/ 2008-01-27 13:37:21.185417500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.185419500 end msg 232128

Delivery completes.

2008-01-27 13:37:21.254274500 new msg 232149 2008-01-27 13:37:21.254283500 info msg 232149: bytes 4853 from <jragland@fuse.net> qp 28243 uid 509 2008-01-27 13:37:21.308078500 starting delivery 106860: msg 232149 to local MYDOMAIN-mooresmtpesxbswr@MYDOMAIN 2008-01-27 13:37:21.308084500 status: local 1/10 remote 0/200 2008-01-27 13:37:21.330455500 delivery 106860: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:21.330462500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.330464500 end msg 232149 2008-01-27 13:37:27.732534500 new msg 232139 2008-01-27 13:37:27.732540500 info msg 232139: bytes 5094 from <jrapp314@cedarville.edu> qp 28285 uid 509 2008-01-27 13:37:27.753766500 starting delivery 106861: msg 232139 to local MYDOMAIN-info@MYDOMAIN 2008-01-27 13:37:27.753773500 status: local 1/10 remote 0/200 2008-01-27 13:37:27.784165500 delivery 106861: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:27.784173500 status: local 0/10 remote 0/200 2008-01-27 13:37:27.784175500 end msg 232139 2008-01-27 13:37:35.365248500 new msg 232142 2008-01-27 13:37:35.365254500 info msg 232142: bytes 5000 from <jrapp314@cedarville.edu> qp 28333 uid 509 2008-01-27 13:37:35.387598500 starting delivery 106862: msg 232142 to local MYDOMAIN-infod@MYDOMAIN 2008-01-27 13:37:35.387605500 status: local 1/10 remote 0/200 2008-01-27 13:37:35.409312500 delivery 106862: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:35.409321500 status: local 0/10 remote 0/200 2008-01-27 13:37:35.409323500 end msg 232142 2008-01-27 13:37:41.924897500 new msg 232142 2008-01-27 13:37:41.924907500 info msg 232142: bytes 5065 from <jr2004@uol.com.br> qp 28351 uid 509 2008-01-27 13:37:41.975110500 starting delivery 106863: msg 232142 to local MYDOMAIN-qif@MYDOMAIN 2008-01-27 13:37:41.975117500 status: local 1/10 remote 0/200 2008-01-27 13:37:41.999415500 delivery 106863: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:41.999422500 status: local 0/10 remote 0/200 2008-01-27 13:37:41.999424500 end msg 232142 2008-01-27 13:37:49.686625500 new msg 232129 2008-01-27 13:37:49.686973500 info msg 232129: bytes 5028 from <jragland@fuse.net> qp 28362 uid 509 2008-01-27 13:37:55.137142500 starting delivery 106864: msg 232129 to local MYDOMAIN-notizie@MYDOMAIN 2008-01-27 13:37:55.137428500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.301245500 delivery 106864: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[28399]_Sun_Jan_27_13:37:55_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/notizie/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/notizie/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/notizie/procmail.log"/did_0+0+1/ 2008-01-27 13:37:55.301885500 status: local 0/10 remote 0/200 2008-01-27 13:37:55.302450500 end msg 232129 2008-01-27 13:37:55.303222500 new msg 232150 2008-01-27 13:37:55.303494500 info msg 232150: bytes 4949 from <jramos@20minutos.es> qp 28386 uid 509 2008-01-27 13:37:55.355206500 starting delivery 106865: msg 232150 to local MYDOMAIN-uweia@MYDOMAIN 2008-01-27 13:37:55.355505500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.370020500 new msg 232149 2008-01-27 13:37:55.370332500 info msg 232149: bytes 4951 from <jqyay@travelgolf.com> qp 28383 uid 509 2008-01-27 13:37:55.395926500 starting delivery 106866: msg 232149 to local MYDOMAIN-meggithaler@MYDOMAIN 2008-01-27 13:37:55.396228500 status: local 2/10 remote 0/200 2008-01-27 13:37:55.410471500 delivery 106865: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:55.411083500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.411620500 end msg 232150 2008-01-27 13:37:55.440438500 delivery 106866: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:55.483851500 status: local 0/10 remote 0/200 2008-01-27 13:37:55.484345500 end msg 232149 2008-01-27 13:37:56.449041500 new msg 231909 2008-01-27 13:37:56.449047500 info msg 231909: bytes 4979 from <jrakers@mtco.com> qp 28410 uid 509 2008-01-27 13:37:56.491199500 starting delivery 106867: msg 231909 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:37:56.491207500 status: local 1/10 remote 0/200 2008-01-27 13:37:56.513523500 delivery 106867: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:56.513532500 status: local 0/10 remote 0/200 2008-01-27 13:37:56.513534500 end msg 231909 2008-01-27 02:13:38.890632500 new msg 229720

More out of sequence timestamps.

2008-01-27 02:13:38.890638500 info msg 229720: bytes 5282 from <jr@drillerssupply.com> qp 30272 uid 509 2008-01-27 13:13:38.855855500 new msg 231316 2008-01-27 13:13:38.855863500 info msg 231316: bytes 1673 from <attelijkabawk@agosd.org> qp 23976 uid 509 2008-01-27 13:13:38.863330500 starting delivery 106597: msg 231316 to local MYDOMAIN-uucp@MYDOMAIN 2008-01-27 13:13:38.863336500 status: local 1/10 remote 0/200 2008-01-27 13:13:38.926690500 delivery 106597: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:38.926697500 status: local 0/10 remote 0/200 2008-01-27 13:13:38.926699500 end msg 231316

End timestamps out of sequence.

2008-01-27 13:38:00.870266500 new msg 232130 2008-01-27 13:38:00.870273500 info msg 232130: bytes 4762 from <jrafert471@hersheys.com> qp 28419 uid 509 2008-01-27 13:38:00.891481500 starting delivery 106868: msg 232130 to local MYDOMAIN-jaquenettawiatt@MYDOMAIN 2008-01-27 13:38:00.891487500 status: local 1/10 remote 0/200 2008-01-27 13:38:00.920009500 delivery 106868: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:00.920017500 status: local 0/10 remote 0/200 2008-01-27 13:38:00.920019500 end msg 232130 2008-01-27 13:38:05.268085500 new msg 232130 2008-01-27 13:38:05.268092500 info msg 232130: bytes 5078 from <jrakers@mtco.com> qp 28425 uid 509 2008-01-27 13:38:05.325911500 starting delivery 106869: msg 232130 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:38:05.325917500 status: local 1/10 remote 0/200 2008-01-27 13:38:06.737068500 delivery 106869: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[28454]_Sun_Jan_27_13:38:06_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/fs/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/fs/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/fs/procmail.log"/did_0+0+1/ 2008-01-27 13:38:06.737077500 status: local 0/10 remote 0/200 2008-01-27 13:38:06.737079500 end msg 232130 2008-01-27 13:38:06.743687500 new msg 232138 2008-01-27 13:38:06.743694500 info msg 232138: bytes 5047 from <jrapp314@cedarville.edu> qp 28443 uid 509 2008-01-27 13:38:06.794904500 starting delivery 106870: msg 232138 to local MYDOMAIN-infodd@MYDOMAIN 2008-01-27 13:38:06.794910500 status: local 1/10 remote 0/200 2008-01-27 13:38:06.797258500 delivery 106870: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:06.797266500 status: local 0/10 remote 0/200 2008-01-27 13:38:06.797268500 end msg 232138 2008-01-27 13:38:06.798999500 new msg 232149 2008-01-27 13:38:06.799006500 info msg 232149: bytes 291 from <TESTMAIL@MYDOMAIN> qp 28437 uid 511 2008-01-27 13:38:06.824979500 starting delivery 106871: msg 232149 to local MYDOMAIN-test@MYDOMAIN 2008-01-27 13:38:06.824986500 status: local 1/10 remote 0/200 2008-01-27 13:38:08.511684500 delivery 106871: success: did_0+0+1/ 2008-01-27 13:38:08.511691500 status: local 0/10 remote 0/200 2008-01-27 13:38:08.511692500 end msg 232149 2008-01-27 13:38:21.766375500 new msg 232142 2008-01-27 13:38:21.766382500 info msg 232142: bytes 4863 from <jrapp314@cedarville.edu> qp 28506 uid 509 2008-01-27 13:38:21.806125500 starting delivery 106872: msg 232142 to local MYDOMAIN-jaquenettawiatt@MYDOMAIN 2008-01-27 13:38:21.806130500 status: local 1/10 remote 0/200 2008-01-27 13:38:21.817952500 new msg 232140 2008-01-27 13:38:21.817963500 info msg 232140: bytes 5043 from <jr2004@uol.com.br> qp 28500 uid 509 2008-01-27 13:38:21.883029500 starting delivery 106873: msg 232140 to local MYDOMAIN-catchallnn@MYDOMAIN 2008-01-27 13:38:21.883036500 status: local 2/10 remote 0/200 2008-01-27 13:38:21.883038500 delivery 106872: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:21.883040500 status: local 1/10 remote 0/200 2008-01-27 13:38:21.883042500 end msg 232142 2008-01-27 13:38:21.908417500 delivery 106873: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:21.908428500 status: local 0/10 remote 0/200 2008-01-27 13:38:21.908430500 end msg 232140 2008-01-27 13:38:32.057960500 new msg 232130 2008-01-27 13:38:32.057967500 info msg 232130: bytes 4807 from <jramos@20minutos.es> qp 28533 uid 509 2008-01-27 13:38:32.099926500 starting delivery 106874: msg 232130 to local MYDOMAIN-zvb-bounces@MYDOMAIN 2008-01-27 13:38:32.099933500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.153416500 new msg 232141 2008-01-27 13:38:32.153425500 info msg 232141: bytes 5033 from <jqsvd@ter.com> qp 28539 uid 509 2008-01-27 13:38:32.167114500 starting delivery 106875: msg 232141 to local MYDOMAIN-zvb-request@MYDOMAIN 2008-01-27 13:38:32.167124500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.206643500 delivery 106875: success:

What's going on with these procmail entries for mailman? What's in /home/vpopmail/domains/MYDOMAIN/procmail-mailman.log?

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/ 2008-01-27 13:38:32.206655500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.206740500 end msg 232141 2008-01-27 13:38:32.312694500 new msg 232144 2008-01-27 13:38:32.312699500 info msg 232144: bytes 5043 from <jr2004@uol.com.br> qp 28536 uid 509 2008-01-27 13:38:32.364072500 starting delivery 106876: msg 232144 to local MYDOMAIN-re@MYDOMAIN 2008-01-27 13:38:32.364079500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.365545500 new msg 232142 2008-01-27 13:38:32.365553500 info msg 232142: bytes 4932 from <jramos@20minutos.es> qp 28542 uid 509 2008-01-27 13:38:32.408993500 starting delivery 106877: msg 232142 to local MYDOMAIN-sp-request@MYDOMAIN 2008-01-27 13:38:32.409002500 status: local 3/10 remote 0/200 2008-01-27 13:38:32.409004500 delivery 106876: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:32.409006500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.409008500 end msg 232144 2008-01-27 13:38:32.490732500 delivery 106877: success: procmail:_[28556]_Sun_Jan_27_13:38:32_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.sp"/procmail:_Couldn't_chdir_to_"/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.sp"/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/ 2008-01-27 13:38:32.490743500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.490837500 end msg 232142 2008-01-27 13:38:32.898991500 delivery 106874: success: did_0+0+1/ 2008-01-27 13:38:32.898998500 status: local 0/10 remote 0/200 2008-01-27 13:38:32.899000500 end msg 232130 2008-01-27 13:38:43.941309500 new msg 232141 2008-01-27 13:38:43.941315500 info msg 232141: bytes 4977 from <jqsvd@ter.com> qp 28591 uid 509 2008-01-27 13:38:44.002411500 starting delivery 106878: msg 232141 to local MYDOMAIN-zvb-subscribe@MYDOMAIN 2008-01-27 13:38:44.002416500 status: local 1/10 remote 0/200 2008-01-27 13:38:44.020049500 delivery 106878: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:44.020057500 status: local 0/10 remote 0/200 2008-01-27 13:38:44.020059500 end msg 232141 2008-01-27 13:38:53.524582500 new msg 232141 2008-01-27 13:38:53.524587500 info msg 232141: bytes 4856 from <jragland@fuse.net> qp 28631 uid 509 2008-01-27 13:38:53.573159500 starting delivery 106879: msg 232141 to local MYDOMAIN-owotyv@MYDOMAIN 2008-01-27 13:38:53.573174500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.574618500 new msg 232142 2008-01-27 13:38:53.574627500 info msg 232142: bytes 4980 from <jr2004@uol.com.br> qp 28625 uid 509 2008-01-27 13:38:53.629800500 starting delivery 106880: msg 232142 to local MYDOMAIN-catchallk@MYDOMAIN 2008-01-27 13:38:53.629807500 status: local 2/10 remote 0/200 2008-01-27 13:38:53.629809500 delivery 106879: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:53.629812500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.629813500 end msg 232141 2008-01-27 13:38:53.631091500 new msg 232144 2008-01-27 13:38:53.631098500 info msg 232144: bytes 4893 from <jramos@20minutos.es> qp 28628 uid 509 2008-01-27 13:38:53.678298500 starting delivery 106881: msg 232144 to local MYDOMAIN-sp-bounces@MYDOMAIN 2008-01-27 13:38:53.678309500 status: local 2/10 remote 0/200 2008-01-27 13:38:53.678311500 delivery 106880: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:53.678313500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.678315500 end msg 232142

Questions?

What's going on with procmail?

What if anything is in Mailman's error and smtp-failure logs?

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.

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

SP wrote:

Thanks for the suggestion: this is what I did yesterday. :-) A message is sent to a test list every 2 minutes: the last sent message was that of 13:36 so whatever happened to mailman, it happened between 13:36 and 13:38, the time of the first message which got stuck in qfiles/out.

Here are my logs from mailman and from my MTA (qmail)... unfortunately I can't see anything which can suggest the reason of my problem in any of them, so my only choice is to post them all... I post only logs which have some entry dated today, 27 Jan.

Hope that someone here can find something interesting (and helpful for me!) :-)

=========== BOUNCE ===============

nothing relevant here

=========== POST ===============

<snip>

Jan 27 13:37:21 2008 (2154) post to test from TESTMAIL@MYDOMAIN, size=1236, message-id=<20080127123607.27936.qmail@MYDOMAIN>, success

The last post processed by Mailman. The next one isn't logged as it is still in the queue.

=========== QRUNNER ===============

unfortunately, nothing relevant here.

=========== SMTP ===============

Jan 27 13:20:14 2008 (2154) <20080127122001.25001.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 7.613 seconds Jan 27 13:22:04 2008 (2154) <20080127122201.25176.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 1.817 seconds Jan 27 13:24:05 2008 (2154) <20080127122401.25298.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 1.516 seconds Jan 27 13:26:06 2008 (2154) <20080127122601.25433.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 3.636 seconds Jan 27 13:28:28 2008 (2154) <20080127122808.25870.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 9.563 seconds Jan 27 13:29:26 2008 (2154) <mailman.1099.1201436955.2150.zvb@MYDOMAIN> smtp to zvb for 1 recips, completed in 9.095 seconds Jan 27 13:30:59 2008 (2154) <20080127123017.26417.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 24.989 seconds Jan 27 13:33:01 2008 (2154) <20080127123207.26967.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 42.552 seconds Jan 27 13:34:57 2008 (2154) <20080127123401.27408.qmail@MYDOMAIN> smtp to test for 1 recips, completed in 55.860 seconds Jan 27 13:37:21 2008 (2154) <20080127123607.27936.qmail@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?

=========== VETTE ===============

nothing relevant here

================= ps aux | grep -i mailman ============

mailman 2139 0.0 0.1 13608 724 ? Ss Jan03 0:00 /usr/bin/python /usr/local/mailman/bin/mailmanctl -s -q start mailman 2149 0.0 1.2 15280 6180 ? S Jan03 7:43 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=ArchRunner:0:1 -s mailman 2150 0.0 1.0 14696 5160 ? S Jan03 7:42 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=BounceRunner:0:1 -s mailman 2151 0.0 0.4 14376 2396 ? S Jan03 3:49 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=CommandRunner:0:1 -s mailman 2152 0.0 1.3 15392 6452 ? S Jan03 11:04 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=IncomingRunner:0:1 -s mailman 2153 0.0 0.4 13436 1936 ? S Jan03 5:35 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=NewsRunner:0:1 -s mailman 2154 0.0 1.1 16572 5520 ? S Jan03 7:26 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=OutgoingRunner:0:1 -s

OutgoingRunner appears normal.

mailman 2155 0.0 1.0 14376 5040 ? S Jan03 2:27 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=VirginRunner:0:1 -s mailman 2156 0.0 0.4 14240 1964 ? S Jan03 0:10 /usr/bin/python /usr/local/mailman/bin/qrunner --runner=RetryRunner:0:1 -s

================= QMAIL-SENT ========================= ======= almost all the mail except my test mails are spam

See my comments interspersed in these log entries.

<snip>

2008-01-27 13:36:13.967860500 new msg 232139 2008-01-27 13:36:13.967867500 info msg 232139: bytes 291 from <TESTMAIL@MYDOMAIN> qp 27937 uid 511 2008-01-27 13:36:13.978364500 starting delivery 106841: msg 232139 to local MYDOMAIN-test@MYDOMAIN

The above is the post to your list.

2008-01-27 13:36:13.978372500 status: local 3/10 remote 3/200 2008-01-27 13:36:15.843941500 delivery 106838: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:15.843950500 status: local 2/10 remote 3/200 2008-01-27 13:36:15.843952500 end msg 232130 2008-01-27 13:36:16.764732500 delivery 106841: success: did_0+0+1/ 2008-01-27 13:36:16.764740500 status: local 1/10 remote 3/200 2008-01-27 13:36:16.764742500 end msg 232139

And the completion of its delivery.

2008-01-27 13:36:16.786087500 delivery 106836: success: did_0+0+1/ 2008-01-27 13:36:16.786093500 status: local 0/10 remote 3/200 2008-01-27 13:36:16.786095500 end msg 232129

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

2008-01-27 13:36:20.801466500 delivery 106837: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801474500 status: local 0/10 remote 2/200 2008-01-27 13:36:20.801476500 delivery 106839: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801478500 status: local 0/10 remote 1/200 2008-01-27 13:36:20.801480500 delivery 106840: deferral: Sorry,_I_couldn't_find_any_host_by_that_name._(#4.1.2)/ 2008-01-27 13:36:20.801482500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.417035500 new msg 232139 2008-01-27 13:36:28.417042500 info msg 232139: bytes 4895 from <jrapp314@cedarville.edu> qp 27992 uid 509 2008-01-27 13:36:28.467668500 starting delivery 106842: msg 232139 to local MYDOMAIN-hszdzlbsrkvx@MYDOMAIN 2008-01-27 13:36:28.467676500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.483611500 new msg 232141 2008-01-27 13:36:28.483618500 info msg 232141: bytes 5000 from <jrapp314@cedarville.edu> qp 27998 uid 509 2008-01-27 13:36:28.520522500 starting delivery 106843: msg 232141 to local MYDOMAIN-gonzalesenrika@MYDOMAIN 2008-01-27 13:36:28.520529500 status: local 2/10 remote 0/200 2008-01-27 13:36:28.536605500 delivery 106842: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.536612500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.536614500 end msg 232139 2008-01-27 13:36:28.544080500 new msg 232146 2008-01-27 13:36:28.544086500 info msg 232146: bytes 4907 from <jrafert471@hersheys.com> qp 28003 uid 509 2008-01-27 13:36:28.576432500 starting delivery 106844: msg 232146 to local MYDOMAIN-hovgxnik@MYDOMAIN 2008-01-27 13:36:28.576438500 status: local 2/10 remote 0/200 2008-01-27 13:36:28.624391500 delivery 106843: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.624401500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.624403500 end msg 232141 2008-01-27 13:36:28.660295500 delivery 106844: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.660303500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.660305500 end msg 232146 2008-01-27 13:36:28.665366500 new msg 232150 2008-01-27 13:36:28.665374500 info msg 232150: bytes 4980 from <jrapp314@cedarville.edu> qp 28007 uid 509 2008-01-27 13:36:28.674495500 starting delivery 106845: msg 232150 to local MYDOMAIN-gruppo@MYDOMAIN 2008-01-27 13:36:28.674504500 status: local 1/10 remote 0/200 2008-01-27 13:36:28.739182500 delivery 106845: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:28.739191500 status: local 0/10 remote 0/200 2008-01-27 13:36:28.739193500 end msg 232150 2008-01-27 13:36:33.833645500 new msg 232137 2008-01-27 13:36:33.833651500 info msg 232137: bytes 4876 from <jqyay@travelgolf.com> qp 28040 uid 509 2008-01-27 13:36:33.963488500 starting delivery 106846: msg 232137 to local MYDOMAIN-mailman@MYDOMAIN 2008-01-27 13:36:33.963493500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.560879500 delivery 106846: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.560885500 status: local 0/10 remote 0/200 2008-01-27 13:36:43.560887500 end msg 232137 2008-01-27 13:36:43.570897500 new msg 232139 2008-01-27 13:36:43.570905500 info msg 232139: bytes 5011 from <jrafert471@hersheys.com> qp 28045 uid 509 2008-01-27 13:36:43.645354500 starting delivery 106847: msg 232139 to local MYDOMAIN-hszdzlbsrkvx@MYDOMAIN 2008-01-27 13:36:43.645361500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.645363500 new msg 232149 2008-01-27 13:36:43.645364500 info msg 232149: bytes 5169 from <jrakers@mtco.com> qp 28081 uid 509 2008-01-27 13:36:43.696390500 starting delivery 106848: msg 232149 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:36:43.696400500 status: local 2/10 remote 0/200 2008-01-27 13:36:43.696402500 delivery 106847: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.696404500 status: local 1/10 remote 0/200 2008-01-27 13:36:43.696406500 end msg 232139 2008-01-27 13:36:43.754748500 delivery 106848: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:43.754755500 status: local 0/10 remote 0/200 2008-01-27 13:36:43.754757500 end msg 232149 2008-01-27 13:36:56.100050500 new msg 232139 2008-01-27 13:36:56.100371500 info msg 232139: bytes 4743 from <jramos@20minutos.es> qp 28123 uid 509 2008-01-27 13:36:56.116975500 starting delivery 106849: msg 232139 to local MYDOMAIN-uiakjb@MYDOMAIN 2008-01-27 13:36:56.117266500 status: local 1/10 remote 0/200 2008-01-27 13:36:56.132433500 new msg 232129 2008-01-27 13:36:56.132800500 info msg 232129: bytes 5136 from <jrakers@mtco.com> qp 28116 uid 509 2008-01-27 13:36:56.158337500 starting delivery 106850: msg 232129 to local MYDOMAIN-ga@MYDOMAIN 2008-01-27 13:36:56.158790500 status: local 2/10 remote 0/200 2008-01-27 13:36:56.172853500 delivery 106849: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:56.173395500 status: local 1/10 remote 0/200 2008-01-27 13:36:56.173936500 end msg 232139 2008-01-27 13:36:56.187853500 delivery 106850: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:36:56.188417500 status: local 0/10 remote 0/200 2008-01-27 13:36:56.188921500 end msg 232129

Why the discontinuity in timestamps here?

2008-01-27 13:13:37.440653500 new msg 232140 2008-01-27 13:13:37.440661500 info msg 232140: bytes 4933 from <jraqn@hq.com> qp 23956 uid 509 2008-01-27 13:13:37.477036500 starting delivery 106595: msg 232140 to local MYDOMAIN-freeradius-devel-owotyv@MYDOMAIN 2008-01-27 13:13:37.477081500 status: local 2/10 remote 0/200 2008-01-27 13:13:37.522920500 delivery 106594: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:37.541620500 status: local 1/10 remote 0/200 2008-01-27 13:13:37.541626500 end msg 232128 2008-01-27 13:13:37.542810500 delivery 106595: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:37.542818500 status: local 0/10 remote 0/200 2008-01-27 13:13:37.542820500 end msg 232140 2008-01-27 13:13:37.547397500 new msg 231316 2008-01-27 13:13:37.547405500 info msg 231316: bytes 3678 from <mailman-bounces@MYDOMAIN> qp 23965 uid 509 2008-01-27 13:13:37.555521500 starting delivery 106596: msg 231316 to local MYDOMAIN-mc@MYDOMAIN 2008-01-27 13:13:37.555529500 status: local 1/10 remote 0/200 2008-01-27 13:13:37.695498500 delivery 106596: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[23973]_Sun_Jan_27_13:13:37_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/mc/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/mc/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/mc/procmail.log"/did_0+0+1/ 2008-01-27 13:13:37.695507500 status: local 0/10 remote 0/200 2008-01-27 13:13:37.695509500 end msg 231316

End timstamps out of sequence.

2008-01-27 13:37:00.390197500 new msg 232130 2008-01-27 13:37:00.390202500 info msg 232130: bytes 4949 from <jrafert471@hersheys.com> qp 28145 uid 509 2008-01-27 13:37:00.426136500 starting delivery 106851: msg 232130 to local MYDOMAIN-infod@MYDOMAIN 2008-01-27 13:37:00.426145500 status: local 1/10 remote 0/200 2008-01-27 13:37:00.542765500 delivery 106851: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:00.542773500 status: local 0/10 remote 0/200 2008-01-27 13:37:00.542775500 end msg 232130 2008-01-27 13:37:00.747076500 new msg 232139 2008-01-27 13:37:00.747082500 info msg 232139: bytes 1395 from <adventistve9389@creative-plane.com> qp 28149 uid 509 2008-01-27 13:37:00.797468500 starting delivery 106852: msg 232139 to local MYDOMAIN-sebvgc@MYDOMAIN 2008-01-27 13:37:00.797475500 status: local 1/10 remote 0/200 2008-01-27 13:37:00.826458500 delivery 106852: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:00.826465500 status: local 0/10 remote 0/200 2008-01-27 13:37:00.826467500 end msg 232139 2008-01-27 13:37:02.845422500 new msg 232130 2008-01-27 13:37:02.845430500 info msg 232130: bytes 4894 from <jrafert471@hersheys.com> qp 28165 uid 509 2008-01-27 13:37:02.867282500 starting delivery 106853: msg 232130 to local MYDOMAIN-gmhu@MYDOMAIN 2008-01-27 13:37:02.867289500 status: local 1/10 remote 0/200 2008-01-27 13:37:02.893949500 delivery 106853: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:02.893957500 status: local 0/10 remote 0/200 2008-01-27 13:37:02.893959500 end msg 232130 2008-01-27 13:37:02.904499500 new msg 232128 2008-01-27 13:37:02.904504500 info msg 232128: bytes 5097 from <jquinn@prudentialdoss.com> qp 28161 uid 509 2008-01-27 13:37:02.919415500 starting delivery 106854: msg 232128 to local MYDOMAIN-climmichiel@MYDOMAIN 2008-01-27 13:37:02.919423500 status: local 1/10 remote 0/200 2008-01-27 13:37:02.949425500 delivery 106854: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:02.949433500 status: local 0/10 remote 0/200 2008-01-27 13:37:02.949435500 end msg 232128 2008-01-27 13:37:17.973957500 new msg 232140 2008-01-27 13:37:17.973964500 info msg 232140: bytes 5004 from <jrapp314@cedarville.edu> qp 28220 uid 509 2008-01-27 13:37:18.024843500 starting delivery 106855: msg 232140 to local MYDOMAIN-gmhu@MYDOMAIN 2008-01-27 13:37:18.024851500 status: local 1/10 remote 0/200 2008-01-27 13:37:19.187835500 delivery 106855: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:19.187841500 status: local 0/10 remote 0/200 2008-01-27 13:37:19.200568500 starting delivery 106856: msg 229708 to remote HIDDEN_EXTERNAL_ADDRESS 2008-01-27 13:37:19.200580500 status: local 0/10 remote 1/200 2008-01-27 13:37:19.200581500 end msg 232140 2008-01-27 13:37:19.211720500 new msg 232144 2008-01-27 13:37:19.211727500 info msg 232144: bytes 4921 from <jqsvd@ter.com> qp 28225 uid 509 2008-01-27 13:37:19.297540500 starting delivery 106857: msg 232144 to local MYDOMAIN-zvb-owner@MYDOMAIN 2008-01-27 13:37:19.297547500 status: local 1/10 remote 1/200 2008-01-27 13:37:20.579956500 delivery 106856: deferral: 206.190.53.191_failed_after_I_sent_the_message./Remote_host_said:_451_Message_temporarily_deferred_-_[70]/ 2008-01-27 13:37:20.579962500 status: local 1/10 remote 0/200 2008-01-27 13:37:20.826018500 new msg 232141 2008-01-27 13:37:20.826027500 info msg 232141: bytes 5026 from <jragland@fuse.net> qp 28223 uid 509 2008-01-27 13:37:20.878151500 starting delivery 106858: msg 232141 to local MYDOMAIN-millsaimerisa@MYDOMAIN 2008-01-27 13:37:20.878158500 status: local 2/10 remote 0/200 2008-01-27 13:37:20.882654500 delivery 106858: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:20.882662500 status: local 1/10 remote 0/200 2008-01-27 13:37:20.882664500 end msg 232141 2008-01-27 13:37:21.157840500 delivery 106857: success: did_0+0+1/ 2008-01-27 13:37:21.157849500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.157850500 end msg 232144

Here, Qmail logs the start of the delivery of the post from the list, but the SMTP connect was issued by Mailman over a minute ago.

2008-01-27 13:37:21.163382500 new msg 232128 2008-01-27 13:37:21.163389500 info msg 232128: bytes 1895 from <test-bounces@MYDOMAIN> qp 28246 uid 509 2008-01-27 13:37:21.185407500 starting delivery 106859: msg 232128 to local MYDOMAIN-mailman-test@MYDOMAIN 2008-01-27 13:37:21.185414500 status: local 1/10 remote 0/200 2008-01-27 13:37:21.185416500 delivery 106859: success: did_0+0+1/ 2008-01-27 13:37:21.185417500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.185419500 end msg 232128

Delivery completes.

2008-01-27 13:37:21.254274500 new msg 232149 2008-01-27 13:37:21.254283500 info msg 232149: bytes 4853 from <jragland@fuse.net> qp 28243 uid 509 2008-01-27 13:37:21.308078500 starting delivery 106860: msg 232149 to local MYDOMAIN-mooresmtpesxbswr@MYDOMAIN 2008-01-27 13:37:21.308084500 status: local 1/10 remote 0/200 2008-01-27 13:37:21.330455500 delivery 106860: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:21.330462500 status: local 0/10 remote 0/200 2008-01-27 13:37:21.330464500 end msg 232149 2008-01-27 13:37:27.732534500 new msg 232139 2008-01-27 13:37:27.732540500 info msg 232139: bytes 5094 from <jrapp314@cedarville.edu> qp 28285 uid 509 2008-01-27 13:37:27.753766500 starting delivery 106861: msg 232139 to local MYDOMAIN-info@MYDOMAIN 2008-01-27 13:37:27.753773500 status: local 1/10 remote 0/200 2008-01-27 13:37:27.784165500 delivery 106861: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:27.784173500 status: local 0/10 remote 0/200 2008-01-27 13:37:27.784175500 end msg 232139 2008-01-27 13:37:35.365248500 new msg 232142 2008-01-27 13:37:35.365254500 info msg 232142: bytes 5000 from <jrapp314@cedarville.edu> qp 28333 uid 509 2008-01-27 13:37:35.387598500 starting delivery 106862: msg 232142 to local MYDOMAIN-infod@MYDOMAIN 2008-01-27 13:37:35.387605500 status: local 1/10 remote 0/200 2008-01-27 13:37:35.409312500 delivery 106862: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:35.409321500 status: local 0/10 remote 0/200 2008-01-27 13:37:35.409323500 end msg 232142 2008-01-27 13:37:41.924897500 new msg 232142 2008-01-27 13:37:41.924907500 info msg 232142: bytes 5065 from <jr2004@uol.com.br> qp 28351 uid 509 2008-01-27 13:37:41.975110500 starting delivery 106863: msg 232142 to local MYDOMAIN-qif@MYDOMAIN 2008-01-27 13:37:41.975117500 status: local 1/10 remote 0/200 2008-01-27 13:37:41.999415500 delivery 106863: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:41.999422500 status: local 0/10 remote 0/200 2008-01-27 13:37:41.999424500 end msg 232142 2008-01-27 13:37:49.686625500 new msg 232129 2008-01-27 13:37:49.686973500 info msg 232129: bytes 5028 from <jragland@fuse.net> qp 28362 uid 509 2008-01-27 13:37:55.137142500 starting delivery 106864: msg 232129 to local MYDOMAIN-notizie@MYDOMAIN 2008-01-27 13:37:55.137428500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.301245500 delivery 106864: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[28399]_Sun_Jan_27_13:37:55_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/notizie/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/notizie/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/notizie/procmail.log"/did_0+0+1/ 2008-01-27 13:37:55.301885500 status: local 0/10 remote 0/200 2008-01-27 13:37:55.302450500 end msg 232129 2008-01-27 13:37:55.303222500 new msg 232150 2008-01-27 13:37:55.303494500 info msg 232150: bytes 4949 from <jramos@20minutos.es> qp 28386 uid 509 2008-01-27 13:37:55.355206500 starting delivery 106865: msg 232150 to local MYDOMAIN-uweia@MYDOMAIN 2008-01-27 13:37:55.355505500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.370020500 new msg 232149 2008-01-27 13:37:55.370332500 info msg 232149: bytes 4951 from <jqyay@travelgolf.com> qp 28383 uid 509 2008-01-27 13:37:55.395926500 starting delivery 106866: msg 232149 to local MYDOMAIN-meggithaler@MYDOMAIN 2008-01-27 13:37:55.396228500 status: local 2/10 remote 0/200 2008-01-27 13:37:55.410471500 delivery 106865: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:55.411083500 status: local 1/10 remote 0/200 2008-01-27 13:37:55.411620500 end msg 232150 2008-01-27 13:37:55.440438500 delivery 106866: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:55.483851500 status: local 0/10 remote 0/200 2008-01-27 13:37:55.484345500 end msg 232149 2008-01-27 13:37:56.449041500 new msg 231909 2008-01-27 13:37:56.449047500 info msg 231909: bytes 4979 from <jrakers@mtco.com> qp 28410 uid 509 2008-01-27 13:37:56.491199500 starting delivery 106867: msg 231909 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:37:56.491207500 status: local 1/10 remote 0/200 2008-01-27 13:37:56.513523500 delivery 106867: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:37:56.513532500 status: local 0/10 remote 0/200 2008-01-27 13:37:56.513534500 end msg 231909 2008-01-27 02:13:38.890632500 new msg 229720

More out of sequence timestamps.

2008-01-27 02:13:38.890638500 info msg 229720: bytes 5282 from <jr@drillerssupply.com> qp 30272 uid 509 2008-01-27 13:13:38.855855500 new msg 231316 2008-01-27 13:13:38.855863500 info msg 231316: bytes 1673 from <attelijkabawk@agosd.org> qp 23976 uid 509 2008-01-27 13:13:38.863330500 starting delivery 106597: msg 231316 to local MYDOMAIN-uucp@MYDOMAIN 2008-01-27 13:13:38.863336500 status: local 1/10 remote 0/200 2008-01-27 13:13:38.926690500 delivery 106597: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:13:38.926697500 status: local 0/10 remote 0/200 2008-01-27 13:13:38.926699500 end msg 231316

End timestamps out of sequence.

2008-01-27 13:38:00.870266500 new msg 232130 2008-01-27 13:38:00.870273500 info msg 232130: bytes 4762 from <jrafert471@hersheys.com> qp 28419 uid 509 2008-01-27 13:38:00.891481500 starting delivery 106868: msg 232130 to local MYDOMAIN-jaquenettawiatt@MYDOMAIN 2008-01-27 13:38:00.891487500 status: local 1/10 remote 0/200 2008-01-27 13:38:00.920009500 delivery 106868: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:00.920017500 status: local 0/10 remote 0/200 2008-01-27 13:38:00.920019500 end msg 232130 2008-01-27 13:38:05.268085500 new msg 232130 2008-01-27 13:38:05.268092500 info msg 232130: bytes 5078 from <jrakers@mtco.com> qp 28425 uid 509 2008-01-27 13:38:05.325911500 starting delivery 106869: msg 232130 to local MYDOMAIN-fs@MYDOMAIN 2008-01-27 13:38:05.325917500 status: local 1/10 remote 0/200 2008-01-27 13:38:06.737068500 delivery 106869: success: procmail:_Couldn't_create_"/var/mail/vpopmail"/procmail:_[28454]_Sun_Jan_27_13:38:06_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/fs/Maildir"/procmail:_Assigning_"LOGFILE=/home/vpopmail/domains/MYDOMAIN/fs/procmail.log"/procmail:_Opening_"/home/vpopmail/domains/MYDOMAIN/fs/procmail.log"/did_0+0+1/ 2008-01-27 13:38:06.737077500 status: local 0/10 remote 0/200 2008-01-27 13:38:06.737079500 end msg 232130 2008-01-27 13:38:06.743687500 new msg 232138 2008-01-27 13:38:06.743694500 info msg 232138: bytes 5047 from <jrapp314@cedarville.edu> qp 28443 uid 509 2008-01-27 13:38:06.794904500 starting delivery 106870: msg 232138 to local MYDOMAIN-infodd@MYDOMAIN 2008-01-27 13:38:06.794910500 status: local 1/10 remote 0/200 2008-01-27 13:38:06.797258500 delivery 106870: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:06.797266500 status: local 0/10 remote 0/200 2008-01-27 13:38:06.797268500 end msg 232138 2008-01-27 13:38:06.798999500 new msg 232149 2008-01-27 13:38:06.799006500 info msg 232149: bytes 291 from <TESTMAIL@MYDOMAIN> qp 28437 uid 511 2008-01-27 13:38:06.824979500 starting delivery 106871: msg 232149 to local MYDOMAIN-test@MYDOMAIN 2008-01-27 13:38:06.824986500 status: local 1/10 remote 0/200 2008-01-27 13:38:08.511684500 delivery 106871: success: did_0+0+1/ 2008-01-27 13:38:08.511691500 status: local 0/10 remote 0/200 2008-01-27 13:38:08.511692500 end msg 232149 2008-01-27 13:38:21.766375500 new msg 232142 2008-01-27 13:38:21.766382500 info msg 232142: bytes 4863 from <jrapp314@cedarville.edu> qp 28506 uid 509 2008-01-27 13:38:21.806125500 starting delivery 106872: msg 232142 to local MYDOMAIN-jaquenettawiatt@MYDOMAIN 2008-01-27 13:38:21.806130500 status: local 1/10 remote 0/200 2008-01-27 13:38:21.817952500 new msg 232140 2008-01-27 13:38:21.817963500 info msg 232140: bytes 5043 from <jr2004@uol.com.br> qp 28500 uid 509 2008-01-27 13:38:21.883029500 starting delivery 106873: msg 232140 to local MYDOMAIN-catchallnn@MYDOMAIN 2008-01-27 13:38:21.883036500 status: local 2/10 remote 0/200 2008-01-27 13:38:21.883038500 delivery 106872: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:21.883040500 status: local 1/10 remote 0/200 2008-01-27 13:38:21.883042500 end msg 232142 2008-01-27 13:38:21.908417500 delivery 106873: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:21.908428500 status: local 0/10 remote 0/200 2008-01-27 13:38:21.908430500 end msg 232140 2008-01-27 13:38:32.057960500 new msg 232130 2008-01-27 13:38:32.057967500 info msg 232130: bytes 4807 from <jramos@20minutos.es> qp 28533 uid 509 2008-01-27 13:38:32.099926500 starting delivery 106874: msg 232130 to local MYDOMAIN-zvb-bounces@MYDOMAIN 2008-01-27 13:38:32.099933500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.153416500 new msg 232141 2008-01-27 13:38:32.153425500 info msg 232141: bytes 5033 from <jqsvd@ter.com> qp 28539 uid 509 2008-01-27 13:38:32.167114500 starting delivery 106875: msg 232141 to local MYDOMAIN-zvb-request@MYDOMAIN 2008-01-27 13:38:32.167124500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.206643500 delivery 106875: success:

What's going on with these procmail entries for mailman? What's in /home/vpopmail/domains/MYDOMAIN/procmail-mailman.log?

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/ 2008-01-27 13:38:32.206655500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.206740500 end msg 232141 2008-01-27 13:38:32.312694500 new msg 232144 2008-01-27 13:38:32.312699500 info msg 232144: bytes 5043 from <jr2004@uol.com.br> qp 28536 uid 509 2008-01-27 13:38:32.364072500 starting delivery 106876: msg 232144 to local MYDOMAIN-re@MYDOMAIN 2008-01-27 13:38:32.364079500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.365545500 new msg 232142 2008-01-27 13:38:32.365553500 info msg 232142: bytes 4932 from <jramos@20minutos.es> qp 28542 uid 509 2008-01-27 13:38:32.408993500 starting delivery 106877: msg 232142 to local MYDOMAIN-sp-request@MYDOMAIN 2008-01-27 13:38:32.409002500 status: local 3/10 remote 0/200 2008-01-27 13:38:32.409004500 delivery 106876: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:32.409006500 status: local 2/10 remote 0/200 2008-01-27 13:38:32.409008500 end msg 232144 2008-01-27 13:38:32.490732500 delivery 106877: success: procmail:_[28556]_Sun_Jan_27_13:38:32_2008/procmail:_Assigning_"MAILDIR=/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.sp"/procmail:_Couldn't_chdir_to_"/home/vpopmail/domains/MYDOMAIN/mailmanspam/Maildir/.sp"/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/ 2008-01-27 13:38:32.490743500 status: local 1/10 remote 0/200 2008-01-27 13:38:32.490837500 end msg 232142 2008-01-27 13:38:32.898991500 delivery 106874: success: did_0+0+1/ 2008-01-27 13:38:32.898998500 status: local 0/10 remote 0/200 2008-01-27 13:38:32.899000500 end msg 232130 2008-01-27 13:38:43.941309500 new msg 232141 2008-01-27 13:38:43.941315500 info msg 232141: bytes 4977 from <jqsvd@ter.com> qp 28591 uid 509 2008-01-27 13:38:44.002411500 starting delivery 106878: msg 232141 to local MYDOMAIN-zvb-subscribe@MYDOMAIN 2008-01-27 13:38:44.002416500 status: local 1/10 remote 0/200 2008-01-27 13:38:44.020049500 delivery 106878: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:44.020057500 status: local 0/10 remote 0/200 2008-01-27 13:38:44.020059500 end msg 232141 2008-01-27 13:38:53.524582500 new msg 232141 2008-01-27 13:38:53.524587500 info msg 232141: bytes 4856 from <jragland@fuse.net> qp 28631 uid 509 2008-01-27 13:38:53.573159500 starting delivery 106879: msg 232141 to local MYDOMAIN-owotyv@MYDOMAIN 2008-01-27 13:38:53.573174500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.574618500 new msg 232142 2008-01-27 13:38:53.574627500 info msg 232142: bytes 4980 from <jr2004@uol.com.br> qp 28625 uid 509 2008-01-27 13:38:53.629800500 starting delivery 106880: msg 232142 to local MYDOMAIN-catchallk@MYDOMAIN 2008-01-27 13:38:53.629807500 status: local 2/10 remote 0/200 2008-01-27 13:38:53.629809500 delivery 106879: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:53.629812500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.629813500 end msg 232141 2008-01-27 13:38:53.631091500 new msg 232144 2008-01-27 13:38:53.631098500 info msg 232144: bytes 4893 from <jramos@20minutos.es> qp 28628 uid 509 2008-01-27 13:38:53.678298500 starting delivery 106881: msg 232144 to local MYDOMAIN-sp-bounces@MYDOMAIN 2008-01-27 13:38:53.678309500 status: local 2/10 remote 0/200 2008-01-27 13:38:53.678311500 delivery 106880: success: user_does_not_exist,_but_will_deliver_to_/home/vpopmail/domains/MYDOMAIN/catchall//did_0+0+1/ 2008-01-27 13:38:53.678313500 status: local 1/10 remote 0/200 2008-01-27 13:38:53.678315500 end msg 232142

Questions?

What's going on with procmail?

What if anything is in Mailman's error and smtp-failure logs?

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.

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