OpenSSL connection setup debug callback issue

Started by Daniel Gustafssonabout 5 years ago5 messages

daniel@yesql.se

about 5 years ago

1 attachment(s)

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

Attachments:

0001-Move-information-callback-earlier-to-capture-connect.patchapplication/octet-stream; name=0001-Move-information-callback-earlier-to-capture-connect.patch; x-unix-mode=0644Download

From e3cc0496ad8b66b7786c3cb6aab944e972cf715d Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <daniel@yesql.se>
Date: Thu, 10 Dec 2020 14:29:06 +0100
Subject: [PATCH] Move information callback earlier to capture connection

The callback for retrieving state change information during connection
setup was only installed when the connection was mostly set up, and
thus didn't provide much information. This also extends the callback
with printing detailed information about the state change.

While there, fix up a few comments which were incorrectly referring
to the callback and its previous location.
---
 src/backend/libpq/be-secure-openssl.c    | 26 ++++++++++++++----------
 src/interfaces/libpq/fe-secure-openssl.c |  2 +-
 src/interfaces/libpq/fe-secure.c         |  6 ------
 3 files changed, 16 insertions(+), 18 deletions(-)

diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index e10260051f..e8626721a2 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -381,6 +381,9 @@ be_tls_open_server(Port *port)
 		return -1;
 	}
 
+	/* set up debugging/info callback */
+	SSL_CTX_set_info_callback(SSL_context, info_cb);
+
 	if (!(port->ssl = SSL_new(SSL_context)))
 	{
 		ereport(COMMERROR,
@@ -562,9 +565,6 @@ aloop:
 		port->peer_cert_valid = true;
 	}
 
-	/* set up debugging/info callback */
-	SSL_CTX_set_info_callback(SSL_context, info_cb);
-
 	return 0;
 }
 
@@ -999,39 +999,43 @@ verify_cb(int ok, X509_STORE_CTX *ctx)
 static void
 info_cb(const SSL *ssl, int type, int args)
 {
+	const char	   *desc;
+
+	desc = SSL_state_string_long(ssl);
+
 	switch (type)
 	{
 		case SSL_CB_HANDSHAKE_START:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: handshake start")));
+					(errmsg_internal("SSL: handshake start: \"%s\"", desc)));
 			break;
 		case SSL_CB_HANDSHAKE_DONE:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: handshake done")));
+					(errmsg_internal("SSL: handshake done: \"%s\"", desc)));
 			break;
 		case SSL_CB_ACCEPT_LOOP:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: accept loop")));
+					(errmsg_internal("SSL: accept loop: \"%s\"", desc)));
 			break;
 		case SSL_CB_ACCEPT_EXIT:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: accept exit (%d)", args)));
+					(errmsg_internal("SSL: accept exit (%d): \"%s\"", args, desc)));
 			break;
 		case SSL_CB_CONNECT_LOOP:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: connect loop")));
+					(errmsg_internal("SSL: connect loop: \"%s\"", desc)));
 			break;
 		case SSL_CB_CONNECT_EXIT:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: connect exit (%d)", args)));
+					(errmsg_internal("SSL: connect exit (%d): \"%s\"", args, desc)));
 			break;
 		case SSL_CB_READ_ALERT:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: read alert (0x%04x)", args)));
+					(errmsg_internal("SSL: read alert (0x%04x): \"%s\"", args, desc)));
 			break;
 		case SSL_CB_WRITE_ALERT:
 			ereport(DEBUG4,
-					(errmsg_internal("SSL: write alert (0x%04x)", args)));
+					(errmsg_internal("SSL: write alert (0x%04x): \"%s\"", args, desc)));
 			break;
 	}
 }
diff --git a/src/interfaces/libpq/fe-secure-openssl.c b/src/interfaces/libpq/fe-secure-openssl.c
index d609a38bbe..4d5906163b 100644
--- a/src/interfaces/libpq/fe-secure-openssl.c
+++ b/src/interfaces/libpq/fe-secure-openssl.c
@@ -14,7 +14,7 @@
  * NOTES
  *
  *	  We don't provide informational callbacks here (like
- *	  info_cb() in be-secure.c), since there's no good mechanism to
+ *	  info_cb() in be-secure-openssl.c), since there's no good mechanism to
  *	  display such information to the user.
  *
  *-------------------------------------------------------------------------
diff --git a/src/interfaces/libpq/fe-secure.c b/src/interfaces/libpq/fe-secure.c
index 97c3805303..a7048988c8 100644
--- a/src/interfaces/libpq/fe-secure.c
+++ b/src/interfaces/libpq/fe-secure.c
@@ -13,12 +13,6 @@
  * IDENTIFICATION
  *	  src/interfaces/libpq/fe-secure.c
  *
- * NOTES
- *
- *	  We don't provide informational callbacks here (like
- *	  info_cb() in be-secure.c), since there's no good mechanism to
- *	  display such information to the user.
- *
  *-------------------------------------------------------------------------
  */
 
-- 
2.21.1 (Apple Git-122.3)

Masahiko Sawada

sawada.mshk@gmail.com

about 5 years ago

In reply to: Daniel Gustafsson (#1)

Re: OpenSSL connection setup debug callback issue

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]https://commitfest.postgresql.org/31/. 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]https://en.wikipedia.org/wiki/Anywhere_on_Earth. 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/

Daniel Gustafsson

daniel@yesql.se

about 5 years ago

In reply to: Masahiko Sawada (#2)

Re: OpenSSL connection setup debug callback issue

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

Michael Paquier

michael@paquier.xyz

almost 5 years ago

In reply to: Daniel Gustafsson (#1)

Re: OpenSSL connection setup debug callback issue

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

Michael Paquier

michael@paquier.xyz

almost 5 years ago

In reply to: Michael Paquier (#4)

Re: OpenSSL connection setup debug callback issue

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