Thread: 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
Attachment
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
Attachment
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