[Mailman-Users] All messages discarded, no reason

[Mark Sapiro]

Milos Prudek wrote:
> 
> Some SpamAssassing processing follows. And then...
> 
> Nov  8 17:41:11 milos-desktop postfix/pickup[2357]: D2FC5CBA73: uid=500 
> from=<t-bounces at z.docestiny.cz>
> Nov  8 17:41:11 milos-desktop postfix/cleanup[3612]: D2FC5CBA73: 
> message-id=<200811081741.00552.prudek at bvx.cz>
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<prudek at bvx.cz>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, dsn=2.0.0, 
> status=sent (delivered via spamchk service)
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<member1 at example.com>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, 
> dsn=2.0.0, status=sent (delivered via spamchk service)
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<member2 at example.com>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, 
> dsn=2.0.0, status=sent (delivered via spamchk service)
> 
> The last three lines look like correct distribution by Mailman to the three 
> members via SpamAssassin... but none of the list members prudek at bvx.cz, 
> member1 at example.com, member2 at example.com receive any emails... and then....


So Mailman has done the correct thing. The question is why isn't Postfix
delivering the three messages to the three recipients?


> Nov  8 17:41:11 milos-desktop postfix/qmgr[19655]: 64731CBA97: removed
> Nov  8 17:41:11 milos-desktop postfix/qmgr[19655]: D2FC5CBA73: 
> from=<t-bounces at z.docestiny.cz>, size=2381, nrcpt=1 (queue active)
> Nov  8 17:41:11 milos-desktop spamd[8350]: prefork: child states: II
> Nov  8 17:41:12 milos-desktop postfix/pipe[3751]: D2FC5CBA73: 
> to=<t at z.docestiny.cz>, relay=mailman, delay=0.24, delays=0.01/0/0/0.23, 
> dsn=2.0.0, status=sent (delivered via mailman service)
> Nov  8 17:41:12 milos-desktop postfix/qmgr[19655]: D2FC5CBA73: removed
> 
> Is this suspicious? t-bounces at z.docestiny.cz is sending email to 
> t at z.docestiny.cz (the list itself).... is this a loop? What may be causing 
> it? I triple-checked that the list address t at z.docestiny.cz IS NOT among list 
> members...


I think this is not Mailman but some issue with postfix-to-mailman.py
that is relaying this message back to the list. If mailman were actually
sending a message to t at z.docestiny.cz, there would be an entry in
Mailman's smtp log, but the only entry is for the delivery to the 3 list
members which is accounted for elsewhere in the Postfix log. I.e., the
64731CBA97 queue entry is the delivery from Mailman to Postfix for 3
recipients. There is no entry in Mailman's smtp log to correspond to the
Postfix D2FC5CBA73 queue entry, so it didn't come from Mailman.


> There is NO MORE traffic from mailman in /var/log/mail.info. And precisely at 
> the same time, 17:41:12, the following appears in /var/log/mailman/vette:
> Nov 08 17:41:12 2008 (17697) Message discarded, msgid: 
> <200811081741.00552.prudek at bvx.cz>


Because Mailman has received the post back to the list, and it knows
this is a loop because of the "X-BeenThere: t at z.docestiny.cz" header it
put in the outgoing posts, so it discards this one.

And Milos Prudek wrote:
> I looked again what happened at 17:41:11... and I realized something 
> important.
> 
> Nov  8 17:41:11 milos-desktop spamd[1840]: spamd: result: . 0 - 
> scantime=4.4,size=2259,user=filter,uid=500,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=37
> 454,mid=<200811081741.00552.prudek at bvx.cz>,autolearn=ham
> Nov  8 17:41:11 milos-desktop postfix/pickup[2357]: D2FC5CBA73: uid=500 
> from=<t-bounces at z.docestiny.cz>
> Nov  8 17:41:11 milos-desktop postfix/cleanup[3612]: D2FC5CBA73: 
> message-id=<200811081741.00552.prudek at bvx.cz>
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<prudek at bvx.cz>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, dsn=2.0.0, 
> status=sent (delivered via spamchk service)
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<member1 at example.com>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, 
> dsn=2.0.0, status=sent (delivered via spamchk service)
> Nov  8 17:41:11 milos-desktop postfix/pipe[3613]: 64731CBA97: 
> to=<member2 at example.com>, relay=spamchk, delay=4.5, delays=0.01/0/0/4.4, 
> dsn=2.0.0, status=sent (delivered via spamchk service)
> 
> 
> This mail 64731CBA97 is delivered from spamassassin as clean... and then 
> something similar to this line OUGHT to appear:
> 
> ... postfix/smtp[7307]: .... to=<prudek at bvx.cz>, 
> relay=mail.rtv5.cz[212.96.165.43]:25
> 
> Notice the relay=mail.rtv5.cz[212.96.165.43]:25, this is the mailserver for 
> prudek at bvx.cz. But this line DOES NOT appear. Neither do the other two lines 
> for member1 at example.com and member2 at example.com (domain example.com is not 
> the real one). So Postfix is NEVER instructed to deliver the emails to their 
> real external destinations.
> 
> Instead some email is sent from t-bounces at z.docestiny.cz to the mailing list 
> itself (t at z.docestiny.cz):


This is almost certainly a problem with mailman-to-postfix.py or the way
you have hooked it in to Postfix.

Or perhaps there is an alias somewhere in postfix that is doing this.

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