On 10/1/22 18:04, Wietse Venema wrote:
Look for the 'disconnect' logfile record, it will report if starttls
was used, and if it was successful.
A recent example:
Sep 27 13:06:35 spike postfix/smtpd[78883]: disconnect from
m227-25.mailgun.net[159.135.227.25] ehlo=1 starttls=0/1 commands=1/2
Sep 27 13:07:36 spike postfix/smtpd[78883]: disconnect from
m227-25.mailgun.net[159.135.227.25] ehlo=2 starttls=1 mail=1 rcpt=1 data=1
commands=6
Their connections seem to come in pairs: the first one fails with
an SSL_accept error, then they reconnect immediately and succeed
with
TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits)
key-exchange X25519 server-signature RSA-PSS (2048 bits)
server-digest SHA256
Counts of disconnects where starttls starts with 0:
elyograg@bilbo:~$ for i in /var/log/mail.log /var/log/mail.log.1 ; do
echo -n "$i: " ; sudo cat $i | perl -lne 'print if m/smtpd\[\d+\]\:
disconnect/' | grep -cw "starttls=0" ; done
/var/log/mail.log: 147
/var/log/mail.log.1: 167
elyograg@bilbo:~$ for i in /var/log/mail.log.?.gz ; do echo -n "$i: " ;
sudo zcat $i | perl -lne 'print if m/smtpd\[\d+\]\: disconnect/' | grep
-cw "starttls=0" ; done
/var/log/mail.log.2.gz: 125
/var/log/mail.log.3.gz: 183
/var/log/mail.log.4.gz: 182
Counts of disconnects where starttls starts with a number other than 0:
elyograg@bilbo:~$ for i in /var/log/mail.log /var/log/mail.log.1 ; do
echo -n "$i: " ; sudo cat $i | perl -lne 'print if m/smtpd\[\d+\]\:
disconnect/' | grep -cw "starttls=[1-9]" ; done
/var/log/mail.log: 2185
/var/log/mail.log.1: 1499
elyograg@bilbo:~$ for i in /var/log/mail.log.?.gz ; do echo -n "$i: " ;
sudo zcat $i | perl -lne 'print if m/smtpd\[\d+\]\: disconnect/' | grep
-cw "starttls=[1-9]" ; done
/var/log/mail.log.2.gz: 1370
/var/log/mail.log.3.gz: 1762
/var/log/mail.log.4.gz: 1558
These numbers suggest that most full connections are in fact using TLS.
A very different conclusion than when I was looking at connects. Based
on the numbers, I am guessing that this only counts connections that
didn't abort early for some reason. Here is the log from two
connections that were made using TLS where it was aborted without trying
to transfer mail, and the disconnect log doesn't have starttls in it:
----------------
Sep 25 00:05:26 bilbo postfix/smtps/smtpd[492903]: connect from
unknown[170.205.161.87]
Sep 25 00:05:27 bilbo postfix/smtps/smtpd[492903]: Anonymous TLS
connection established from unknown[170.205.161.87]: TLSv1.2
with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Sep 25 00:05:31 bilbo postfix/smtps/smtpd[492903]: warning:
unknown[170.205.161.87]: SASL PLAIN authentication failed:
Sep 25 00:05:31 bilbo postfix/smtps/smtpd[492903]: lost connection after
AUTH from unknown[170.205.161.87]
Sep 25 00:05:31 bilbo postfix/smtps/smtpd[492903]: disconnect from
unknown[170.205.161.87] ehlo=1 auth=0/1 commands=1/2
Sep 25 00:05:33 bilbo postfix/smtps/smtpd[492903]: warning: hostname
221-12-59-213.zjnetcom.com does not resolve to address 221.12.59.213:
Name or service not known
Sep 25 00:05:33 bilbo postfix/smtps/smtpd[492903]: connect from
unknown[221.12.59.213]
Sep 25 00:05:35 bilbo postfix/smtps/smtpd[492903]: Anonymous TLS
connection established from unknown[221.12.59.213]: TLSv1.2 with cipher
ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Sep 25 00:05:40 bilbo postfix/smtps/smtpd[492903]: warning:
unknown[221.12.59.213]: SASL PLAIN authentication failed:
Sep 25 00:05:41 bilbo postfix/smtps/smtpd[492903]: lost connection after
AUTH from unknown[221.12.59.213]
Sep 25 00:05:41 bilbo postfix/smtps/smtpd[492903]: disconnect from
unknown[221.12.59.213] ehlo=1 auth=0/1 commands=1/2
----------------
I leave it to you to decide whether the omission of any info about TLS
in the disconnect log for this type of connection constitutes a bug. I
am running Postfix 3.4.13 from the Ubuntu focal repository. Eventually
I will upgrade to jammy, but not until a lot more PHP software supports
PHP 8.1 out of the box. I was caught off guard by PHP software not
supporting PHP 8.1 when I upgraded my server at home to Ubuntu jammy.
The mailserver is a lot more mission critical than my basement server,
so I am delaying that upgrade. Which means that it's not running
anywhere near the latest version of postfix.
The config I was aiming for should not allow authentication on anything
other than port 587, so even if somehow they have the right password, it
shouldn't allow the connection. I do have it listening on port 465,
hopefully I got the config right so that does not allow authentication.
I think I also disabled TLS below 1.2 on port 587.
Outbound connections from postfix on port 25 is probably the one place
where I would plan on not checking that the server cert validates,
because chances are that a lot of MTAs will be using the default
self-signed certificate that they get when they are installed. I may be
in the minority using a "real" cert (from LE). I actually don't know if
my TLS config does or does not check this. I will check on that later.
And maybe later I will also figure out if I can count outbound
connections in my logs that do and do not use TLS.
Mostly offtopic but interesting to me: Right after those logs, mail.log
contains a message about a failed TLS connection to dovecot on one of
the imap ports. For dovecot, I am refusing connections with TLS below 1.2:
Sep 25 00:07:45 bilbo dovecot: imap-login: Disconnected: Connection
closed: SSL_accept() failed: error:14209102:SSL
routines:tls_early_post_process_client_hello:unsupported protocol (no
auth attempts in 3 secs): user=<>, rip=205.210.31.140, lip=172.31.8.104,
TLS handshaking: SSL_accept() failed: error:14209102:SSL
routines:tls_early_post_process_client_hello:unsupported protocol,
session=<x8XLOnrp39PN0h+M>
Thanks,
Shawn
