The remote peer sent a TLS shutdown message during the TLS handshake.
There is no way to 'continue' the handshake.
Maybe the remote peer times out - you could find out by looking at
the TIME STAMPS in your logs. Causes for timeout: your server is
slow, or your network has packet loss.
The timestamps look good (i.e. the entire transaction happens very
quickly without huge gaps in time). The server has little load and is on
a high-quality network. Not to say that those causes aren't possible,
but the only change in the last few days has been the upgraded software.
I'm including logs for a send event and a receive event. I've removed
spf/opendkim/etc entries so that it's just postfix (and also scrubbed
some hostname and IP data).
On the send, I immediately resent the message and then it succeeded. On
the receive, the mailserver immediately retried sending (and it
succeeded, as can be seen).
Send:
May 11 12:20:56 vasaconsulting postfix/smtpd[28652]: connect from <data
scrubbed>[<data scrubbed>]
May 11 12:20:56 vasaconsulting postfix/tlsmgr[8390]: put smtpd session
id=AB4F6D34D354C888E50413E7DFADA37D900F7FD03D2A57145F8C9EBCD4F85CD5&s=submission&l=269488207
[data 137 bytes]
May 11 12:20:56 vasaconsulting postfix/tlsmgr[8390]: write smtpd TLS cache entry
AB4F6D34D354C888E50413E7DFADA37D900F7FD03D2A57145F8C9EBCD4F85CD5&s=submission&l=269488207:
time=1589224856 [data 137 bytes]
May 11 12:20:56 vasaconsulting postfix/smtpd[28652]: Anonymous TLS connection established
from <data scrubbed>[<data scrubbed>]: TLSv1.3 with cipher
TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048
bits) server-digest SHA256
May 11 12:20:57 vasaconsulting postfix/smtpd[28652]: 53C0A102C037: client=<data
scrubbed>[<data scrubbed>], sasl_method=LOGIN, sasl_username=<data scrubbed>
May 11 12:20:57 vasaconsulting postfix/smtpd[28652]: warning: TLS library
problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in
init:../ssl/ssl_lib.c:2086:
May 11 12:20:57 vasaconsulting postfix/smtpd[28652]: lost connection after RCPT from
<data scrubbed>[<data scrubbed>]
May 11 12:20:57 vasaconsulting postfix/smtpd[28652]: disconnect from <data
scrubbed>[<data scrubbed>] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 commands=6
...(failed, so I immediately resent)...
May 11 12:21:04 vasaconsulting postfix/smtpd[28652]: connect from <data
scrubbed>[<data scrubbed>]
May 11 12:21:04 vasaconsulting postfix/tlsmgr[8390]: put smtpd session
id=087C6BFDEF211BFF520D2E1045C1EDEFAEC4D278CAA6C90BBF359DA242DC148B&s=submission&l=269488207
[data 137 bytes]
May 11 12:21:04 vasaconsulting postfix/tlsmgr[8390]: write smtpd TLS cache entry
087C6BFDEF211BFF520D2E1045C1EDEFAEC4D278CAA6C90BBF359DA242DC148B&s=submission&l=269488207:
time=1589224864 [data 137 bytes]
May 11 12:21:04 vasaconsulting postfix/smtpd[28652]: Anonymous TLS connection established
from <data scrubbed>[<data scrubbed>]: TLSv1.3 with cipher
TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048
bits) server-digest SHA256
May 11 12:21:04 vasaconsulting postfix/smtpd[28652]: E94AB102C037: client=<data
scrubbed>[<data scrubbed>], sasl_method=LOGIN, sasl_username=<data scrubbed>
May 11 12:21:05 vasaconsulting postfix/cleanup[28662]: E94AB102C037:
message-id=<20200511192056.ga653...@vasaconsulting.com>
May 11 12:21:05 vasaconsulting postfix/qmgr[8383]: E94AB102C037: from=<<data
scrubbed>@vasaconsulting.com>, size=805, nrcpt=1 (queue active)
May 11 12:21:05 vasaconsulting postfix/smtpd[28652]: disconnect from <data
scrubbed>[<data scrubbed>] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1
commands=8
Receive:
May 11 12:01:23 vasaconsulting postfix/smtpd[26470]: connect from
mail.netbsd.org[199.233.217.200]
May 11 12:01:23 vasaconsulting postfix/smtpd[26470]: Anonymous TLS connection
established from mail.netbsd.org[199.233.217.200]: TLSv1.2 with cipher
ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: 8E132102C037:
client=mail.netbsd.org[199.233.217.200]
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: warning: TLS library
problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in
init:../ssl/ssl_lib.c:2086:
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: lost connection after DATA
(0 bytes) from mail.netbsd.org[199.233.217.200]
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: disconnect from
mail.netbsd.org[199.233.217.200] ehlo=2 starttls=1 mail=1 rcpt=1 data=0/1
commands=5/6
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: connect from
mail.netbsd.org[199.233.217.200]
May 11 12:01:25 vasaconsulting postfix/smtpd[26470]: A1BFD102C037:
client=mail.netbsd.org[199.233.217.200]
May 11 12:01:25 vasaconsulting postfix/cleanup[26482]: A1BFD102C037:
message-id=<20200511195523.75ad319caf398a1c685c8...@googlemail.com>
May 11 12:01:26 vasaconsulting postfix/qmgr[8383]: A1BFD102C037:
from=<bounces-pkgsrc-users-owner-alexander+pkgsrc=vasaconsulting....@netbsd.org>,
size=4653, nrcpt=1 (queue active)
May 11 12:01:26 vasaconsulting postfix/smtpd[26470]: disconnect from
mail.netbsd.org[199.233.217.200] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Another other thing that may be of interest is the last line before the
disconnect. Sometimes it's like this:
May 11 12:28:07 vasaconsulting postfix/smtpd[29124]: lost connection after DATA
(0 bytes) from english-breakfast.cloud9.net[168.100.1.7]
And other times, it's like this:
May 11 12:20:57 vasaconsulting postfix/smtpd[28652]: lost connection after RCPT from
<data scrubbed>[<data scrubbed>]
Just in case this is an OpenSSL glitch, you should at this point be
using OpenSSL 1.1.1g.
I can upgrade OpenSSL to 1.1.1g, but it would go outside of the stable
"channel" of my distribution, so it's not a preferred approach. I
recognize that this is a symptom of an underlying problem, just trying
to figure out what that underlying problem might be. Thanks.
Alexander
