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

Missing smtp delivery log event with smtp_tls_loglevel = 3

Expand Messages
  • Asa Gage
    I seem to be missing smtp log events regarding delivery status for TLS enabled mail when smtp_tls_loglevel = 3. I see a ton of TLS data as expected, but the
    Message 1 of 6 , Jan 30, 2013
    • 0 Attachment
      I seem to be missing smtp log events regarding delivery status for TLS
      enabled mail when smtp_tls_loglevel = 3. I see a ton of TLS data as
      expected, but the actual smtp result is no longer present. Is there any
      explanation for this behavior?
      mail_version = 2.6.6

      #sample TLS mail
      grep CAEAB20079 ./maillog
      Jan 29 01:00:25 server242 postfix-mx01/smtpd[24491]: CAEAB20079:
      client=unknown[10.100.190.101]
      Jan 29 01:00:25 server242 postfix-mx01/cleanup[24601]: CAEAB20079:
      message-id=<redacted@...>
      Jan 29 01:00:25 server242 postfix-mx01/qmgr[18097]: CAEAB20079:
      from=<redacted@...>, size=10269, nrcpt=1 (queue active)
      Jan 29 01:00:27 server242 postfix-mx01/qmgr[18097]: CAEAB20079: removed

      #sample non TLS mail
      grep 8B8362008B ./maillog
      Jan 29 03:00:43 server242 postfix-mx01/smtpd[12814]: 8B8362008B:
      client=unknown[10.100.190.101]
      Jan 29 03:00:43 server242 postfix-mx01/cleanup[12903]: 8B8362008B:
      message-id=<redacted@redacted>
      Jan 29 03:00:43 server242 postfix-mx01/qmgr[18097]: 8B8362008B:
      from=<redacted@...>, size=10262, nrcpt=1 (queue active)
      #the line below is the one that is missing from the example above
      Jan 29 03:00:49 server242 postfix-mx01/smtp[12904]: 8B8362008B:
      to=<redacted@...>, relay=server[X.X.X.X]:25, conn_use=4,
      delay=6.4, delays=0.01/4.5/0.12/1.8, dsn=2.0.0, status=sent (250 Backend
      Replied [XXXXX]: 2.0.0 r0T80nWF017713 Message acce)
      Jan 29 03:00:49 server242 postfix-mx01/qmgr[18097]: 8B8362008B: removed

      Thanks,

      Asa Gage
    • Wietse Venema
      ... syslog uses a connection-less transport. The more logging you turn on, the more events will be lost. Wietse
      Message 2 of 6 , Jan 30, 2013
      • 0 Attachment
        Asa Gage:
        > I seem to be missing smtp log events regarding delivery status for TLS
        > enabled mail when smtp_tls_loglevel = 3. I see a ton of TLS data as
        > expected, but the actual smtp result is no longer present. Is there any
        > explanation for this behavior?

        syslog uses a connection-less transport. The more logging you turn
        on, the more events will be lost.

        Wietse
      • /dev/rob0
        ... Below you have showed us nothing which would be affected by the setting of smtp_tls_loglevel. ... No smtp(8) logging shown in this incomplete log snippet.
        Message 3 of 6 , Jan 30, 2013
        • 0 Attachment
          On Wed, Jan 30, 2013 at 05:07:47PM -0500, Asa Gage wrote:
          > I seem to be missing smtp log events regarding delivery status for
          > TLS enabled mail when smtp_tls_loglevel = 3.

          Below you have showed us nothing which would be affected by the
          setting of smtp_tls_loglevel.

          > I see a ton of TLS data as expected, but the actual smtp result is
          > no longer present. Is there any explanation for this behavior?
          > mail_version = 2.6.6
          >
          > #sample TLS mail
          > grep CAEAB20079 ./maillog
          > Jan 29 01:00:25 server242 postfix-mx01/smtpd[24491]: CAEAB20079:
          > client=unknown[10.100.190.101]
          > Jan 29 01:00:25 server242 postfix-mx01/cleanup[24601]: CAEAB20079:
          > message-id=<redacted@...>
          > Jan 29 01:00:25 server242 postfix-mx01/qmgr[18097]: CAEAB20079:
          > from=<redacted@...>, size=10269, nrcpt=1 (queue active)
          > Jan 29 01:00:27 server242 postfix-mx01/qmgr[18097]: CAEAB20079: removed

          No smtp(8) logging shown in this incomplete log snippet. (No outgoing
          transport at all, for that matter.)

          > #sample non TLS mail
          > grep 8B8362008B ./maillog
          > Jan 29 03:00:43 server242 postfix-mx01/smtpd[12814]: 8B8362008B:
          > client=unknown[10.100.190.101]
          > Jan 29 03:00:43 server242 postfix-mx01/cleanup[12903]: 8B8362008B:
          > message-id=<redacted@redacted>
          > Jan 29 03:00:43 server242 postfix-mx01/qmgr[18097]: 8B8362008B:
          > from=<redacted@...>, size=10262, nrcpt=1 (queue active)
          > #the line below is the one that is missing from the example above
          > Jan 29 03:00:49 server242 postfix-mx01/smtp[12904]: 8B8362008B:
          > to=<redacted@...>, relay=server[X.X.X.X]:25, conn_use=4,
          > delay=6.4, delays=0.01/4.5/0.12/1.8, dsn=2.0.0, status=sent (250 Backend
          > Replied [XXXXX]: 2.0.0 r0T80nWF017713 Message acce)

          There's smtp logging, but you did say it was non-TLS.

          > Jan 29 03:00:49 server242 postfix-mx01/qmgr[18097]: 8B8362008B: removed

          Perhaps you are confusing smtp(8) and smtpd(8)?
          --
          http://rob0.nodns4.us/ -- system administration and consulting
          Offlist GMX mail is seen only if "/dev/rob0" is in the Subject:
        • James Griffin
          ... I believe setting the tls log level to 1 is all you need to see the relevant session details. Setting the logging too high renders it difficult to make
          Message 4 of 6 , Jan 31, 2013
          • 0 Attachment
            * Asa Gage <agage@...> [2013-01-30 17:07:47 -0500]:

            > I seem to be missing smtp log events regarding delivery status for TLS
            > enabled mail when smtp_tls_loglevel = 3. I see a ton of TLS data as
            > expected, but the actual smtp result is no longer present. Is there any
            > explanation for this behavior?
            > mail_version = 2.6.6

            I believe setting the tls log level to 1 is all you need to see the
            relevant session details. Setting the logging too high renders it
            difficult to make sense of imo. Also, as pointed out by /dev/rob0,
            are you trying to see the details for incoming (smtpd(8)) or outgoing
            (smtp(8))?


            --
            Primary Key: 4096R/1D31DC38 2011-12-03
            Key Fingerprint: A4B9 E875 A18C 6E11 F46D B788 BEE6 1251 1D31 DC38
          • Asa Gage
            This was right on. Thanks Wietse. The rsyslogd service had rate limiting enabled by default and the log lines were getting dropped. I fixed it by adding the
            Message 5 of 6 , Feb 1, 2013
            • 0 Attachment
              This was right on. Thanks Wietse.

              The rsyslogd service had rate limiting enabled by default and the log
              lines were getting dropped.

              I fixed it by adding the following line to /etc/rsyslog.conf

              $SystemLogRateLimitInterval 0 # turn off rate limiting


              ________________________________________
              Asa Gage
              Senior Systems Engineer, NOC | Next Jump, Inc.
              One Kendall Square, STE B2401, Cambridge, MA 02139
              P: 617.682.4660 x5574 24/7: 617-682-4665
              agage@... | oo.com

              "BETTER Me+You=Us"
              Check out our culture video http://nxj.me/nextjump


              -----Original Message-----
              From: wietse@... [mailto:wietse@...]
              Sent: Wednesday, January 30, 2013 5:27 PM
              To: Asa Gage
              Cc: postfix-users@...
              Subject: Re: Missing smtp delivery log event with smtp_tls_loglevel = 3

              Asa Gage:
              > I seem to be missing smtp log events regarding delivery status for TLS

              > enabled mail when smtp_tls_loglevel = 3. I see a ton of TLS data as
              > expected, but the actual smtp result is no longer present. Is there
              > any explanation for this behavior?

              syslog uses a connection-less transport. The more logging you turn on,
              the more events will be lost.

              Wietse
            • Viktor Dukhovni
              ... Still you never need a tls log level greater than 2 when doing trouble-shoots or 1 in production. Log levels 3 and 4 are for packet-level SSL traffic
              Message 6 of 6 , Feb 1, 2013
              • 0 Attachment
                On Fri, Feb 01, 2013 at 10:39:31AM -0500, Asa Gage wrote:

                > This was right on. Thanks Wietse.
                >
                > The rsyslogd service had rate limiting enabled by default and the log
                > lines were getting dropped.
                >
                > I fixed it by adding the following line to /etc/rsyslog.conf
                >
                > $SystemLogRateLimitInterval 0 # turn off rate limiting

                Still you never need a tls log level greater than 2 when doing
                trouble-shoots or 1 in production. Log levels 3 and 4 are for
                packet-level SSL traffic debugging by Postfix developers, to
                diagnose potential issues in the SSL I/O plumbing, not for
                general use. If you want to capture traffic, it is better
                to use tcpdump not syslog.

                While you may not want to have rate limits on syslog for other
                reasons, the fix for this problem is to not set a tls log level of
                3 or more in either the SMTP client or server.

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