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

PATCH: Weird bounces with Postfix, LMTP and Cyrus

Expand Messages
  • 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 1 of 17 , Dec 1, 2005
    • 0 Attachment
      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
    • 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 2 of 17 , Dec 1, 2005
      • 0 Attachment
        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 3 of 17 , Dec 1, 2005
        • 0 Attachment
          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 4 of 17 , Dec 1, 2005
          • 0 Attachment
            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 5 of 17 , Dec 1, 2005
            • 0 Attachment
              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 6 of 17 , Dec 2, 2005
              • 0 Attachment
                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.