As implemented many years ago, Postfix SMTP client and server
processes log TLS status information like this:
postfix/smtp[process-id]: Untrusted TLS connection established
to host.example.com[192.168.0.2]:25: TLSv1 with cipher cipher-name
(actual-key-size/raw-key-size bits)
postfix/smtpd[process-id]: Anonymous TLS connection established
from host.example.com[192.168.0.2]: TLSv1 with cipher cipher-name
(actual-key-size/raw-key-size bits)
That is a lot of information, but that is OK because it is logged
once per SMTP session. It is logged soon as the handshake completes,
to simplify trouble shooting.
One consequence of this terseness is that you can't use grep to
find out whether a mail delivery transaction was encrypted. You
need a stateful logfile parser instead.
Nowadays people seem to care more about whether or their connections
are encrypted, so this may be the time to elevate the status of TLS
status information to something that is logged with every mail
delivery transaction (i.e. with the queue ID).
SMTP SERVER
===========
This is an example of how the SMTP server currently logs SASL status
information for each inbound mail transaction:
postfix/smtpd[process-id]: QUEUEID: client=hostname[address],
sasl_method=xxx, sasl_username=yyy, sasl_sender=zzz
It seems natural to add some name=value attribute to this record
to indicate that a particular mail delivery transaction used an
encrypted session.
Once per mail delivery transaction, adding to an existing record:
postfix/smtpd[process-id]: QUEUEID: client=hostname[address],
sasl_method=xxx, sasl_username=yyy, sasl_sender=zzz, <some new
name=value attribute(s) here>
The alternative is to introduce a new logfile record that is
logged once per inbound mail delivery transaction:
New record, once per mail delivery transaction:
postfix/smtpd[process-id]: QUEUEID: <some name=value attribute(s) here>
The new record would be logged in addition to the per-session TLS
status information that is shown in the introduction of this message.
SMTP CLIENT
===========
On the SMTP client side we have basically the same choice: log TLS
status information once per mail delivery transaction or add some
name=value attributes to an existing logfile record.
Once per recipient, adding to an existing record:
postfix/smtp[process-id]: QUEUEID: to=<recipient>, relay=host[address],
<some new name=value attribute(s) here>, delay=xxx, delays=a/b/c/d,
dsn=2.0.0, status=sent (server reply)
New record, once per mail delivery transaction:
postfix/smtp[process-id]: QUEUEID: <some name=value attribute(s) here>
The new record would be logged in addition to the per-session TLS
status information that is shown in the introduction of this message.
WHAT STATUS INFORMATION TO LOG
==============================
If cost is not a concern, then we could log everything like this:
... tls_protocol=TLSv1.2 tls_cipher=ECDHE-RSA-AES256-GCM-SHA384
tls_keysize=256/256 ...
This format is fully extensible, but it adds a lot to the logfile,
and it repeats all the information that is already logged when the
TLS handshake is completed.
Currently people seem to care primarily whether mail was delivered
in plaintext or not, so we could suffice with just the TLS cipher.
tls_cipher=ECDHE-RSA-AES256-GCM-SHA384
Alternatively we could use a non-extensible format such as
tls_status=TLSv1/ECDHE-RSA-AES256-GCM-SHA384/256/256
This basically repeats the information in a less-verbose format,
but also makes adding information more difficult (for example how
the remote peer was authenticated).
Of course the ultimate solution is to make logging fully configurable
and leave the problem in the hands of the capable administrator.
Wietse
