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

Weird bounces with Postfix, LMTP and Cyrus

Expand Messages
  • Christian Theune
    Hi, unfortunately I m not able to give you much context information, as I m not sure what influences this error. Within the first 5 minutes of every hour, I
    Message 1 of 17 , Nov 26, 2005
    • 0 Attachment
      Hi,

      unfortunately I'm not able to give you much context information, as
      I'm not sure what influences this error.

      Within the first 5 minutes of every hour, I get one or two bounces
      that should have been delivered normally. The error messages appear
      mailinglists indexed by google, but are several years old and don't
      refer to any solution that applies to me.

      Typical log entries for those mails look like this:

      Nov 26 07:01:42 uter postfix/lmtp[635]: 7A507294B:
      to=<ctheune+quarantine@...>,
      orig_to=<admin+quarantine@...>,
      relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
      status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
      said: 354 go ahead (in reply to MAIL FROM command))

      Nov 26 07:00:49 uter postfix/lmtp[635]: 8CE1A294D:
      to=<coco@...>, orig_to=<ck@...>,
      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.5 ok (in reply to DATA command))

      Nov 26 01:00:09 uter postfix/lmtp[8381]: 3AD5D294B:
      to=<ctheune@...>,
      orig_to=<ctheune@...>,
      relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
      status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
      said: 500 5.5.2 Syntax error (in reply to MAIL FROM command))

      Did you notice the three different replies from the LMTP server? I 'm
      not sure why the first two replies bounce at all, and I'm not sure why
      the last one occurs at all. Some older posting (2003) implied that the
      LMTP client was broken in a way that transfers a size parameter within
      the first FROM line and wasn't understood properly by cyrus ...

      Anyway. The most awkward parameter is still, that it only happens in
      the first five minutes of an hour ...

      Thanks for any tip where to continue looking for why this happens,
      Christian
    • Charles Gregory
      Hello! Re the hourly (:00: to :05:) bounces, what you might do is look for cron jobs that run at the beginning of each hour, and see if any of them close and
      Message 2 of 17 , Nov 28, 2005
      • 0 Attachment
        Hello!

        Re the hourly (:00: to :05:) bounces, what you might do is look for cron
        jobs that run at the beginning of each hour, and see if any of them close
        and re-open sockets or files. In particular, look for badly behaved
        'update' utilities for any of your content filters.

        I'm taking a wild guess that the lmtp client is getting 'killed' in a
        fashion that fails to generate a proper error message, so the error logged
        is whatever was in the buffer from a previous command.

        - Charles


        On Sat, 26 Nov 2005, Christian Theune wrote:
        > Within the first 5 minutes of every hour, I get one or two bounces
        > that should have been delivered normally. The error messages appear
        > mailinglists indexed by google, but are several years old and don't
        > refer to any solution that applies to me.
        >
        > Typical log entries for those mails look like this:
        >
        > Nov 26 07:01:42 uter postfix/lmtp[635]: 7A507294B:
        > to=<ctheune+quarantine@...>,
        > orig_to=<admin+quarantine@...>,
        > relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
        > status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
        > said: 354 go ahead (in reply to MAIL FROM command))
        >
        > Nov 26 07:00:49 uter postfix/lmtp[635]: 8CE1A294D:
        > to=<coco@...>, orig_to=<ck@...>,
        > 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.5 ok (in reply to DATA command))
        >
        > Nov 26 01:00:09 uter postfix/lmtp[8381]: 3AD5D294B:
        > to=<ctheune@...>,
        > orig_to=<ctheune@...>,
        > relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
        > status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
        > said: 500 5.5.2 Syntax error (in reply to MAIL FROM command))
        >
        > Did you notice the three different replies from the LMTP server? I 'm
        > not sure why the first two replies bounce at all, and I'm not sure why
        > the last one occurs at all. Some older posting (2003) implied that the
        > LMTP client was broken in a way that transfers a size parameter within
        > the first FROM line and wasn't understood properly by cyrus ...
        >
        > Anyway. The most awkward parameter is still, that it only happens in
        > the first five minutes of an hour ...
        >
        > Thanks for any tip where to continue looking for why this happens,
        > Christian
        >
      • Victor Duchovni
        ... This is a protocol violation. 354 is not a valid response in this context. What version of Postfix is this? From the HISTORY file: 20040415 Bugfix: the
        Message 3 of 17 , Nov 28, 2005
        • 0 Attachment
          On Sat, Nov 26, 2005 at 09:58:47AM +0100, Christian Theune wrote:

          > Hi,
          >
          > unfortunately I'm not able to give you much context information, as
          > I'm not sure what influences this error.
          >
          > Within the first 5 minutes of every hour, I get one or two bounces
          > that should have been delivered normally. The error messages appear
          > mailinglists indexed by google, but are several years old and don't
          > refer to any solution that applies to me.
          >
          > Typical log entries for those mails look like this:
          >
          > Nov 26 07:01:42 uter postfix/lmtp[635]: 7A507294B:
          > to=<ctheune+quarantine@...>,
          > orig_to=<admin+quarantine@...>,
          > relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
          > status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
          > said: 354 go ahead (in reply to MAIL FROM command))

          This is a protocol violation. 354 is not a valid response in
          this context. What version of Postfix is this? From the
          HISTORY file:

          20040415

          Bugfix: the LMTP client attempted to reuse a connection
          after timeout, causing protocol synchronization errors.
          Reported by Rob Mueller. File: lmtp/lmtp.c.

          This fix is in the 2.0.20, 2.1.6 and 2.2.5 releases, but may not be in
          earlier major or minor releases. Check your copy of the HISTORY file
          (if you built Postfix from source).

          --
          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
          Thanks for the response. I m running 2.1.5 right now. I ll update to 2.2.5 later and tell you if this fixed it. ... Christian
          Message 4 of 17 , Nov 30, 2005
          • 0 Attachment
            Thanks for the response. I'm running 2.1.5 right now. I'll update to
            2.2.5 later and tell you if this fixed it.

            On 11/28/05, Victor Duchovni <Victor.Duchovni@...> wrote:
            > This is a protocol violation. 354 is not a valid response in
            > this context. What version of Postfix is this? From the
            > HISTORY file:
            >
            > 20040415
            >
            > Bugfix: the LMTP client attempted to reuse a connection
            > after timeout, causing protocol synchronization errors.
            > Reported by Rob Mueller. File: lmtp/lmtp.c.
            >
            > This fix is in the 2.0.20, 2.1.6 and 2.2.5 releases, but may not be in
            > earlier major or minor releases. Check your copy of the HISTORY file
            > (if you built Postfix from source).
            >

            Christian
          • Christian Theune
            Ok, I installed Postfix 2.2.5 now and saw my errors again. On the reuse of lmtp-connections I throtteld cyrus to create a new lmtp connection for each request
            Message 5 of 17 , Nov 30, 2005
            • 0 Attachment
              Ok, I installed Postfix 2.2.5 now and saw my errors again. On the
              reuse of lmtp-connections I throtteld cyrus to create a new lmtp
              connection for each request from postfix. Eventually that will help to
              avoid getting a connection that has an unknown state ...

              On 11/30/05, Christian Theune <theuni@...> wrote:
              > Thanks for the response. I'm running 2.1.5 right now. I'll update to
              > 2.2.5 later and tell you if this fixed it.

              Christian
            • Victor Duchovni
              ... 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. If Cyrus is LMTPD is running on
              Message 6 of 17 , Nov 30, 2005
              • 0 Attachment
                On Wed, Nov 30, 2005 at 01:10:09PM +0100, Christian Theune wrote:

                > Ok, I installed Postfix 2.2.5 now and saw my errors again. On the
                > reuse of lmtp-connections I throtteld cyrus to create a new lmtp
                > connection for each request from postfix. Eventually that will help to
                > avoid getting a connection that has an unknown state ...
                >
                > On 11/30/05, Christian Theune <theuni@...> wrote:
                > > Thanks for the response. I'm running 2.1.5 right now. I'll update to
                > > 2.2.5 later and tell you if this fixed it.
                >

                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.

                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.

                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 ".").

                --
                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
                ... 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 7 of 17 , Dec 1, 2005
                • 0 Attachment
                  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 8 of 17 , Dec 1, 2005
                  • 0 Attachment
                    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 9 of 17 , Dec 1, 2005
                    • 0 Attachment
                      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 10 of 17 , Dec 1, 2005
                      • 0 Attachment
                        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 11 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 12 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 13 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 14 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 15 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 16 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 17 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.