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