Victor Duchovni wrote:
> 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..
Hi Victor,
your analysis is correct. The info callback is not very sensible when it
comes to the non-blocking case.
Your approach comes with an upside and a downside. What you are
seeing with your approach is more a view to the SSL handshake
state (which may be better understandable for the users).
You are however (as a developer) loosing the information about
additional calls being necessary to complete read/write operations.
Best regards,
Lutz
______________________________________________________________________
OpenSSL Project http://www.openssl.org
User Support Mailing List [email protected]
Automated List Manager [EMAIL PROTECTED]
