Re: Mail Data termination

On 2011-08-21 12:07:06 +0200, Peter J. Holzer wrote:
> After a RSET it's a bit different: Only 76% send a QUIT after 0 or 1
> seconds, 10% after 5 seconds and there seem to be small peaks of
> decreasing size every 20 seconds.
Actually, the 20 seconds peak is probably due to the interaction between
sendmails connection caching, callback sender verification and a
misconfigured sendmail. 

I found this in the logfiles (domain names and local parts anonymized):

MX2 2011-08-24T12:02:29+0200  220 mx2.example.com ESMTP qpsmtpd 0.84 ready; 
send us your mail, but not your spam.
MX2 2011-08-24T12:02:29+0200  dispatching EHLO delphi.example.com
MX2 2011-08-24T12:02:29+0200  250 STARTTLS
MX2 2011-08-24T12:02:29+0200  dispatching STARTTLS
MX2 2011-08-24T12:02:29+0200  220 Go ahead with TLS
MX2 2011-08-24T12:02:29+0200  dispatching EHLO delphi.example.com
MX2 2011-08-24T12:02:29+0200  250 SIZE 20971520
MX2 2011-08-24T12:02:29+0200  dispatching MAIL 
From:<S1(_at_)delphi(_dot_)example(_dot_)com> SIZE=60373
MX2 2011-08-24T12:02:29+0200  250 <S1(_at_)delphi(_dot_)example(_dot_)com>, 
sender OK - how exciting to get mail from you!
MX2 2011-08-24T12:02:29+0200  dispatching RCPT To:<R(_at_)example(_dot_)com>
MX2 2011-08-24T12:02:49+0200  450 <S1(_at_)delphi(_dot_)example(_dot_)com> 
cannot be verified (server unreachable?) (#4.1.8)
MX2 2011-08-24T12:02:49+0200  dispatching DATA
MX2 2011-08-24T12:02:49+0200  503 RCPT first
MX2 2011-08-24T12:02:49+0200  dispatching RSET
MX2 2011-08-24T12:02:49+0200  250 OK

MX1 2011-08-24T12:02:50+0200  220 mx1.example.com ESMTP qpsmtpd 0.40 ready; 
send us your mail, but not your spam. [LOGINFO]
MX1 2011-08-24T12:02:50+0200  dispatching EHLO delphi.example.com [LOGINFO]
MX1 2011-08-24T12:02:50+0200  250 SIZE 20971520 [LOGINFO]
MX1 2011-08-24T12:02:50+0200  dispatching MAIL 
From:<S1(_at_)delphi(_dot_)example(_dot_)com> SIZE=60373 [LOGINFO]
MX1 2011-08-24T12:02:50+0200  250 <S1(_at_)delphi(_dot_)example(_dot_)com>, 
sender OK - how exciting to get mail from you! [LOGINFO]
MX1 2011-08-24T12:02:50+0200  dispatching RCPT To:<R(_at_)example(_dot_)com> 
[LOGINFO]
MX1 2011-08-24T12:03:12+0200  450 <S1(_at_)delphi(_dot_)example(_dot_)com> 
cannot be verified (server unreachable?) (#4.1.8) [LOGINFO]
MX1 2011-08-24T12:03:12+0200  dispatching DATA [LOGINFO]
MX1 2011-08-24T12:03:12+0200  503 RCPT first [LOGINFO]
MX1 2011-08-24T12:03:12+0200  dispatching RSET [LOGINFO]

MX2 2011-08-24T12:03:12+0200  dispatching RSET
MX2 2011-08-24T12:03:12+0200  250 OK
MX2 2011-08-24T12:03:12+0200  dispatching MAIL 
From:<S2(_at_)delphi(_dot_)example(_dot_)com> SIZE=4589
[...]

MX1 2011-08-24T12:03:12+0200  250 OK [LOGINFO]
MX1 2011-08-24T12:03:32+0200  dispatching RSET [LOGINFO]
MX1 2011-08-24T12:03:32+0200  250 OK [LOGINFO]
MX1 2011-08-24T12:03:32+0200  dispatching MAIL 
From:<S2(_at_)delphi(_dot_)example(_dot_)com> SIZE=4589 [LOGINFO]
[...]

After your explanation about sendmail's queueing behaviour it is clear
what happens:

Sendmail on delphi is misconfigured to attach the full hostname instead
of only domainname to the username to create mail addresses. Since
addresses like this aren't supposed to exist, port 25 of delphi is
unreachable and there is no MX record either. The recipient R has CBV
enabled.

There are a few mails in the queue, so sendmail begins by connecting to
the primary MX (MX2 in this case). The MX returns (after 20 seconds,
because CBV can't connect to delphi and times out) a temporary error. So
sendmail sends a RSET and leaves to connection open.

There is a secondary MX (confusingly called MX1), so it connects to
that. Again, RCPT fails after about 20 seconds. So it sends a RSET and
leaves the connection open. The mail is currently undeliverable and goes
back into the queue.

The next mail should again be delivered to MX2, and sendmail already has
a connection. So it sends a RSET and tries the delivery, which again
fails after a timeout of 20 seconds and the same game starts with MX1
...

So during the entire queue run the two connections stay open and
delivery switches from one MX to the other every 20 seconds - not
because the client has a 20 second limit somewhere but because the
server takes 20 seconds to reject each message.

        hp

-- 
   _  | Peter J. Holzer    | Web 2.0 könnte man also auch übersetzen als
|_|_) | Sysadmin WSR       | "Netz der kleinen Geister".
| |   | hjp(_at_)hjp(_dot_)at         | 
__/   | http://www.hjp.at/ |  -- Oliver Cromm in desd

signature.asc
Description: Digital signature