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 [EMAIL PROTECTED], >size=1236, message-id=<[EMAIL PROTECTED]>, 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) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 7.613 seconds >Jan 27 13:22:04 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 1.817 seconds >Jan 27 13:24:05 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 1.516 seconds >Jan 27 13:26:06 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 3.636 seconds >Jan 27 13:28:28 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 9.563 seconds >Jan 27 13:29:26 2008 (2154) <[EMAIL PROTECTED]> >smtp to zvb for 1 recips, completed in 9.095 seconds >Jan 27 13:30:59 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 24.989 seconds >Jan 27 13:33:01 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 42.552 seconds >Jan 27 13:34:57 2008 (2154) <[EMAIL PROTECTED]> smtp >to test for 1 recips, completed in 55.860 seconds >Jan 27 13:37:21 2008 (2154) <[EMAIL PROTECTED]> 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 ><[EMAIL PROTECTED]> qp 27937 uid 511 >2008-01-27 13:36:13.978364500 starting delivery 106841: msg 232139 to >local [EMAIL PROTECTED] 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 ><[EMAIL PROTECTED]> qp 27992 uid 509 >2008-01-27 13:36:28.467668500 starting delivery 106842: msg 232139 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 27998 uid 509 >2008-01-27 13:36:28.520522500 starting delivery 106843: msg 232141 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28003 uid 509 >2008-01-27 13:36:28.576432500 starting delivery 106844: msg 232146 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28007 uid 509 >2008-01-27 13:36:28.674495500 starting delivery 106845: msg 232150 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28040 uid 509 >2008-01-27 13:36:33.963488500 starting delivery 106846: msg 232137 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28045 uid 509 >2008-01-27 13:36:43.645354500 starting delivery 106847: msg 232139 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28081 uid 509 >2008-01-27 13:36:43.696390500 starting delivery 106848: msg 232149 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28123 uid 509 >2008-01-27 13:36:56.116975500 starting delivery 106849: msg 232139 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28116 uid 509 >2008-01-27 13:36:56.158337500 starting delivery 106850: msg 232129 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 23956 uid 509 >2008-01-27 13:13:37.477036500 starting delivery 106595: msg 232140 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 23965 uid 509 >2008-01-27 13:13:37.555521500 starting delivery 106596: msg 231316 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28145 uid 509 >2008-01-27 13:37:00.426136500 starting delivery 106851: msg 232130 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28149 uid 509 >2008-01-27 13:37:00.797468500 starting delivery 106852: msg 232139 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28165 uid 509 >2008-01-27 13:37:02.867282500 starting delivery 106853: msg 232130 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28161 uid 509 >2008-01-27 13:37:02.919415500 starting delivery 106854: msg 232128 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28220 uid 509 >2008-01-27 13:37:18.024843500 starting delivery 106855: msg 232140 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28225 uid 509 >2008-01-27 13:37:19.297540500 starting delivery 106857: msg 232144 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28223 uid 509 >2008-01-27 13:37:20.878151500 starting delivery 106858: msg 232141 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28246 uid 509 >2008-01-27 13:37:21.185407500 starting delivery 106859: msg 232128 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28243 uid 509 >2008-01-27 13:37:21.308078500 starting delivery 106860: msg 232149 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28285 uid 509 >2008-01-27 13:37:27.753766500 starting delivery 106861: msg 232139 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28333 uid 509 >2008-01-27 13:37:35.387598500 starting delivery 106862: msg 232142 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28351 uid 509 >2008-01-27 13:37:41.975110500 starting delivery 106863: msg 232142 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28362 uid 509 >2008-01-27 13:37:55.137142500 starting delivery 106864: msg 232129 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28386 uid 509 >2008-01-27 13:37:55.355206500 starting delivery 106865: msg 232150 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28383 uid 509 >2008-01-27 13:37:55.395926500 starting delivery 106866: msg 232149 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28410 uid 509 >2008-01-27 13:37:56.491199500 starting delivery 106867: msg 231909 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> 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 ><[EMAIL PROTECTED]> qp 23976 uid 509 >2008-01-27 13:13:38.863330500 starting delivery 106597: msg 231316 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28419 uid 509 >2008-01-27 13:38:00.891481500 starting delivery 106868: msg 232130 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28425 uid 509 >2008-01-27 13:38:05.325911500 starting delivery 106869: msg 232130 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28443 uid 509 >2008-01-27 13:38:06.794904500 starting delivery 106870: msg 232138 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28437 uid 511 >2008-01-27 13:38:06.824979500 starting delivery 106871: msg 232149 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28506 uid 509 >2008-01-27 13:38:21.806125500 starting delivery 106872: msg 232142 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28500 uid 509 >2008-01-27 13:38:21.883029500 starting delivery 106873: msg 232140 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28533 uid 509 >2008-01-27 13:38:32.099926500 starting delivery 106874: msg 232130 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28539 uid 509 >2008-01-27 13:38:32.167114500 starting delivery 106875: msg 232141 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28536 uid 509 >2008-01-27 13:38:32.364072500 starting delivery 106876: msg 232144 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28542 uid 509 >2008-01-27 13:38:32.408993500 starting delivery 106877: msg 232142 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28591 uid 509 >2008-01-27 13:38:44.002411500 starting delivery 106878: msg 232141 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28631 uid 509 >2008-01-27 13:38:53.573159500 starting delivery 106879: msg 232141 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28625 uid 509 >2008-01-27 13:38:53.629800500 starting delivery 106880: msg 232142 to >local [EMAIL PROTECTED] >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 ><[EMAIL PROTECTED]> qp 28628 uid 509 >2008-01-27 13:38:53.678298500 starting delivery 106881: msg 232144 to >local [EMAIL PROTECTED] >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 <[EMAIL PROTECTED]> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan ------------------------------------------------------ Mailman-Users mailing list [email protected] http://mail.python.org/mailman/listinfo/mailman-users Mailman FAQ: http://www.python.org/cgi-bin/faqw-mm.py Searchable Archives: http://www.mail-archive.com/mailman-users%40python.org/ Unsubscribe: http://mail.python.org/mailman/options/mailman-users/archive%40jab.org Security Policy: http://www.python.org/cgi-bin/faqw-mm.py?req=show&file=faq01.027.htp
