On Wed, May 13, 2020 at 10:01:24PM -0700, Alexander Vasarab wrote:
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: hsfunc=(nil),
> rfunc=0x7f310ef36dd0, wfunc=(nil), SSL_get_error(36) = 0
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: TLS success
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: AEF2F102C03E:
> client=<data scrubbed>[<data scrubbed>], sasl_method=LOGIN,
> sasl_username=<data scrubbed>
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: hsfunc=(nil),
> rfunc=(nil), wfunc=0x7f310ef37090, SSL_get_error(14) = 0
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: TLS success
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: hsfunc=(nil),
> rfunc=0x7f310ef36dd0, wfunc=(nil), SSL_get_error(-1) = 1
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: tls_bio: TLS layer error
This proves Postfix attempting to call SSL_read, and had not called
SSL_shutdown(), which is also only called via the tls_bio() function,
and would have shown up as a non-nil (NULL pointer) value of "hsfunc".
With a bit of luck Kurt might have something to say some time soon. I'm
out of ideas on the Postfix side, and while I'm also an OpenSSL
committer, I don't know of anything in OpenSSL that would account for
the symptoms you're reporting.
Somehow a call to SSL_read() is returning SSL_ERROR_SSL, with reportedly
untimely calls to SSL_shutdown() on the error stack.
I'f you're comfortable with gdb, and willing to build both Postfix and
OpenSSL from source with debugging symbols, then you could add a "-D"
flag to the "smtpd" entry in the /opt/postfix/etc/master.cf file, and
attach to a "screen" running a debugger on smtpd, setting a breakpoint
in SSL_shutdown, and continue. Then report a stack trace...
http://www.postfix.org/DEBUG_README.html#screen
I can't expect you're that curious, but if you are, go for it. This is
rather a weird case. You may be able to install the debian debug symbol
package for at least OpenSSL, saving the hassle of building the package
yourself. Don't know whether there is also a debug symbol package for
Postfix.
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: warning: TLS library
> problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in
> init:../ssl/ssl_lib.c:2086:
> May 13 21:56:38 vasaconsulting postfix/smtpd[25599]: lost connection after
> RCPT from <data scrubbed>[<data scrubbed>]
This set of symptoms is not consistent with the expected behaviour of
any version OpenSSL I've come across. All the evidence so far looks
quite exculpatory for Postfix. Leaving a possibly mispatched OpenSSL,
or flakey hardware as potential suspects.
--
Viktor.
