From: Victor Duchovni (Victor.DuchovniMorganStanley.com)
Date: Fri Dec 02 2005 - 02:00:45 CST

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Fri, Dec 02, 2005 at 08:02:45AM +0100, Christian Theune wrote:

> Damn. That log file was too large. Anyway, I posted an excerpt here:
>
> http://amy.gocept.com/~ctheune/postfix.log
>

Super!

    14:59:32 < 220 uter LMTP Cyrus v2.2.12-Gentoo ready
    14:59:32 > LHLO uter.whq.gocept.com
    14:59:32 < 250-uter
    14:59:32 < 250-8BITMIME
    14:59:32 < 250-ENHANCEDSTATUSCODES
    14:59:32 < 250-PIPELINING
    14:59:32 < 250-SIZE
    14:59:32 < 250-AUTH EXTERNAL
    14:59:32 < 250 IGNOREQUOTA
    14:59:32 > MAIL FROM:<rootmail.pressetext.com> SIZE=4594
    14:59:32 > RCPT TO:<zagy+ptdimap.whq.gocept.com>
    14:59:32 > DATA
    14:59:32 < 250 2.1.0 ok
    14:59:32 < 250 2.1.5 ok
    14:59:32 < 354 go ahead
    14:59:32 > .
    14:59:32 < 250 2.1.5 Ok

So far so good.

    15:00:02 > RSET
    15:00:02 < 250 2.0.0 ok
    15:00:02 > MAIL FROM:<amaviswhq.gocept.com> SIZE=570
    15:00:02 > RCPT TO:<ctheuneimap.whq.gocept.com>
    15:00:02 > DATA
    15:00:02 < 250 2.1.0 ok
    15:00:02 < 250 2.1.5 ok
    15:00:02 < 354 go ahead
    15:00:02 > .
    15:00:02 < 250 2.1.5 Ok

This one also.

    15:00:02 > RSET
    15:00:02 < 250 2.0.0 ok
    15:00:02 > MAIL FROM:<ctgocept.com> SIZE=4064
    15:00:02 > RCPT TO:<ctheuneimap.whq.gocept.com>
    15:00:02 > DATA
    15:00:02 < 250 2.1.0 ok
    15:00:02 < 250 2.1.5 ok
    15:00:02 < 354 go ahead
    15:00:02 > .
    15:00:02 < 250 2.1.5 Ok

And this.

    15:00:08 > RSET
    15:00:08 < 250 2.0.0 ok
    15:00:08 > MAIL FROM:<niloamy.gocept.com> SIZE=1274
    15:00:08 > RCPT TO:<niloimap.whq.gocept.com>
    15:00:08 > DATA
    15:00:08 < 250 2.1.0 ok
    15:00:08 < 250 2.1.5 ok
    15:00:08 < 354 go ahead
    15:00:08 > .
    15:00:08 < 250 2.1.5 Ok

And this is fine too! But from below all hell breaks loose:

    15:01:10 > RSET
    15:01:10 < 500 5.5.2 Syntax error

WTF? There is no reason to complain about this RSET. It looks
as though the LMTP server saw something sent before RSET, even
though Postfix did not send anything between "." and RSET.

Only two possibilities:

    1. The LMTP server saw end-of-body prematurely and responded to
       the last three lines of the body as invalid SMTP commands.

    2. There is a bug in the I/O chain from Postfix to the LMTP
       server (Postfix buffering, kernel socket I/O or LMTP server
       buffering) that caused double writes or double reads of
       previous data.

It would be very interesting to see the last 5 lines of body
content from the above message from <niloamy.gocept.com> SIZE=1274 to
<niloimap.whq.gocept.com>. How big is the received message (counting line
breaks as two bytes for <CRLF> and not counting any Received header added
by the LMTP server). Does the message appear to end abruptly? Is there
a problem with the "." stuffing (transparency) in the LMTP server or
the Postfix LMTP client?

    15:01:10 > MAIL FROM:<backcommunity.sport1.de> SIZE=13831
    15:01:10 < 500 5.5.2 Syntax error
    15:01:10 > RSET
    15:01:10 < 500 5.5.2 Syntax error

Two more invalid commands Postfix did not send are being responded to out
of sequence. This transaction fails and Postfix aborts it with an RSET,
which is again rejected, though we are well out of sync and the game
is lost. So there are three phantom invalid SMTP commands before RSET.

    15:02:41 > RSET
    15:02:41 < 250 2.0.0 ok

A false glimmer of hope, but this 2.0.0 is really a response for the
first of the two RSET commands above.

    15:02:41 > MAIL FROM:<plone-users-adminlists.sourceforge.net> SIZE=6620
    15:02:41 > RCPT TO:<ctheuneimap.whq.gocept.com>
    15:02:41 > RCPT TO:<niloimap.whq.gocept.com>
    15:02:41 > DATA
    15:02:41 < 250 2.1.0 ok

This is for the previously rejected (500 5.5.2) MAIL FROM.

    15:02:41 < 250 2.0.0 ok

This is for the RSET that followed it.

    15:02:41 < 250 2.0.0 ok

This is for the RSET that started this delivery.

    15:02:41 < 250 2.1.0 ok

This is for the current "MAIL FROM:". The LMTP server saw 3 extra
commands that Postfix did not send. From here on the game is lost.

    15:02:41 > RSET
    15:02:41 < 250 2.1.5 ok
    15:03:38 > RSET
    15:03:38 < 250 2.1.5 ok
    15:03:38 > MAIL FROM:<zope-bounceszope.org> SIZE=4333
    15:03:38 < 354 go ahead
    15:03:38 > RSET

There is really no point in Postfix even trying...

--
        Viktor.

Disclaimer: off-list followups get on-list replies or get ignored.
Please do not ignore the "Reply-To" header.

To unsubscribe from the postfix-users list, visit
http://www.postfix.org/lists.html or click the link below:
<mailto:majordomopostfix.org?body=unsubscribe%20postfix-users>

If my response solves your problem, the best way to thank me is to not
send an "it worked, thanks" follow-up. If you must respond, please put
"It worked, thanks" in the "Subject" so I can delete these quickly.

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]