Loading ...
Sorry, an error occurred while loading the content.
 

Re: Weird bounces with Postfix, LMTP and Cyrus

Expand Messages
  • Christian Theune
    ... Unfortunately gentoo didn t have 2.1.5 available, so I just made the switch to 2.2.5. ... That was just a guess. In my case the LMTPD runs on the same
    Message 1 of 17 , Dec 1, 2005
      On 11/30/05, Victor Duchovni <Victor.Duchovni@...> wrote:
      > I think that 2.1.5 already had the fix in place, though of course 2.2.5
      > is good release with many significant improvements.

      Unfortunately gentoo didn't have 2.1.5 available, so I just made the
      switch to 2.2.5.
      >
      > If Cyrus is LMTPD is running on another machine, there may be a broken
      > firewall between your Postfix server and the LMTP client. Otherwise the
      > out-of-sync sessions don't make much sense.

      That was just a guess. In my case the LMTPD runs on the same server.
      Unfortunately even when turning preforking off, I still get the
      bounces with codes 2.0.0, 354 and 5.5.2 ...

      I think I need more log output here ... I'll try to increase output of
      postfix and cyrus a bit ...

      > While there are no known bugs in the LMTP client or reason to expect that
      > there are new bugs to be found its session re-use code, session re-use
      > is tested much more thoroughly in the new SMTP client. Hopefully one
      > of these days the LMTP client will be phased out and replaced by minor
      > ehhancements to the SMTP client (say LHLO instead of EHLO and process
      > multiple responses to ".").

      Hmm. Ok. I'm not so informed to know about a probable replacement of
      LMTP with SMTP ...

      Christian
    • Christian Theune
      Ok, I increased the log level and here is what I got for one of the error messages: Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: from
      Message 2 of 17 , Dec 1, 2005
        Ok, I increased the log level and here is what I got for one of the
        error messages:

        Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: from
        zope-dev-bounces@...
        Dec 1 13:00:41 uter postfix/lmtp[4407]: >
        /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
        Dec 1 13:00:41 uter postfix/lmtp[4407]: <
        /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error
        Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: reusing
        (count 3) session with: /var/imap/socket/lmtp
        Dec 1 13:00:41 uter postfix/lmtp[4407]: >
        /var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
        FROM:<zope-dev-bounces@...> SIZE=4246
        Dec 1 13:00:41 uter postfix/lmtp[4407]: <
        /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error

        I remember having found a posting somewhere that said, cyrus complains
        about the SIZE=... parameter in the MAIL FROM ... I thought that was
        solved already ...
      • Wietse Venema
        Christian Theune: [ Charset ISO-8859-1 unsupported, converting... ] ... Cyrus is screwed up. Postfix sends a valid RESET command. ... Cyrus is screwed up. Same
        Message 3 of 17 , Dec 1, 2005
          Christian Theune:
          [ Charset ISO-8859-1 unsupported, converting... ]
          > Ok, I increased the log level and here is what I got for one of the
          > error messages:
          >
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: from
          > zope-dev-bounces@...
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: >
          > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: <
          > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: reusing

          Cyrus is screwed up. Postfix sends a valid RESET command.

          > (count 3) session with: /var/imap/socket/lmtp
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: >
          > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
          > FROM:<zope-dev-bounces@...> SIZE=4246
          > Dec 1 13:00:41 uter postfix/lmtp[4407]: <
          > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error

          Cyrus is screwed up. Same reply as RSET.

          If Cyrus mis-handles something as simple as RSET, then all bets
          are off with more complex commands.

          You can turn off connection reuse with "lmtp_cache_connection = no".

          Wietse

          > I remember having found a posting somewhere that said, cyrus complains
          > about the SIZE=... parameter in the MAIL FROM ... I thought that was
          > solved already ...
          >
          >
        • Wietse Venema
          ... Surprise: the LMTP client reuses the session after 5xx error reply. The Postfix SMTP client would never do that. You can work around this with
          Message 4 of 17 , Dec 1, 2005
            Wietse Venema:
            > Christian Theune:
            > > Ok, I increased the log level and here is what I got for one of the
            > > error messages:
            > >
            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: from
            > > zope-dev-bounces@...
            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: >
            > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: <
            > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error
            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: reusing
            >
            > Cyrus is screwed up. Postfix sends a valid RESET command.
            >
            > > (count 3) session with: /var/imap/socket/lmtp

            Surprise: the LMTP client reuses the session after 5xx error reply.
            The Postfix SMTP client would never do that.

            You can work around this with lmtp_cache_connection=no.

            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: >
            > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
            > > FROM:<zope-dev-bounces@...> SIZE=4246
            > > Dec 1 13:00:41 uter postfix/lmtp[4407]: <
            > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error
            >
            > Cyrus is screwed up. Same reply as RSET.

            Now, what may be happening here is that server and client have
            somehow gotten out of step.

            For example (I am not saying that this is the cause!), if Cyrus
            "detects" end-of-data too early it will spit out a gazillion "500
            5.5.2 Syntax error" responses for every line of email content that
            follows. Postfix won't flush the input buffers, and will read
            these replies as if they are replies to commands sent after the
            real end-of-data.

            The 2.3 Postfix has a "purge" primitive for streams that discards
            whatever is buffered in Postfix itself. This could be used to clear
            the input buffer before sending RSET. However, this primitive does
            not discard data that's still buffered in the kernel, and would
            have to be extended to handle that.

            But all this is academic. The LMTP client should not reuse the
            session after a 5XX reply. Worse it's not even my own bug.

            Wietse
          • Wietse Venema
            ... With the patch below, the Postfix LMTP client will not reuse a session after the RSET command gets a negative reply. There are versions for Postfix 2.2 and
            Message 5 of 17 , Dec 1, 2005
              Wietse Venema:
              > Wietse Venema:
              > > Christian Theune:
              > > > Ok, I increased the log level and here is what I got for one of the
              > > > error messages:
              > > >
              > > > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: from
              > > > zope-dev-bounces@...
              > > > Dec 1 13:00:41 uter postfix/lmtp[4407]: >
              > > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
              > > > Dec 1 13:00:41 uter postfix/lmtp[4407]: <
              > > > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 500 5.5.2 Syntax error
              > > > Dec 1 13:00:41 uter postfix/lmtp[4407]: deliver_message: reusing
              > >
              > > Cyrus is screwed up. Postfix sends a valid RESET command.
              > >
              > > > (count 3) session with: /var/imap/socket/lmtp
              >
              > Surprise: the LMTP client reuses the session after 5xx error reply.
              > The Postfix SMTP client would never do that.
              >
              > You can work around this with lmtp_cache_connection=no.

              With the patch below, the Postfix LMTP client will not reuse
              a session after the RSET command gets a negative reply.
              There are versions for Postfix 2.2 and 2.3.

              It would still be interesting to learn if the delivery right before
              the above logfile fragment went well or not.

              Wietse
            • Christian Theune
              Ok. I think I was able to follow your excellent explanation. I ll switch off the connection re-use and cross my fingers for now... I hope the other bounces I
              Message 6 of 17 , Dec 1, 2005
                Ok. I think I was able to follow your excellent explanation. I'll
                switch off the connection re-use and cross my fingers for now... I
                hope the other bounces I saw have the same cause...

                Thanks,
                Christian
              • Wietse Venema
                ... It would still be worthwhile to find out if the last delivery was OK by the process with the failed RSET. Wietse
                Message 7 of 17 , Dec 1, 2005
                  Christian Theune:
                  > Ok. I think I was able to follow your excellent explanation. I'll
                  > switch off the connection re-use and cross my fingers for now... I
                  > hope the other bounces I saw have the same cause...

                  It would still be worthwhile to find out if the last
                  delivery was OK by the process with the failed RSET.

                  Wietse
                • Christian Theune
                  Hmm. Ok, I ve taken a bit more log data that might help you: This is a first mail that bounces: Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: from
                  Message 8 of 17 , Dec 1, 2005
                    Hmm. Ok, I've taken a bit more log data that might help you:

                    This is a first mail that bounces:

                    Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: from
                    plone-users-admin@...
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: reusing
                    (count 5) session with: /var/imap/socket/lmtp
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
                    FROM:<plone-users-admin@...> SIZE=6620
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
                    TO:<ctheune@...>
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
                    TO:<nilo@...>
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: DATA
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: connect to subsystem private/bounce
                    Dec 1 15:02:41 uter postfix/bounce[11366]: connection established
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr nrequest = 0
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr flags = 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: bounce socket: wanted
                    attribute: nrequest
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr queue_id = 2BAE72974
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr original_recipient
                    = ct@...
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr recipient =
                    ctheune@...
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr offset = 355
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 5.0.0
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr action = failed
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason = host
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
                    reply to DATA command)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
                    wanted attribute: status

                    The next mail is related to that, it looks like the bounce
                    notification and seems to get through to me (as I get those bounces):

                    Dec 1 15:02:41 uter postfix/bounce[11366]: bounce_append_proto:
                    flags=0x0 service=bounce id=2BAE72974 org_to=ct@...
                    to=ctheune@... off=355 stat=5.0.0 act=failed why=host
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
                    reply to DATA command)
                    Dec 1 15:02:41 uter postfix/bounce[11366]: send attr status = 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 1
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: status
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute value: 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: connection closed
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
                    wanted attribute: (list terminator)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: (end)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: 2BAE72974:
                    to=<ctheune@...>, orig_to=<ct@...>,
                    relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
                    status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
                    said: 250 2.1.0 ok (in reply to DATA command))
                    Dec 1 15:02:41 uter postfix/bounce[11366]: connection established
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: connect to subsystem private/bounce
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr nrequest = 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: bounce socket: wanted
                    attribute: nrequest
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr flags = 0
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr queue_id = 2BAE72974
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr original_recipient
                    = dh@...
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr recipient =
                    nilo@...
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr offset = 399
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 5.0.0
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr action = failed
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason = host
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
                    reply to DATA command)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
                    wanted attribute: status

                    After that the same mail tries again on dh@... (rewritten to
                    nilo@...) and fails again while talking to the lmtp:


                    Dec 1 15:02:41 uter postfix/bounce[11366]: bounce_append_proto:
                    flags=0x0 service=bounce id=2BAE72974 org_to=dh@...
                    to=nilo@... off=399 stat=5.0.0 act=failed why=host
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
                    reply to DATA command)
                    Dec 1 15:02:41 uter postfix/bounce[11366]: send attr status = 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 1
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: status
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute value: 0
                    Dec 1 15:02:41 uter postfix/bounce[11366]: connection closed
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
                    wanted attribute: (list terminator)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: (end)
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: 2BAE72974:
                    to=<nilo@...>, orig_to=<dh@...>,
                    relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
                    status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
                    said: 250 2.1.0 ok (in reply to DATA command))
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                    /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.5 ok
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: name_mask: resource
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: name_mask: software
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_request_final: send: "" 0
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason =
                    Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 0

                    On 12/1/05, Wietse Venema <wietse@...> wrote:
                    > It would still be worthwhile to find out if the last
                    > delivery was OK by the process with the failed RSET.

                    I hope this is enough information. I'm not sure, but it looks like the
                    mail before the RSET was broken already.

                    After switching off connection reuse everything works fine. I haven't
                    found another bounce with those errors in the last 15 hours.

                    Thanks,
                    Christian
                  • Victor Duchovni
                    ... Please also show what happens before this! We are already out of sync at this point. Show all the logs for process 11210 changing only the sender and
                    Message 9 of 17 , Dec 1, 2005
                      On Fri, Dec 02, 2005 at 07:22:16AM +0100, Christian Theune wrote:

                      > Hmm. Ok, I've taken a bit more log data that might help you:
                      >
                      > This is a first mail that bounces:
                      >
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: from
                      > plone-users-admin@...
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: reusing
                      > (count 5) session with: /var/imap/socket/lmtp
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
                      > FROM:<plone-users-admin@...> SIZE=6620
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
                      > TO:<ctheune@...>
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
                      > TO:<nilo@...>
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: >
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: DATA
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
                      > Dec 1 15:02:41 uter postfix/lmtp[11210]: <
                      > /var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok

                      Please also show what happens before this! We are already out of sync
                      at this point. Show all the logs for process 11210 changing only the
                      sender and recipient addresses if you want to protect their identities.
                      The specific addresses don't matter in this context

                      --
                      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:majordomo@...?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.
                    • Christian Theune
                      Damn. That log file was too large. Anyway, I posted an excerpt here: http://amy.gocept.com/~ctheune/postfix.log
                      Message 10 of 17 , Dec 1, 2005
                        Damn. That log file was too large. Anyway, I posted an excerpt here:

                        http://amy.gocept.com/~ctheune/postfix.log

                        On 12/2/05, Christian Theune <theuni@...> wrote:
                        > Oh, ok. I'm sorry. You find a larger snippet as an attachment.
                        >
                        > I grepped the log for process 11210 only, I hope this is enough.
                      • Victor Duchovni
                        ... Super! 14:59:32 LHLO uter.whq.gocept.com 14:59:32
                        Message 11 of 17 , Dec 2, 2005
                          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:<root@...> SIZE=4594
                          14:59:32 > RCPT TO:<zagy+ptd@...>
                          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:<amavis@...> SIZE=570
                          15:00:02 > RCPT TO:<ctheune@...>
                          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:<ct@...> SIZE=4064
                          15:00:02 > RCPT TO:<ctheune@...>
                          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:<nilo@...> SIZE=1274
                          15:00:08 > RCPT TO:<nilo@...>
                          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 <nilo@...> SIZE=1274 to
                          <nilo@...>. 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:<back@...> 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-admin@...> SIZE=6620
                          15:02:41 > RCPT TO:<ctheune@...>
                          15:02:41 > RCPT TO:<nilo@...>
                          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-bounces@...> 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:majordomo@...?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.
                        Your message has been successfully submitted and would be delivered to recipients shortly.