Inspection of postfix server logs for outgoing mail shows TLS handshake errors in connecting to the recipients’ mail servers. The server tried again later, and messages were eventually delivered, but I’d like to avoid the delays. Besides, if I didn’t understand what was going on, maybe in the future the mail would not be delivered even after a delay. I investigate and solve the problem.
From mail sent 2025 May 24 at 3:02 p.m., I have TLS handshake errors for
Could it be I am restricting the TLS protocols or ciphers too much? It might be a temporary glitch, but that seems unlikely since it comes from four different sources. On the other hand, didn’t some of these go through the other day? Yes, two of them did (earthlink, vtext). And one of those was deferred but successfully sent eight minutes later.
I’ve copied parts of the maillog to /var/log/maillog-tls-hserrors for further analysis later.
Ah, yes, all four have now come in at 15:10; again, eight minutes delayed.
So no need to investigate further, I guess.
Same thing happened, mail sent today at 12:13 p.m., except mail went through to user1 this time. As of 12:30 no further action on the part of our server. Messages with deferred status to Verizon (user2), Prodigy.net (user4), and ATT.net (user3), and there is no further action for a long time….
—No, it just looked that way because the terminal showing the log file went dead. I close the terminal, reconnect, and look again at the log file. Okay, all three went through at 12:22–12:23.
A typical case looks like this (excerpts from /var/log/maillog):
May 31 12:13:06 user0 postfix/smtp[29437]: SSL_connect error to al-ip4-mx-vip1.prodigy.net[144.160.235.143]:25: -1
May 31 12:13:06 user0 postfix/smtp[29437]: warning: TLS library problem: error:0A000410:SSL routines::sslv3 alert handshake failure:/usr/src/crypto/openssl/ssl/record/rec_layer_s3.c:1605:SSL alert number 40:
May 31 12:13:06 user0 postfix/smtp[29437]: 3DA188638: Cannot start TLS: handshake failure
It may be the client and server cannot agree on a version of TLS. But if that were the case, why would the messages eventually have gone through, on May 24?
See these search results:
Here’s another incident:
Jul 25 13:18:11 user0 dovecot[913]:
submission(user0)<19304>
Jul 25 13:18:12 user0 postfix/smtp[19311]: SSL_connect error to pkvw-mx.msg.pkvw.co.charter.net[47.43.26.7]:25: -1
Jul 25 13:18:12 user0 postfix/smtp[19311]: warning: TLS library problem: error:0A000410:SSL routines::sslv3 alert handshake failure:/usr/src/crypto/openssl/ssl/record/rec_layer_s3.c:1605:SSL alert number 40:
Jul 25 13:18:12 user0 postfix/smtp[19311]: BBB9E20D2F: to=user5@woh.rr.com, relay=pkvw-mx.msg.pkvw.co.charter.net[47.43.26.7]:25, delay=0.73, delays=0.21/0.01/0.51/0, dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
Then a bit later:
Jul 25 13:23:34 user0 postfix/qmgr[1007]: BBB9E20D2F: from=user0@gdweber.org, size=1745, nrcpt=1 (queue active)
Jul 25 13:23:35 user0 postfix/smtp[19326]: SSL_connect error to pkvw-mx.msg.pkvw.co.charter.net[47.43.26.7]:25: -1
Jul 25 13:23:35 user0 postfix/smtp[19326]: warning: TLS library problem: error:0A000410:SSL routines::sslv3 alert handshake failure:/usr/src/crypto/openssl/ssl/record/rec_layer_s3.c:1605:SSL alert number 40:
Jul 25 13:23:35 user0 postfix/smtp[19326]: BBB9E20D2F: Cannot start TLS: handshake failure
Jul 25 13:23:35 user0 postfix/smtp[19326]: BBB9E20D2F: to=user5@woh.rr.com, relay=pkvw-mx.msg.pkvw.co.charter.net[47.43.26.7]:25, delay=324, delays=323/0.01/0.7/0.34, dsn=2.0.0, status=sent (250 2.0.0 fM8tuTrVmhmOhfM8tuUtUI mail accepted for delivery)
Jul 25 13:23:35 user0 postfix/qmgr[1007]: BBB9E20D2F: removed
Now why, immediately after the TLS handshake error, does it say the message is accepted?
Following the recommendation from one of my search results, though not for precisely the same error, I decide to use openssl s_client to debug the TLS connection:
$ openssl s_client -starttls smtp -crlf -connect pkvw-mx.msg.pkvw.co.charter.net:25
Handshake succeeds with result “New, TLSv1.2, Cipher is ECDHE-RSA-AES256-GCM-SHA384”.
I made a script ~/bin/tls-test HOST to make testing more convenient. Here is the script:
$ cat bin/tls-test
#!/bin/sh
HOST=$1
echo quit | openssl s_client -starttls smtp -crlf -connect $HOST:25 | grep 'New, TLS'Here is what the parameters of the openssl command do:
Here are the results:
These responses tell me that most of the servers probably only support TLS up to v1.2. Earthlink has probably recently upgraded one of theirs to v1.3, and the other two I contacted are having some kind of trouble! All of the ones that I’ve had no trouble with (Gmail, Microsoft, Yahoo, Hotmail) are responding with TLSv1.3.
So probably I need to relax my rules for postfix and allow TLSv1.2.
I edit /usr/local/etc/mail/postfix/main.cf, changing the lines
smtpd_tls_mandatory_protocols = >=TLSv1.3
smtpd_tls_protocols = >=TLSv1.3and the corresponding parameters for the SMTP client (i.e., Postfix sending mail to another server)
smtp_tls_security_level = may
smtp_tls_mandatory_protocols = >=TLSv1.3
smtp_tls_protocols = >=TLSv1.3changing TLSv1.3 to TLSv1.2.
I must have gotten those with TLSv1.3 from Mozilla’s configuration generator with the “Modern” option (“all clients support TLSv1.3”). It didn’t occur to me that that should read “all clients and servers support TLSv1.3”.
Sent a test message to four deferred message recipients; all four went through immediately.
2025 July 26
What a joy to send out my rehearsal plan and see all of them getting through to their recipients immediately!
Jul 26 13:58:03 user0 postfix/qmgr[20008]: 2A68C20D99: from=user0@gdweber.org, size=1400, nrcpt=8 (queue active)
Jul 26 13:58:03 user0 dovecot[913]:
submission(user0)<23672>
Jul 26 13:58:03 user0 postfix/smtpd[23667]: disconnect from localhost[::1] ehlo=1 mail=1 rcpt=8 bdat=1 quit=1 commands=12
Jul 26 13:58:04 user0 postfix/smtp[23678]: 2A68C20D99: to=user1@earthlink.net, relay=mx01.earthlink-vadesecure.net[51.81.61.70]:25, delay=1.3, delays=0.31/0.02/0.37/0.64, dsn=2.6.0, status=sent (250 2.6.0 Message accepted with ID 1dac88de-1855dee00f4fa1fc)
Jul 26 13:58:05 user0 postfix/smtp[23682]: 2A68C20D99: to=user2@vtext.com, relay=vrz-sms.mx.a.cloudfilter.net[35.165.168.89]:25, delay=2.3, delays=0.31/0.05/1/0.92, dsn=2.0.0, status=sent (250 2.0.0 fj9nuHKRrEnw4fj9oux1SS mail accepted for delivery)
Jul 26 13:58:05 user0 postfix/smtp[23681]: 2A68C20D99: to=user4@sbcglobal.net, relay=al-ip4-mx-vip2.prodigy.net[144.160.235.144]:25, delay=2.8, delays=0.31/0.04/1.3/1.2, dsn=2.0.0, status=sent (250 2.0.0 56QHw3Ew056193 Message accepted for delivery)
Jul 26 13:58:06 user0 postfix/smtp[23677]: 2A68C20D99: to=user3@att.net, relay=ff-ip4-mx-vip2.prodigy.net[144.160.159.22]:25, delay=3.5, delays=0.31/0.01/1.7/1.5, dsn=2.0.0, status=sent (250 2.0.0 56QHw3Ra014236 Message accepted for delivery)
Jul 26 13:58:06 user0 postfix/qmgr[20008]: 2A68C20D99: removed