Re: OpenSSL connection setup debug callback issue

Hi Daniel,

On Thu, Dec 10, 2020 at 10:43 PM Daniel Gustafsson <daniel(at)yesql(dot)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/