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

Tue Jan 29 00:02:01 CET 2008

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 at MYDOMAIN,
>size=1236, message-id=<20080127123607.27936.qmail at 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 at MYDOMAIN> smtp
>to test for 1 recips, completed in 7.613 seconds
>Jan 27 13:22:04 2008 (2154) <20080127122201.25176.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 1.817 seconds
>Jan 27 13:24:05 2008 (2154) <20080127122401.25298.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 1.516 seconds
>Jan 27 13:26:06 2008 (2154) <20080127122601.25433.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 3.636 seconds
>Jan 27 13:28:28 2008 (2154) <20080127122808.25870.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 9.563 seconds
>Jan 27 13:29:26 2008 (2154) <mailman.1099.1201436955.2150.zvb at MYDOMAIN>
>smtp to zvb for 1 recips, completed in 9.095 seconds
>Jan 27 13:30:59 2008 (2154) <20080127123017.26417.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 24.989 seconds
>Jan 27 13:33:01 2008 (2154) <20080127123207.26967.qmail at MYDOMAIN> smtp
>to test for 1 recips, completed in 42.552 seconds
>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?

>===========  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 at MYDOMAIN> qp 27937 uid 511
>2008-01-27 13:36:13.978364500 starting delivery 106841: msg 232139 to
>local MYDOMAIN-test at 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 at cedarville.edu> qp 27992 uid 509
>2008-01-27 13:36:28.467668500 starting delivery 106842: msg 232139 to
>local MYDOMAIN-hszdzlbsrkvx at 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 at cedarville.edu> qp 27998 uid 509
>2008-01-27 13:36:28.520522500 starting delivery 106843: msg 232141 to
>local MYDOMAIN-gonzalesenrika at 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 at hersheys.com> qp 28003 uid 509
>2008-01-27 13:36:28.576432500 starting delivery 106844: msg 232146 to
>local MYDOMAIN-hovgxnik at 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 at cedarville.edu> qp 28007 uid 509
>2008-01-27 13:36:28.674495500 starting delivery 106845: msg 232150 to
>local MYDOMAIN-gruppo at 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 at travelgolf.com> qp 28040 uid 509
>2008-01-27 13:36:33.963488500 starting delivery 106846: msg 232137 to
>local MYDOMAIN-mailman at 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 at hersheys.com> qp 28045 uid 509
>2008-01-27 13:36:43.645354500 starting delivery 106847: msg 232139 to
>local MYDOMAIN-hszdzlbsrkvx at 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 at mtco.com> qp 28081 uid 509
>2008-01-27 13:36:43.696390500 starting delivery 106848: msg 232149 to
>local MYDOMAIN-fs at 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 at 20minutos.es> qp 28123 uid 509
>2008-01-27 13:36:56.116975500 starting delivery 106849: msg 232139 to
>local MYDOMAIN-uiakjb at 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 at mtco.com> qp 28116 uid 509
>2008-01-27 13:36:56.158337500 starting delivery 106850: msg 232129 to
>local MYDOMAIN-ga at 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 at hq.com> qp 23956 uid 509
>2008-01-27 13:13:37.477036500 starting delivery 106595: msg 232140 to
>local MYDOMAIN-freeradius-devel-owotyv at 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 at MYDOMAIN> qp 23965 uid 509
>2008-01-27 13:13:37.555521500 starting delivery 106596: msg 231316 to
>local MYDOMAIN-mc at 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 at hersheys.com> qp 28145 uid 509
>2008-01-27 13:37:00.426136500 starting delivery 106851: msg 232130 to
>local MYDOMAIN-infod at 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 at creative-plane.com> qp 28149 uid 509
>2008-01-27 13:37:00.797468500 starting delivery 106852: msg 232139 to
>local MYDOMAIN-sebvgc at 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 at hersheys.com> qp 28165 uid 509
>2008-01-27 13:37:02.867282500 starting delivery 106853: msg 232130 to
>local MYDOMAIN-gmhu at 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 at prudentialdoss.com> qp 28161 uid 509
>2008-01-27 13:37:02.919415500 starting delivery 106854: msg 232128 to
>local MYDOMAIN-climmichiel at 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 at cedarville.edu> qp 28220 uid 509
>2008-01-27 13:37:18.024843500 starting delivery 106855: msg 232140 to
>local MYDOMAIN-gmhu at 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 at ter.com> qp 28225 uid 509
>2008-01-27 13:37:19.297540500 starting delivery 106857: msg 232144 to
>local MYDOMAIN-zvb-owner at 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 at fuse.net> qp 28223 uid 509
>2008-01-27 13:37:20.878151500 starting delivery 106858: msg 232141 to
>local MYDOMAIN-millsaimerisa at 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 at MYDOMAIN> qp 28246 uid 509
>2008-01-27 13:37:21.185407500 starting delivery 106859: msg 232128 to
>local MYDOMAIN-mailman-test at 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 at fuse.net> qp 28243 uid 509
>2008-01-27 13:37:21.308078500 starting delivery 106860: msg 232149 to
>local MYDOMAIN-mooresmtpesxbswr at 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 at cedarville.edu> qp 28285 uid 509
>2008-01-27 13:37:27.753766500 starting delivery 106861: msg 232139 to
>local MYDOMAIN-info at 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 at cedarville.edu> qp 28333 uid 509
>2008-01-27 13:37:35.387598500 starting delivery 106862: msg 232142 to
>local MYDOMAIN-infod at 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 at uol.com.br> qp 28351 uid 509
>2008-01-27 13:37:41.975110500 starting delivery 106863: msg 232142 to
>local MYDOMAIN-qif at 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 at fuse.net> qp 28362 uid 509
>2008-01-27 13:37:55.137142500 starting delivery 106864: msg 232129 to
>local MYDOMAIN-notizie at 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 at 20minutos.es> qp 28386 uid 509
>2008-01-27 13:37:55.355206500 starting delivery 106865: msg 232150 to
>local MYDOMAIN-uweia at 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 at travelgolf.com> qp 28383 uid 509
>2008-01-27 13:37:55.395926500 starting delivery 106866: msg 232149 to
>local MYDOMAIN-meggithaler at 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 at mtco.com> qp 28410 uid 509
>2008-01-27 13:37:56.491199500 starting delivery 106867: msg 231909 to
>local MYDOMAIN-fs at 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 at 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 at agosd.org> qp 23976 uid 509
>2008-01-27 13:13:38.863330500 starting delivery 106597: msg 231316 to
>local MYDOMAIN-uucp at 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 at hersheys.com> qp 28419 uid 509
>2008-01-27 13:38:00.891481500 starting delivery 106868: msg 232130 to
>local MYDOMAIN-jaquenettawiatt at 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 at mtco.com> qp 28425 uid 509
>2008-01-27 13:38:05.325911500 starting delivery 106869: msg 232130 to
>local MYDOMAIN-fs at 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 at cedarville.edu> qp 28443 uid 509
>2008-01-27 13:38:06.794904500 starting delivery 106870: msg 232138 to
>local MYDOMAIN-infodd at 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 at MYDOMAIN> qp 28437 uid 511
>2008-01-27 13:38:06.824979500 starting delivery 106871: msg 232149 to
>local MYDOMAIN-test at 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 at cedarville.edu> qp 28506 uid 509
>2008-01-27 13:38:21.806125500 starting delivery 106872: msg 232142 to
>local MYDOMAIN-jaquenettawiatt at 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 at uol.com.br> qp 28500 uid 509
>2008-01-27 13:38:21.883029500 starting delivery 106873: msg 232140 to
>local MYDOMAIN-catchallnn at 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 at 20minutos.es> qp 28533 uid 509
>2008-01-27 13:38:32.099926500 starting delivery 106874: msg 232130 to
>local MYDOMAIN-zvb-bounces at 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 at ter.com> qp 28539 uid 509
>2008-01-27 13:38:32.167114500 starting delivery 106875: msg 232141 to
>local MYDOMAIN-zvb-request at 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 at uol.com.br> qp 28536 uid 509
>2008-01-27 13:38:32.364072500 starting delivery 106876: msg 232144 to
>local MYDOMAIN-re at 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 at 20minutos.es> qp 28542 uid 509
>2008-01-27 13:38:32.408993500 starting delivery 106877: msg 232142 to
>local MYDOMAIN-sp-request at 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 at ter.com> qp 28591 uid 509
>2008-01-27 13:38:44.002411500 starting delivery 106878: msg 232141 to
>local MYDOMAIN-zvb-subscribe at 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 at fuse.net> qp 28631 uid 509
>2008-01-27 13:38:53.573159500 starting delivery 106879: msg 232141 to
>local MYDOMAIN-owotyv at 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 at uol.com.br> qp 28625 uid 509
>2008-01-27 13:38:53.629800500 starting delivery 106880: msg 232142 to
>local MYDOMAIN-catchallk at 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 at 20minutos.es> qp 28628 uid 509
>2008-01-27 13:38:53.678298500 starting delivery 106881: msg 232144 to
>local MYDOMAIN-sp-bounces at 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 at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan