When a user requests SSL protocol debug logging from Postfix, we use
essentially boilerplate code from SSL_CTX_set_info_callback(3):
... initialiation ...
if (where & SSL_CB_LOOP)
{
BIO_printf(bio_err,"%s:%s\n",str,SSL_state_string_long(s)
);
}
... alert case ...
else if (where & SSL_CB_EXIT)
{
if (ret == 0)
BIO_printf(bio_err,"%s:failed in %s\n",
str,SSL_state_string_long(s));
else if (ret < 0)
{
BIO_printf(bio_err,"%s:error in %s\n",
str,SSL_state_string_long(s));
}
}
Now (my conjecture) because Postfix uses biopairs for I/O, with
reads/writes to/from the network triggered by SSL_ERR_WANT_READ and
SSL_ERR_WANT_WRITE events, the debug log looks as follows (sans the
constant "SSL_accept:" prefix):
before/accept initialization
error in SSLv2/v3 read client hello A
error in SSLv3 read client hello B
error in SSLv3 read client hello B
SSLv3 read client hello B
SSLv3 write server hello A
SSLv3 write certificate A
SSLv3 write key exchange A
SSLv3 write certificate request A
SSLv3 flush data
error in SSLv3 read client certificate A
error in SSLv3 read client certificate A
SSLv3 read client certificate A
error in SSLv3 read client key exchange A
error in SSLv3 read client key exchange A
SSLv3 read client key exchange A
error in SSLv3 read certificate verify A
error in SSLv3 read certificate verify A
SSLv3 read certificate verify A
error in SSLv3 read finished A
SSLv3 read finished A
SSLv3 write change cipher spec A
SSLv3 write finished A
SSLv3 flush data
The "error in SSL" lines always confuse users who believe something is
going wrong. I tested suppressing these as follows (Postfix logs
via msg_info(...) rather than BIO_printf(bio_err, ...)):
... initialiation, loop, alerts, ...
} else if (where & SSL_CB_EXIT) {
if (ret == 0)
msg_info("%s:failed in %s",
str, SSL_state_string_long((SSL *) s));
else if (ret < 0) {
switch(SSL_get_error((SSL *)s, ret)) {
case SSL_ERROR_WANT_READ:
case SSL_ERROR_WANT_WRITE:
break;
default:
msg_info("%s:error in %s",
str, SSL_state_string_long((SSL *) s));
break;
}
}
}
What is new here is the call to SSL_get_error() to skip the WANT_READ
and WANT_WRITE cases, only logging other (unexpected) errors. Is this
approach sound? Is it safe to call SSL_get_error() from the info callback,
or might it modify the SSL state in some unsupport fashion. The logging
I get is now:
before/accept initialization
SSLv3 read client hello B
SSLv3 write server hello A
SSLv3 write certificate A
SSLv3 write key exchange A
SSLv3 write certificate request A
SSLv3 flush data
SSLv3 read client certificate A
SSLv3 read client key exchange A
SSLv3 read certificate verify A
SSLv3 read finished A
SSLv3 write change cipher spec A
SSLv3 write finished A
SSLv3 flush data
No remaining "error" cases at all, and likey more useful to users. I am
hoping this is a correct analysis and sensible solution...
--
Viktor.
______________________________________________________________________
OpenSSL Project http://www.openssl.org
User Support Mailing List [email protected]
Automated List Manager [EMAIL PROTECTED]
