Обсуждение: OpenSSL connection setup debug callback issue

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

Hi Daniel,

On Thu, Dec 10, 2020 at 10:43 PM Daniel Gustafsson <daniel@yesql.se> wrote:
>
> 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.

You sent in your patch,
0001-Move-information-callback-earlier-to-capture-connect.patch to
pgsql-hackers on Dec 10, but you did not post it to the next
CommitFest[1].  If this was intentional, then you need to take no
action.  However, if you want your patch to be reviewed as part of the
upcoming CommitFest, then you need to add it yourself before
2021-01-01 AoE[2]. Thanks for your contributions.

Regards,

[1] https://commitfest.postgresql.org/31/
[2] https://en.wikipedia.org/wiki/Anywhere_on_Earth

-- 
Masahiko Sawada
EnterpriseDB:  https://www.enterprisedb.com/

> On 28 Dec 2020, at 13:04, Masahiko Sawada <sawada.mshk@gmail.com> wrote:

> if you want your patch to be reviewed as part of the
> upcoming CommitFest, then you need to add it yourself before
> 2021-01-01 AoE[2]. Thanks for your contributions.

I thought I had added it but clearly I had missed doing so, fixed now.  Thanks
for the reminder!

cheers ./daniel

On Thu, Dec 10, 2020 at 02:43:33PM +0100, Daniel Gustafsson wrote:
> 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).

Looking at the docs, SSL_state_string_long() is better than just
SSL_state_string(), so that sounds right:
https://www.openssl.org/docs/manmaster/man3/SSL_CTX_set_info_callback.html
https://www.openssl.org/docs/manmaster/man3/SSL_state_string.html
https://www.openssl.org/docs/manmaster/man3/SSL_state_string_long.html

This is interesting for debugging, +1 for applying what you have
here, and this works for 1.0.1~3.0.0.  Worth noting that this returns
a static string, as per ssl_stat.c.
--
Michael

On Thu, Jan 21, 2021 at 05:01:15PM +0900, Michael Paquier wrote:
> This is interesting for debugging, +1 for applying what you have
> here, and this works for 1.0.1~3.0.0.  Worth noting that this returns
> a static string, as per ssl_stat.c.

Done as of af0e79c, after an indentation.
--
Michael