OpenSSL connection setup debug callback issue

From: Daniel Gustafsson <daniel(at)yesql(dot)se>
To: Postgres hackers <pgsql-hackers(at)lists(dot)postgresql(dot)org>
Subject: OpenSSL connection setup debug callback issue
Date: 2020-12-10 13:43:33
Message-ID: 232CF476-94E1-42F1-9408-719E2AEC5491@yesql.se
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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 Content-Type Size
0001-Move-information-callback-earlier-to-capture-connect.patch application/octet-stream 4.2 KB

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Bharath Rupireddy 2020-12-10 13:50:29 Re: Parallel Inserts in CREATE TABLE AS
Previous Message Ashutosh Bapat 2020-12-10 13:31:28 Re: Insert Documentation - Returning Clause and Order