I went looking at the SSL connection state change information callback we
install when setting up connections with OpenSSL, and I wasn't getting the
state changes I expected. Turns out we install it at the tail end of setting
up the connection so we miss most of the calls. Moving it to the beginning of
be_tls_open_server allows us to catch the handshake etc. I also extended it by
printing the human readable state change message available from OpenSSL to make
the logs more detailed (SSL_state_string_long has existed since 0.9.8).
A randomly selected sequence from a src/test/ssl testrun with the callback
moved but not extended with state information:
LOG: connection received: host=localhost port=51177
DEBUG: SSL: handshake start
DEBUG: SSL: accept loop
DEBUG: SSL: accept exit (-1)
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept exit (-1)
DEBUG: SSL: accept exit (-1)
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: accept loop
DEBUG: SSL: handshake done
DEBUG: SSL: accept exit (1)
DEBUG: SSL connection from "(anonymous)"
The same sequence with the patch applied:
LOG: connection received: host=localhost port=51177
DEBUG: SSL: handshake start: "before/accept initialization"
DEBUG: SSL: accept loop: "before/accept initialization"
DEBUG: SSL: accept exit (-1): "SSLv2/v3 read client hello A"
DEBUG: SSL: accept loop: "SSLv3 read client hello A"
DEBUG: SSL: accept loop: "SSLv3 write server hello A"
DEBUG: SSL: accept loop: "SSLv3 write certificate A"
DEBUG: SSL: accept loop: "SSLv3 write key exchange A"
DEBUG: SSL: accept loop: "SSLv3 write certificate request A"
DEBUG: SSL: accept loop: "SSLv3 flush data"
DEBUG: SSL: accept exit (-1): "SSLv3 read client certificate A"
DEBUG: SSL: accept exit (-1): "SSLv3 read client certificate A"
DEBUG: SSL: accept loop: "SSLv3 read client certificate A"
DEBUG: SSL: accept loop: "SSLv3 read client key exchange A"
DEBUG: SSL: accept loop: "SSLv3 read certificate verify A"
DEBUG: SSL: accept loop: "SSLv3 read finished A"
DEBUG: SSL: accept loop: "SSLv3 write change cipher spec A"
DEBUG: SSL: accept loop: "SSLv3 write finished A"
DEBUG: SSL: accept loop: "SSLv3 flush data"
DEBUG: SSL: handshake done: "SSL negotiation finished successfully"
DEBUG: SSL: accept exit (1): "SSL negotiation finished successfully"
DEBUG: SSL connection from "(anonymous)"
The attached contains these two changes as well as comment fixups which Heikki
noticed.
cheers ./daniel