Missing smtp delivery log event with smtp_tls_loglevel = 3

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

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?
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=<[hidden email]>
Jan 29 01:00:25 server242 postfix-mx01/qmgr[18097]: CAEAB20079:
from=<[hidden email]>, 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=<[hidden email]>, 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=<[hidden email]>, 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
Reply | Threaded
Open this post in threaded view
|

Re: Missing smtp delivery log event with smtp_tls_loglevel = 3

Wietse Venema
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
Reply | Threaded
Open this post in threaded view
|

Re: Missing smtp delivery log event with smtp_tls_loglevel = 3

/dev/rob0
In reply to this post by Asa Gage
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=<[hidden email]>
> Jan 29 01:00:25 server242 postfix-mx01/qmgr[18097]: CAEAB20079:
> from=<[hidden email]>, 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=<[hidden email]>, 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=<[hidden email]>, 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:
Reply | Threaded
Open this post in threaded view
|

Re: Missing smtp delivery log event with smtp_tls_loglevel = 3

James Griffin
In reply to this post by Asa Gage
* Asa Gage <[hidden email]> [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
Reply | Threaded
Open this post in threaded view
|

RE: Missing smtp delivery log event with smtp_tls_loglevel = 3

Asa Gage
In reply to this post by Wietse Venema
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
[hidden email] | oo.com

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


-----Original Message-----
From: [hidden email] [mailto:[hidden email]]
Sent: Wednesday, January 30, 2013 5:27 PM
To: Asa Gage
Cc: [hidden email]
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
Reply | Threaded
Open this post in threaded view
|

Re: Missing smtp delivery log event with smtp_tls_loglevel = 3

Viktor Dukhovni
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.