[Mailman-Users] Email arrives after a long delay

[BERTHOLD Jean]

Hello Brad,

First, many thanks for your long, useful and complete response (whaou...)
I'm not a email specialist but when I seen the message:

> [ID 801593 mail.warning] kB6BcXf1016562: collect: premature EOM:
>  unexpected close )

I Think you are true, there is a problem on our Exchange server...

The second problem is now to convince our Exchange administrator... 
But I think your response will give them a good idea about the problem... :-)

Thanks again for your help and have a nice week-end

Jean


-----Message d'origine-----
De : Brad Knowles [mailto:brad at shub-internet.org] 
Envoyé : jeudi, 7. décembre 2006 17:52
À : BERTHOLD Jean; mailman-users at python.org
Cc : BERTHOLD Jean
Objet : Re: [Mailman-Users] Email arrives after a long delay

At 9:34 AM +0100 12/7/06, BERTHOLD Jean wrote:

>  I have a configuration problem.
>  All my lists works correctly excepted that the emails arrives with
>  a delay of 10 minutes on the mailman server.

In the world of Internet e-mail, ten minutes is nothing.  In fact, 
that's pretty damn fast.

>  Dec 06 12:49:49 2006 (4144) post to fpbg-dtr from
>  jean.berthold at eosholding.ch, size=1880,
>  message-id=<C02FA870DECC5F4A933E05E3A37F441720A630 at SWEXCH.sila.local,
>  success
>
>  Dec 06 13:08:18 2006 (4144) post to fpbg-dtr from
>  jean.berthold at eosholding.ch, size=1875,
>  message-id=<C02FA870DECC5F4A933E05E3A37F441720A634 at SWEXCH.sila.local,
>  success

Okay, so here we have two different messages coming into Mailman from 
you.  So that we can make it easy to identify them, let's call them 
"630" and "634", which comes from the last three digits of the 
Message-ID field before the at-symbol.

>  Dec 06 12:49:49 2006 (4144)
>  <C02FA870DECC5F4A933E05E3A37F441720A630 at SWEXCH.sila.local> smtp to
>  fpbg-dtr for 1 recips, completed in 0.318 seconds

Okay, so we see that 630 came into Mailman from the MTA at 12:49:49 
and went back out to the MTA in less than a second.  That's good.

>  Dec  6 12:48:46 bahamas sendmail[16562]: [ID 801593 mail.warning]
>  kB6BcXf1016562: collect: premature EOM: unexpected close
>  Dec  6 12:48:46 bahamas sendmail[16562]: [ID 801593 mail.notice]
>  kB6BcXf1016562: collect: unexpected close on connection from
>  swexch01lpro.sila.local, sender=<CheckTpsAckCnfMailTask at sila.local
>  Dec  6 12:48:46 bahamas sendmail[16562]: [ID 801593 mail.info]
>  kB6BcXf1016562: from=<CheckTpsAckCnfMailTask at sila.local>, size=1217,
>  class=0, nrcpts=1, proto=ESMTP, daemon=MTA-v4,
>  relay=swexch01lpro.sila.local [172.25.2.76]

These are signs that your Exchange server is screwing up the SMTP protocol.

>  Dec  6 12:49:46 bahamas sendmail[16721]: [ID 801593 mail.info]
>  kB6BnkRQ016721: from=<Jean.BERTHOLD at eosholding.ch>, size=1315,
>  class=0, nrcpts=1,
>  msgid=<C02FA870DECC5F4A933E05E3A37F441720A630 at SWEXCH.sila.local>,
>  proto=ESMTP, daemon=MTA-v4, relay=swexch01lpro.sila.local [172.25.2.76]

Okay, so here is 630 coming into the system from Exchange.  Note that 
the sendmail queue-id in this case is kB6BnkRQ016721.  This is how we 
tie other log entries together back to this same message -- by the 
sendmail queue-id.

>  Dec  6 12:49:47 bahamas sendmail[16722]: [ID 801593 mail.info]
>  kB6BnkRQ016721: to="|/usr/local/mailman/mail/mailman post fpbg-dtr",
>  ctladdr=<fpbg-dtr at bahamas.sila.local> (1/0), delay=00:00:01,
>  xdelay=00:00:01, mailer=prog, pri=31536, dsn=2.0.0, stat=Sent

Okay, so here is sendmail saying that it has now sent 630 to Mailman. 
We know that it's what we're calling message 630 because we see the 
same sendmail queue-id, namely kB6BnkRQ016721.

Note that Mailman says that it finished getting this message about 
two seconds later (at 12:49:49), and that Mailman then sends that 
message back to the MTA in less than a second (still 12:49:49).

>  Dec  6 12:49:49 bahamas sendmail[16725]: [ID 801593 mail.info]
>  kB6Bnnn6016725: from=<fpbg-dtr-bounces at bahamas.sila.local>,
>  size=1880, class=-30, nrcpts=1,
>  msgid=<C02FA870DECC5F4A933E05E3A37F441720A630 at SWEXCH.sila.local>,
>  proto=ESMTP, daemon=MTA-v4, relay=localhost [127.0.0.1]

Okay, so here is 630 having come back out of Mailman, and going into 
the MTA to be delivered to the recipient.  Note that the sendmail 
queue-id is now kB6Bnnn6016725, because as far as sendmail is 
concerned this is a totally different message.  Sendmail doesn't know 
that the content is exactly the same, and that what has happened is 
that the message has come through sendmail, into Mailman, and then 
back out again.  Sendmail sees the inbound and outbound legs as being 
two totally separate messages.

Any further delay is totally and completely out of the hands of 
Mailman.  There is absolutely nothing that we can do to help.

>  Dec  6 13:08:20 bahamas sendmail[17179]: [ID 801593 mail.info]
>  kB6C8Kge017177: to=<jean.berthold at eosholding.ch>, delay=00:00:00,
>  xdelay=00:00:00, mailer=esmtp, pri=176820, relay=mta0.eosholding.ch.
>  [193.8.222.23], dsn=2.0.0, stat=Sent (Ok: queued as 360A520C03B)

Dunno what message this is, but it doesn't look like it's 630.  Note 
that the sendmail queue-id is different -- Message 630 came in with 
queue-id kB6Bnnn6016725, and this has queue-id kB6C8Kge017177.  So, 
it looks like there are some log entries missing.

>  Dec  6 13:08:21 bahamas sendmail[17180]: [ID 801593 mail.info]
>  kB6C8LhF017180: from=<fpbg-dct-bounces at bahamas.sila.local>, size=2777,
>  class=-30, nrcpts=1,
>  msgid=<-227556877.1165399238285.JavaMail.javamailuser at localhost>,
>  proto=ESMTP, daemon=MTA-v4, relay=localhost [127.0.0.1]
>  Dec  6 13:08:21 bahamas sendmail[17182]: [ID 801593 mail.info]
>  kB6C8LhF017180: to=<jean.berthold at eosholding.ch>, delay=00:00:00,
>  xdelay=00:00:00, mailer=esmtp, pri=176777, relay=mta0.eosholding.ch.
>  [193.8.222.23], dsn=2.0.0, stat=Sent (Ok: queued as 5E95B20C053)

Okay, so this is a totally different message.  Different Message-id, 
different sendmail queue-id.  Apparently completely unrelated.

>  As you can see, there is some warning with sendmail ( [ID
>  801593 mail.warning] kB6BcXf1016562: collect: premature EOM:
>  unexpected close )

Yup.  That's a sign that your Exchange server is screwing up the SMTP 
dialog to sendmail.  Get your Exchange admin to fix the Exchange 
server.

>  Mailman is 2.1.8 release and apache is running on release 2.

Version 2.1.8 had security issues.  Upgrade to 2.1.9, or risk having 
your server get compromised by an attacker.

>  Is there a special sendmail configuration to apply for avoiding 
>this problem ?

Nope.  From what I can see, this delay is completely and totally out 
of the hands of either Mailman or sendmail.  Looks to me like the 
delay is somewhere else entirely.

-- 
Brad Knowles, <brad at shub-internet.org>

Trend Micro has announced that they will cancel the stop.mail-abuse.org
mail forwarding service as of 15 November 2006.  If you have an old
e-mail account for me at this domain, please make sure you correct that
with the current address.