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

Lost connection after DATA and queue IDs

Expand Messages
  • Alvaro Marín
    Hello, one question about connection errors...for example: Jun 19 08:43:37 postfix/smtpd[26460]: connect from unknown[x] Jun 19 08:43:46 postfix/smtpd[26460]:
    Message 1 of 6 , Jun 19, 2014
    • 0 Attachment
      Hello,

      one question about connection errors...for example:

      Jun 19 08:43:37 postfix/smtpd[26460]: connect from unknown[x]
      Jun 19 08:43:46 postfix/smtpd[26460]: 7EAD855B8355: client=unknown[x]
      Jun 19 08:43:55 postfix/smtpd[26460]: lost connection after DATA (17
      bytes) from unknown[x]
      Jun 19 08:43:55 postfix/smtpd[26460]: disconnect from unknown[x]

      when the connection is lost sending DATA, it logs the error and
      disconnects the client. But why is a queue ID assigned if the message is
      not fully received? Why is not logged any line with the error and the ID?

      The same when there is a HOLD rule in header_checks:

      Jun 16 19:47:48 postfix/cleanup[28517]: 18A2F23A00A:
      hold: header Received: from x(x[IP]) by relayserver (Postfix) with
      ESMTPA id from
      x[x]; from=user@... to=user2@...
      proto=ESMTP helo=helo
      Jun 16 19:47:48 postfix/cleanup[28517]: 18A2F23A00A:
      message-id=<003901cf898b$1307a000$3916e000$@domain>

      and here, logs of that ID disappear. As Viktor said in this thread:

      http://archives.neohapsis.com/archives/postfix/2005-09/0097.html
      ==
      The "HOLD" action in body_checks and header_checks happens as the message
      is being accumulatd to the queue file, before the entire message is
      received (i.e. before the final ".<CRLF>" that terminates the message)
      and before
      the "250 OK" is sent to the remote server.
      For transactions that abort in the middle of message transmission, you
      may see cleanup prepare to "HOLD" the message, but the full message
      never arrives and so the queue file is deleted.
      ==

      There is no way to relate the queue ID with the connection error, only
      with the sender's IP. Why is a queue ID assigned if the message hasn't
      been received correctly? Why not show an error with that ID or a NOQUEUE
      message? There is no way to trace a message with the ID and just seems
      to disappear.

      Thank you.

      Regards,

      --
      Alvaro Marín Illera
      Hostalia Internet
      www.hostalia.com
    • Viktor Dukhovni
      ... I see no problem with the above logging. ... So that logs for messages that are not aborted can be correlated, and in any case so as to write the message
      Message 2 of 6 , Jun 19, 2014
      • 0 Attachment
        On Thu, Jun 19, 2014 at 09:06:34AM +0200, Alvaro Mar?n wrote:

        > Jun 19 08:43:37 postfix/smtpd[26460]: connect from unknown[x]
        > Jun 19 08:43:46 postfix/smtpd[26460]: 7EAD855B8355: client=unknown[x]
        > Jun 19 08:43:55 postfix/smtpd[26460]: lost connection after DATA (17 bytes) from unknown[x]
        > Jun 19 08:43:55 postfix/smtpd[26460]: disconnect from unknown[x]

        I see no problem with the above logging.

        > Why is a queue ID assigned if the message hasn't been received correctly?

        So that logs for messages that are not aborted can be correlated, and
        in any case so as to write the message somewhere while it is being
        received. What problem are you having?

        > Why not show an error with that ID or a NOQUEUE
        > message? There is no way to trace a message with the ID and just seems
        > to disappear.

        These questions don't seem to be leading anywhere useful. I suggest
        you find more useful things to think about.

        --
        Viktor.
      • Alvaro Marín
        ... The problem is that there is no way to see what has happened with an email searching the queue ID in the logs (in scripts or apps to trace emails, for
        Message 3 of 6 , Jun 19, 2014
        • 0 Attachment
          El 19/06/14 09:24, Viktor Dukhovni escribió:
          > On Thu, Jun 19, 2014 at 09:06:34AM +0200, Alvaro Mar?n wrote:
          >
          >> Jun 19 08:43:37 postfix/smtpd[26460]: connect from unknown[x]
          >> Jun 19 08:43:46 postfix/smtpd[26460]: 7EAD855B8355: client=unknown[x]
          >> Jun 19 08:43:55 postfix/smtpd[26460]: lost connection after DATA (17 bytes) from unknown[x]
          >> Jun 19 08:43:55 postfix/smtpd[26460]: disconnect from unknown[x]
          >
          > I see no problem with the above logging.
          >
          >> Why is a queue ID assigned if the message hasn't been received correctly?
          >
          > So that logs for messages that are not aborted can be correlated, and
          > in any case so as to write the message somewhere while it is being
          > received. What problem are you having?
          >
          >> Why not show an error with that ID or a NOQUEUE
          >> message? There is no way to trace a message with the ID and just seems
          >> to disappear.
          >
          > These questions don't seem to be leading anywhere useful. I suggest
          > you find more useful things to think about.

          The problem is that there is no way to see what has happened with an
          email searching the queue ID in the logs (in scripts or apps to trace
          emails, for example). It would be usefull add that queue ID to the "lost
          connection error", something like:

          Jun 19 08:43:55 postfix/smtpd[26460]: 7EAD855B8355: lost connection
          after DATA (17 bytes) from unknown[x]

          In this specific case, I could search with the smtpd PID but I guess
          that is not unique.

          Regards,

          --
          Alvaro Marín Illera
          Hostalia Internet
          www.hostalia.com
        • Viktor Dukhovni
          ... It was far from clear you were asking for a queue-id here, that s possible, but would likely require changes in existing log parsing scripts. Not sure
          Message 4 of 6 , Jun 19, 2014
          • 0 Attachment
            On Thu, Jun 19, 2014 at 09:51:39AM +0200, Alvaro Mar?n wrote:

            > The problem is that there is no way to see what has happened with an
            > email searching the queue ID in the logs (in scripts or apps to trace
            > emails, for example). It would be usefull add that queue ID to the "lost
            > connection error", something like:
            >
            > Jun 19 08:43:55 postfix/smtpd[26460]: 7EAD855B8355: lost connection
            > after DATA (17 bytes) from unknown[x]

            It was far from clear you were asking for a queue-id here, that's
            possible, but would likely require changes in existing log parsing
            scripts. Not sure this is sufficiently compelling...

            --- a/postfix/src/smtpd/smtpd.c
            +++ b/postfix/src/smtpd/smtpd.c
            @@ -4893,13 +4893,15 @@ static void smtpd_proto(SMTPD_STATE *state)
            */
            if (state->reason && state->where) {
            if (strcmp(state->where, SMTPD_AFTER_DATA) == 0) {
            - msg_info("%s after %s (%lu bytes) from %s", /* 2.5 compat */
            + msg_info("%s: %s after %s (%lu bytes) from %s", /* 2.5 compat */
            + (state->queue_id ? state->queue_id : "NOQUEUE"),
            state->reason, SMTPD_CMD_DATA, /* 2.5 compat */
            (long) (state->act_size + vstream_peek(state->client)),
            state->namaddr);
            } else if (strcmp(state->where, SMTPD_AFTER_DOT)
            || strcmp(state->reason, REASON_LOST_CONNECTION)) {
            - msg_info("%s after %s from %s",
            + msg_info("%s: %s after %s from %s",
            + (state->queue_id ? state->queue_id : "NOQUEUE"),
            state->reason, state->where, state->namaddr);
            }
            }

            > In this specific case, I could search with the smtpd PID but I guess
            > that is not unique.

            My "collate" Perl script posted previously to this list may be helpful.

            --
            Viktor.
          • Paul C
            Just scanning this thread, are you seeing the mail is actually failing or is the log just concerning you? I had a similar issue not too long ago that sounds
            Message 5 of 6 , Jun 19, 2014
            • 0 Attachment
              Just scanning this thread, are you seeing the mail is actually failing
              or is the log just concerning you?

              I had a similar issue not too long ago that sounds like it could be
              the same issue, where there's no obvious problem but you get an smtp
              error at different parts of the injection process, like before DATA,
              after MAIL TO, etc, and my issue was the time out of my injector's
              smtp transfer, I was using phpmailer which had a 10 second timeout,
              setting it to 20 seconds made those transmission errors stop
              completely, 10 seconds should be plenty of time as smtp is super fast
              but there could be a lag someone on either the server, your script
              etc. If this sounds possible, try raising your timeout, not in
              postfix, but in the script injecting the message in to postfix.

              On Thu, Jun 19, 2014 at 3:51 AM, Alvaro Marín <alvaro@...> wrote:
              > El 19/06/14 09:24, Viktor Dukhovni escribió:
              >> On Thu, Jun 19, 2014 at 09:06:34AM +0200, Alvaro Mar?n wrote:
              >>
              >>> Jun 19 08:43:37 postfix/smtpd[26460]: connect from unknown[x]
              >>> Jun 19 08:43:46 postfix/smtpd[26460]: 7EAD855B8355: client=unknown[x]
              >>> Jun 19 08:43:55 postfix/smtpd[26460]: lost connection after DATA (17 bytes) from unknown[x]
              >>> Jun 19 08:43:55 postfix/smtpd[26460]: disconnect from unknown[x]
              >>
              >> I see no problem with the above logging.
              >>
              >>> Why is a queue ID assigned if the message hasn't been received correctly?
              >>
              >> So that logs for messages that are not aborted can be correlated, and
              >> in any case so as to write the message somewhere while it is being
              >> received. What problem are you having?
              >>
              >>> Why not show an error with that ID or a NOQUEUE
              >>> message? There is no way to trace a message with the ID and just seems
              >>> to disappear.
              >>
              >> These questions don't seem to be leading anywhere useful. I suggest
              >> you find more useful things to think about.
              >
              > The problem is that there is no way to see what has happened with an
              > email searching the queue ID in the logs (in scripts or apps to trace
              > emails, for example). It would be usefull add that queue ID to the "lost
              > connection error", something like:
              >
              > Jun 19 08:43:55 postfix/smtpd[26460]: 7EAD855B8355: lost connection
              > after DATA (17 bytes) from unknown[x]
              >
              > In this specific case, I could search with the smtpd PID but I guess
              > that is not unique.
              >
              > Regards,
              >
              > --
              > Alvaro Marín Illera
              > Hostalia Internet
              > www.hostalia.com
              >
            • Wietse Venema
              ... Indeed. Such logging is desirable with mail that Postfix has taken responsibility for, but it s not compelling in the case of thrash, and there is no
              Message 6 of 6 , Jun 19, 2014
              • 0 Attachment
                Viktor Dukhovni:
                > On Thu, Jun 19, 2014 at 09:51:39AM +0200, Alvaro Mar?n wrote:
                >
                > > The problem is that there is no way to see what has happened with an
                > > email searching the queue ID in the logs (in scripts or apps to trace
                > > emails, for example). It would be usefull add that queue ID to the "lost
                > > connection error", something like:
                > >
                > > Jun 19 08:43:55 postfix/smtpd[26460]: 7EAD855B8355: lost connection
                > > after DATA (17 bytes) from unknown[x]
                >
                > It was far from clear you were asking for a queue-id here, that's
                > possible, but would likely require changes in existing log parsing
                > scripts. Not sure this is sufficiently compelling...

                Indeed. Such logging is desirable with mail that Postfix has taken
                responsibility for, but it's not compelling in the case of thrash,
                and there is no guarantee that it would always be logged because
                a Postfix daemon may be terminated prematurely.

                Wietse
              Your message has been successfully submitted and would be delivered to recipients shortly.