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 openssl-users@openssl.org Automated List Manager [EMAIL PROTECTED]