"SSL_Shutdown:shutdown while in init" while sending and receiving

classic Classic list List threaded Threaded
43 messages Options
123
Reply | Threaded
Open this post in threaded view
|

"SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
Greetings,

I recently upgraded postfix and OpenSSL to 3.4.10 and 1.1.1d,
respectively. These versions align with Debian GNU/Linux 10 (buster).
Since the upgrade I've begun receiving regular log entries that look
like this:

May 11 11:23:54 vasaconsulting postfix/smtpd[21870]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:

These happen both when receiving and sending messages.

Notably, when sending, the send will fail, but if I immediately resend,
the message goes through. If instead I wait 10 or so seconds before
resending, it will fail.

When it occurs when receiving, the sending mailserver retries sometime
later and seems to get through (though I haven't sought to verify
repeated failures).

I've seen this failure on both TLS v1.2 and v1.3 connections. Some
messages seem to succeed as normal and expected but most fail due to
this error and I haven't been able to identify a pattern.

A survey of the mailing list suggests the problem as experienced by
another user may have been related to tlsproxy but I have
smtp_tls_connection_reuse set to no.

Thanks and regards,

Alexander Vasarab
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Wietse Venema
Alexander Vasarab:

> Greetings,
>
> I recently upgraded postfix and OpenSSL to 3.4.10 and 1.1.1d,
> respectively. These versions align with Debian GNU/Linux 10 (buster).
> Since the upgrade I've begun receiving regular log entries that look
> like this:
>
> May 11 11:23:54 vasaconsulting postfix/smtpd[21870]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
>
> These happen both when receiving and sending messages.

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.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
In reply to this post by Alexander Vasarab
On Mon, May 11, 2020 at 11:43:41AM -0700, Alexander Vasarab wrote:

> I recently upgraded postfix and OpenSSL to 3.4.10 and 1.1.1d,
> respectively. These versions align with Debian GNU/Linux 10 (buster).
> Since the upgrade I've begun receiving regular log entries that look
> like this:
>
> May 11 11:23:54 vasaconsulting postfix/smtpd[21870]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:

Just in case this is an OpenSSL glitch, you should at this point be
using OpenSSL 1.1.1g.

That said, it perhaps possible that Postfix is calling SSL_shutdown() on
a connection that never progressed enough to complete the handshake.
I'll check what preconditions are needed for OpenSSL to allow the
SSL_shutdown() call.  We may need some logic to avoid calling it
too early.

That said, this is not the cause of any problems, rather a symptom.

> When it occurs when receiving, the sending mailserver retries sometime
> later and seems to get through (though I haven't sought to verify
> repeated failures).

Perhaps some network-layer issues.

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
>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=<[hidden email]>
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=<[hidden email]>
May 11 12:01:26 vasaconsulting postfix/qmgr[8383]: A1BFD102C037: from=<bounces-pkgsrc-users-owner-alexander+pkgsrc=[hidden email]>, 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
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Wietse Venema
In reply to this post by Viktor Dukhovni
Viktor Dukhovni:

> On Mon, May 11, 2020 at 11:43:41AM -0700, Alexander Vasarab wrote:
>
> > I recently upgraded postfix and OpenSSL to 3.4.10 and 1.1.1d,
> > respectively. These versions align with Debian GNU/Linux 10 (buster).
> > Since the upgrade I've begun receiving regular log entries that look
> > like this:
> >
> > May 11 11:23:54 vasaconsulting postfix/smtpd[21870]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
>
> Just in case this is an OpenSSL glitch, you should at this point be
> using OpenSSL 1.1.1g.
>
> That said, it perhaps possible that Postfix is calling SSL_shutdown() on
> a connection that never progressed enough to complete the handshake.
> I'll check what preconditions are needed for OpenSSL to allow the
> SSL_shutdown() call.  We may need some logic to avoid calling it
> too early.

Like this?

    if (!SSL_in_init(tls_context->con)
        && (ssl_stat = SSL_shutdown(tls_context->con)) < 0) {
                log some warning
    }
    // Wrap up.

        Wietse

> That said, this is not the cause of any problems, rather a symptom.
>
> > When it occurs when receiving, the sending mailserver retries sometime
> > later and seems to get through (though I haven't sought to verify
> > repeated failures).
>
> Perhaps some network-layer issues.
>
> --
>     Viktor.
>
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On Mon, May 11, 2020 at 03:52:27PM -0400, Wietse Venema wrote:

> Viktor Dukhovni:
>
> > That said, it perhaps possible that Postfix is calling SSL_shutdown() on
> > a connection that never progressed enough to complete the handshake.
> > I'll check what preconditions are needed for OpenSSL to allow the
> > SSL_shutdown() call.  We may need some logic to avoid calling it
> > too early.
>
> Like this?
>
>     if (!SSL_in_init(tls_context->con)
> && (ssl_stat = SSL_shutdown(tls_context->con)) < 0) {
> log some warning
>     }
>     // Wrap up.

Yes, that's the idea.

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
In reply to this post by Alexander Vasarab
On Mon, May 11, 2020 at 12:51:55PM -0700, Alexander Vasarab wrote:

> 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

The real problem is that the connection was terminated mid-transaction.

The "shutdown while in init" is I think a distraction, Postfix was
cleaning up the TLS session, when it was not yet, or is no longer in a
state that is valid for calling SSL_shutdown().  If you manage to
collect a PCAP capture of the traffic for a failed delivery, it should
be possible (especially if limited to TLS 1.2, which is a bit easier to
debug from TCP captures) to see whether the failure is at the
application or TCP layer.

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

Ideally, they have all the bug fixes from 1.1.1g in the package they're
calling 1.1.1d.

I think your next step is to get a PCAP of the traffic.

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Wietse Venema
In reply to this post by Viktor Dukhovni
Viktor Dukhovni:

> On Mon, May 11, 2020 at 03:52:27PM -0400, Wietse Venema wrote:
>
> > Viktor Dukhovni:
> >
> > > That said, it perhaps possible that Postfix is calling SSL_shutdown() on
> > > a connection that never progressed enough to complete the handshake.
> > > I'll check what preconditions are needed for OpenSSL to allow the
> > > SSL_shutdown() call.  We may need some logic to avoid calling it
> > > too early.
> >
> > Like this?
> >
> >     if (!SSL_in_init(tls_context->con)
> > && (ssl_stat = SSL_shutdown(tls_context->con)) < 0) {
> > log some warning
> >     }
> >     // Wrap up.
>
> Yes, that's the idea.

Then, this should shut up the warning.

        Wietse

--- ./src/tls/tls_session.c- 2019-06-15 19:36:31.000000000 -0400
+++ ./src/tls/tls_session.c 2020-05-11 17:57:18.000000000 -0400
@@ -118,7 +118,7 @@
      * so we will not perform SSL_shutdown() and the session will be removed
      * as being bad.
      */
-    if (!failure) {
+    if (!failure && !SSL_in_init(TLScontext->con)) {
  retval = tls_bio_shutdown(vstream_fileno(stream), timeout, TLScontext);
  if (!var_tls_fast_shutdown && retval == 0)
     tls_bio_shutdown(vstream_fileno(stream), timeout, TLScontext);
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
In reply to this post by Viktor Dukhovni
>The real problem is that the connection was terminated mid-transaction.
>
>The "shutdown while in init" is I think a distraction, Postfix was
>cleaning up the TLS session, when it was not yet, or is no longer in a
>state that is valid for calling SSL_shutdown().  If you manage to
>collect a PCAP capture of the traffic for a failed delivery, it should
>be possible (especially if limited to TLS 1.2, which is a bit easier to
>debug from TCP captures) to see whether the failure is at the
>application or TCP layer.

>I think your next step is to get a PCAP of the traffic.

I've captured the relevant conversation. In doing so, it became clear to
me that when the message succeeds after immediately trying again, it
does so because the subsequent connection does not try to use TLS. So
the pattern is: attempt TLS connection, fail, attempt plaintext
connection, succeed. This was alarming to realize.

 From the pcap, in brief: I see the connection, STARTTLS, TLSv1.2
handshake succeed, "application data" packets being exchanged using
TLSv1.2. Finally, my mail server sends two TCP packets with the RST flag
set. Between those two packets is an 'encrypted alert' packet from the
foreign mailserver.

I'm not certain on the norms of this mailing list but I can put the
entire pcap somewhere if it would be helpful, it's 35 frames long.

Alexander
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On May 11, 2020, at 11:19 PM, Alexander Vasarab <[hidden email]> wrote:

> I've captured the relevant conversation. In doing so, it became clear to
> me that when the message succeeds after immediately trying again, it
> does so because the subsequent connection does not try to use TLS. So
> the pattern is: attempt TLS connection, fail, attempt plaintext
> connection, succeed. This was alarming to realize.
>
> From the pcap, in brief: I see the connection, STARTTLS, TLSv1.2
> handshake succeed, "application data" packets being exchanged using
> TLSv1.2. Finally, my mail server sends two TCP packets with the RST flag
> set. Between those two packets is an 'encrypted alert' packet from the
> foreign mailserver.

The encrypted alert is almost certain to be a close_notify. But you're
saying that your server sends a RST first?  That's surprising, please
post the PCAP file (just the one session), and the associated Postfix
logs.
>
> I'm not certain on the norms of this mailing list but I can put the
> entire pcap somewhere if it would be helpful, it's 35 frames long.

Attaching it is fine, if you're willing to disclose the IP addresses and
hostnames of the two servers.

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
On 11/05/20 23:35 -0400, Viktor Dukhovni wrote:
>Attaching it is fine, if you're willing to disclose the IP addresses and
>hostnames of the two servers.

Okay, I've attached two files; the PCAP and the postfix log.

To clarify my earlier email, the unencrypted session scenario only
arises when I receive mail. It seems that when a foreign mail server
connects to mine to send me a message, it fails, then retries sometime
later NOT over TLS, and that succeeds. When I send mail, it fails the
first time, and then as long as I immediately resend, it succeeds (over
TLS, thankfully).

I've also seen at least one sender (notably, GMAIL) connect, elicit the
SSL_Shutdown error, and yet their message gets queued and delivered
without another try being needed.

Alexander

postfix-SSL_Shutdown.pcap (14K) Download Attachment
postfix-SSL_Shutdown.log (892 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On Mon, May 11, 2020 at 09:17:16PM -0700, Alexander Vasarab wrote:

> On 11/05/20 23:35 -0400, Viktor Dukhovni wrote:
> >Attaching it is fine, if you're willing to disclose the IP addresses and
> >hostnames of the two servers.
>
> Okay, I've attached two files; the PCAP and the postfix log.

Indeed the server slams the TCP socket closed after receiving the
client's RCPT command.  Unclear why.  You might try debug_peer_list
next, to see whether the server can log enough cleartext traffic
to expose the SMTP traffic inside TLS.

    May 11 19:29:06 vasaconsulting postfix/smtpd[14174]: 80D73102C036:
        client=mail1.bemta23.messagelabs.com[67.219.246.1]
    May 11 19:29:06 vasaconsulting postfix/smtpd[14174]:
        lost connection after RCPT from mail1.bemta23.messagelabs.com[67.219.246.1]
    May 11 19:29:06 vasaconsulting postfix/smtpd[14174]:
        disconnect from mail1.bemta23.messagelabs.com[67.219.246.1]
        ehlo=2 starttls=1 mail=1 rcpt=1 commands=5

The server opened a queue file, which by default happens only after the
first recipient is accepted.  Is there really no other logging for this
process at that time?

--
    Viktor.

    -- 3-way TCP
    -- Server greeting
    -- Client EHLO
    -- Server EHLO reply
    -- Client STARTTLS
    -- Server go-ahead

    -- Client TLS HELLO
    [Time since reference or first frame: 0.574920000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 47, Ack: 251, Len: 201
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1 Record Layer: Handshake Protocol: Client Hello

    -- Server TLS HELLO
    [Time since reference or first frame: 0.575167000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 251, Ack: 248, Len: 1448
        Flags: 0x010 (ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Handshake Protocol: Server Hello

    -- Server Certificate and key excahnge
    [Time since reference or first frame: 0.637786000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 1699, Ack: 248, Len: 1448
        Flags: 0x018 (PSH, ACK)
    [Time since reference or first frame: 0.700283000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 3147, Ack: 248, Len: 1448
        Flags: 0x010 (ACK)
    [Time since reference or first frame: 0.762836000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 4595, Ack: 248, Len: 1448
        Flags: 0x018 (PSH, ACK)
    [Time since reference or first frame: 0.762845000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 6043, Ack: 248, Len: 452
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Handshake Protocol: Certificate
    Transport Layer Security
        TLSv1.2 Record Layer: Handshake Protocol: Server Key Exchange
        TLSv1.2 Record Layer: Handshake Protocol: Server Hello Done

    -- Client key exchange, CCS and Finished
    [Time since reference or first frame: 0.826362000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 248, Ack: 6495, Len: 126
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Handshake Protocol: Client Key Exchange
        TLSv1.2 Record Layer: Change Cipher Spec Protocol: Change Cipher Spec
        TLSv1.2 Record Layer: Handshake Protocol: Encrypted Handshake Message

    -- Server Session ticket, CCS and Finished
    [Time since reference or first frame: 0.827649000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 6495, Ack: 374, Len: 226
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Handshake Protocol: New Session Ticket
        TLSv1.2 Record Layer: Change Cipher Spec Protocol: Change Cipher Spec
        TLSv1.2 Record Layer: Handshake Protocol: Encrypted Handshake Message

    -- Client EHLO inside TLS
    [Time since reference or first frame: 0.890215000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 374, Ack: 6721, Len: 65
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Server EHLO reply
    [Time since reference or first frame: 0.890582000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 6721, Ack: 439, Len: 213
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Client MAIL
    [Time since reference or first frame: 0.953134000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 439, Ack: 6934, Len: 62
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Server MAIL reply
    [Time since reference or first frame: 0.955403000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 6934, Ack: 501, Len: 43
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Client RCPT
    [Time since reference or first frame: 1.017831000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 501, Ack: 6977, Len: 56
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Server RCPT reply, with ~1s delay, perhaps the hard error sleep
    -- time?  (was it a 421 or 521 reply?)
    [Time since reference or first frame: 2.159092000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 6977, Ack: 557, Len: 43
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- Server slams the TCP connection closed, no SSL close-notify.
    [Time since reference or first frame: 2.161183000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 7020, Ack: 557, Len: 0
        Flags: 0x011 (FIN, ACK)

    -- Client continues (DATA?, QUIT? ...)
    [Time since reference or first frame: 2.221487000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 557, Ack: 7020, Len: 35
        Flags: 0x018 (PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp

    -- But the socket is closed.
    [Time since reference or first frame: 2.221518000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 7020, Len: 0
        Flags: 0x004 (RST)

    -- Client also closes, including close-notify
    [Time since reference or first frame: 2.223734000 seconds]
    Transmission Control Protocol, Src Port: 59453, Dst Port: 25, Seq: 592, Ack: 7021, Len: 66
        Flags: 0x019 (FIN, PSH, ACK)
    Transport Layer Security
        TLSv1.2 Record Layer: Application Data Protocol: smtp
        TLSv1.2 Record Layer: Encrypted Alert

    -- Server already closed
    [Time since reference or first frame: 2.223750000 seconds]
    Transmission Control Protocol, Src Port: 25, Dst Port: 59453, Seq: 7021, Len: 0
        Flags: 0x004 (RST)
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Andreas Schamanek
FWIW:

On Mon, 11 May 2020, at 21:17, Alexander Vasarab wrote:

> When I send mail, it fails the first time, and then as long as I
> immediately resend, it succeeds (over TLS, thankfully).

I have recently come along this very same pattern when using command
line tools like curl or lynx to access https. The observed pattern
includes the ~10s you mentioned earlier and the fact that it's not
related to versions of TLS or SSL libraries like OpenSSL.

On Tue, 12 May 2020, at 05:40, Viktor Dukhovni wrote:

> Indeed the server slams the TCP socket closed after receiving the
> client's RCPT command.  Unclear why.

This is also what I observed. For the record a typical curl error
message

   curl: (35) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to server:443

Unfortunately, I haven't yet come along a server where I felt
comfortable testing the heck of this out of it. Plus, the servers
where I have observed it did not show the same behavior over the
course of my attempts at debugging it (several hours). So, yes, very
unclear what and why.

One admin I contacted suspected that their provider was trying to
mitigate DOS attacks. But that's too vague an explanation for my
taste.

--
-- Andreas

      :-)

Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
In reply to this post by Viktor Dukhovni
On 12/05/20 05:40 -0400, Viktor Dukhovni wrote:
>Indeed the server slams the TCP socket closed after receiving the
>client's RCPT command.  Unclear why.  You might try debug_peer_list
>next, to see whether the server can log enough cleartext traffic
>to expose the SMTP traffic inside TLS.

Thanks. Using debug_peer_list, I have a few more pieces of information.

May 12 14:27:21 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 235 2.7.0 Authentication successful
May 12 14:27:21 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: < <data scrubbed>[<data scrubbed>]: MAIL FROM:<<data scrubbed>>

...lots of debug info e.g. send attr, etc...

May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.0 Ok
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: < <data scrubbed>[<data scrubbed>]: RCPT TO:<<data scrubbed>>

...lots of debug info e.g. config maps, etc...

May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: smtp_get: EOF

...some match_hostname stuff, etc...

May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: lost connection after RCPT from <data scrubbed>[<data scrubbed>]

...abort milter stuff...

May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: disconnect from <data scrubbed>[<data scrubbed>] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 commands=6

>The server opened a queue file, which by default happens only after the
>first recipient is accepted.  Is there really no other logging for this
>process at that time?

That's correct. Just those three lines (plus the warning about TLS
library issue).

What follows is how the conversation above ended. Different than the
PCAP I attached yesterday, this is me sending an email as opposed to an
email being sent to me (it's easier to use debug_peer_list with a
predictable peer aka myself). There's no Encrypted Alert, and only one
RST. I don't know if that's pertinent or not.

[Time since reference or first frame: 0.861553000 seconds]
Transmission Control Protocol, Src Port: 587, Dst Port: 37049, Seq: 7301, Ack: 748, Len: 0
     Flags: 0x011 (FIN, ACK)

[Time since reference or first frame: 0.907717000 seconds]
Transmission Control Protocol, Src Port: 37049, Dst Port: 587, Seq: 748, Ack: 7302, Len: 28
     Flags: 0x018 (PSH, ACK)
Transport Layer Security
     TLSv1.3 Record Layer: Application Data Protocol: smtp

[Time since reference or first frame: 0.907756000 seconds]
Transmission Control Protocol, Src Port: 587, Dst Port: 37049, Seq: 7302, Len: 0
     Flags: 0x004 (RST)

Alexander
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On Tue, May 12, 2020 at 03:08:16PM -0700, Alexander Vasarab wrote:

> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.0 Ok
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: < <data scrubbed>[<data scrubbed>]: RCPT TO:<<data scrubbed>>
>
> ...lots of debug info e.g. config maps, etc...
>
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
> May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: smtp_get: EOF

That's really weird, your server is closing the connection for no
obvious reason, right after sending a "250 OK" for "RCPT", and with no
indication from the client at either the TLS or TCP layer that there's
no more data.

At this point, clone your submission service onto port 588, and
configure that copy with "smtpd -vvv" + all the other options.
Then use your client to connect to port 588, and there should
now be voluminous logging from the Postfix I/O layer (events
and vstreams).  The question is now whether Postfix is seeing
EOF from OpenSSL and then reciprocating by closing the stream,
or somehow deciding to close the stream (for no obvious reason).

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
On 12/05/20 21:07 -0400, Viktor Dukhovni wrote:
>At this point, clone your submission service onto port 588, and
>configure that copy with "smtpd -vvv" + all the other options.
>Then use your client to connect to port 588, and there should
>now be voluminous logging from the Postfix I/O layer (events
>and vstreams).  The question is now whether Postfix is seeing
>EOF from OpenSSL and then reciprocating by closing the stream,
>or somehow deciding to close the stream (for no obvious reason).

Thanks. I've attached the log, pruned to the important section.

I wish I could offer an interpretation, but I'm ignorant to the arcana
that's on full display in this log.

Alexander

postfix-vvv.log (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On Tue, May 12, 2020 at 07:31:02PM -0700, Alexander Vasarab wrote:

> I wish I could offer an interpretation, but I'm ignorant to the arcana
> that's on full display in this log.

> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: watchdog_pat: 0x5571a55eaa60
> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 17 flush 14

There's a 14-byte write to fd 17 consisting of "250 2.1.5 Ok\r\n", and
then:

> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: smtp_get: EOF
> ...match_hostname/addr stuff...

Once again out of the blue, a lost connection.  The SMTP server is
trying to read the next command after sending "RCPT TO" and encounters
an EOF condition, for no apparent reason.  At this point, I'd guess
your SSL library is broken...

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Alexander Vasarab
On 12/05/20 23:27 -0400, Viktor Dukhovni wrote:
>Once again out of the blue, a lost connection.  The SMTP server is
>trying to read the next command after sending "RCPT TO" and encounters
>an EOF condition, for no apparent reason.  At this point, I'd guess
>your SSL library is broken...

I was able to squeeze a bit more information out using
smtpd_tls_loglevel=4.

May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: watchdog_pat: 0x55e2224ca3f0
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: vstream_fflush_some: fd 17 flush 14
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: Write 14 chars: 250 2.1.5 Ok??
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: write to 55E222534FF0 [55E222542173] (36 bytes => 36 (0x24))
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0000 17 03 03 00 1f df 3e 1c|66 4c e9 c5 07 39 56 6a  ......>. fL...9Vj
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0010 ed 71 92 5b ee e6 8b e5|bd a6 9e 8f 33 68 38 74  .q.[.... ....3h8t
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0020 86 60 a1 32                                      .`.2
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: read from 55E222534FF0 [55E22253E023] (5 bytes => -1 (0xFFFFFFFFFFFFFFFF))
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: smtp_get: EOF
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Viktor Dukhovni
On Tue, May 12, 2020 at 08:59:15PM -0700, Alexander Vasarab wrote:

> On 12/05/20 23:27 -0400, Viktor Dukhovni wrote:
> >Once again out of the blue, a lost connection.  The SMTP server is
> >trying to read the next command after sending "RCPT TO" and encounters
> >an EOF condition, for no apparent reason.  At this point, I'd guess
> >your SSL library is broken...
>
> I was able to squeeze a bit more information out using
> smtpd_tls_loglevel=4.
>
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: watchdog_pat: 0x55e2224ca3f0
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: vstream_fflush_some: fd 17 flush 14
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: Write 14 chars: 250 2.1.5 Ok??
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: write to 55E222534FF0 [55E222542173] (36 bytes => 36 (0x24))
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0000 17 03 03 00 1f df 3e 1c|66 4c e9 c5 07 39 56 6a  ......>. fL...9Vj
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0010 ed 71 92 5b ee e6 8b e5|bd a6 9e 8f 33 68 38 74  .q.[.... ....3h8t
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: 0020 86 60 a1 32                                      .`.2
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: read from 55E222534FF0 [55E22253E023] (5 bytes => -1 (0xFFFFFFFFFFFFFFFF))

That's normal, the socket is non-blocking.

> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
> May 12 20:47:14 vasaconsulting postfix/smtpd[15943]: smtp_get: EOF

What's not normal is lack of an immediate select for read followed by a
retry of the read.  The SSL library is likely reporting EOF instead of
an SSL_ERROR_WANT_READ.  You need to try an updated OpenSSL.

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: "SSL_Shutdown:shutdown while in init" while sending and receiving

Matus UHLAR - fantomas
In reply to this post by Alexander Vasarab
>On 12/05/20 05:40 -0400, Viktor Dukhovni wrote:
>>Indeed the server slams the TCP socket closed after receiving the
>>client's RCPT command.  Unclear why.  You might try debug_peer_list
>>next, to see whether the server can log enough cleartext traffic
>>to expose the SMTP traffic inside TLS.

On 12.05.20 15:08, Alexander Vasarab wrote:

>Thanks. Using debug_peer_list, I have a few more pieces of information.
>
>May 12 14:27:21 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 235 2.7.0 Authentication successful
>May 12 14:27:21 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: < <data scrubbed>[<data scrubbed>]: MAIL FROM:<<data scrubbed>>
>
>...lots of debug info e.g. send attr, etc...
>
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.0 Ok
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: < <data scrubbed>[<data scrubbed>]: RCPT TO:<<data scrubbed>>
>
>...lots of debug info e.g. config maps, etc...
>
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: watchdog_pat: 0x55bec82e41e0
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086:
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: smtp_get: EOF
>
>...some match_hostname stuff, etc...
>
>May 12 14:27:22 vasaconsulting postfix/smtpd[3482]: lost connection after RCPT from <data scrubbed>[<data scrubbed>]

maybe some form of address veriification?

--
Matus UHLAR - fantomas, [hidden email] ; http://www.fantomas.sk/
Warning: I wish NOT to receive e-mail advertising to this address.
Varovanie: na tuto adresu chcem NEDOSTAVAT akukolvek reklamnu postu.
They that can give up essential liberty to obtain a little temporary
safety deserve neither liberty nor safety. -- Benjamin Franklin, 1759
123