Subject: Re: disabled SSL log_like tests

From: Tom Lane <[email-masked]>
Date: Thu, 17 Apr 2025 10:56:25 -0400

Andrew Dunstan <[email-masked]> writes:
> Back in 2022 in commit 55828a6b6084 we disabled a bunch of tests due to 
> a timing issue. Nothing seems to have been done since ... do we still 
> want to keep these commented out lines around? This "temporary" fix 
> seems to have stretched the definition of that term more than somewhat.

Per my coffee cup, "Nothing is as permanent as a temporary fix".

However, I wonder whether Andres' work at 8b886a4e3 could be used
to improve this, either directly or as inspiration?

			regards, tom lane

---

From: Andrew Dunstan <[email-masked]>
Date: Thu, 17 Apr 2025 14:37:55 -0400

> to improve this, either directly or as inspiration?

I don't think so - these tests are about checking log file contents, not 
a psql problem.

cheers

andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

---

From: Tom Lane <[email-masked]>
Date: Fri, 18 Apr 2025 15:45:58 -0400

> I don't think so - these tests are about checking log file contents, not 

Well, I was mainly leaning on the "inspiration" part: the idea
is to wait for something that must come out after the text we
want to look for.  After digging around a bit I noticed that
002_connection_limits.pl's connect_fails_wait is doing something
that's almost what we want: that test cranks log_min_messages
up to DEBUG2 and then waits for the postmaster's report of
backend exit before believing that it's done.

Awhile later I had the attached patch.  Some notes:

* The commented-out tests in 001_ssltests.pl contained hard-wired
expectations as to certificate serial numbers, which are obsolete now.
I just replaced them with "\d+", but if anyone feels like that's not
good enough, we could continue to check for exact serial numbers and
eat the ensuing maintenance effort.

* I was more than slightly surprised to find that there are a bunch of
other connect_fails callers that are testing log_like or log_unlike
and thereby risking the same type of race condition.  Some of those
tests are relatively new and perhaps just haven't failed *yet*,
but I wonder if we changed something since 2022 that solves this
problem in a different way?  Anyway, after this change any such
caller must set log_min_messages = debug2 or fail.  I think I got
all the relevant test scripts in the attached.

			regards, tom lane

diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 756b4146050..37d96d95a1a 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -66,6 +66,8 @@ sub test_conn
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
 $node->append_conf('postgresql.conf', "log_connections = on\n");
+# Needed to allow connect_fails to inspect postmaster log:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->start;
 
 # Test behavior of log_connections GUC
diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 69ba73bd2b9..2879800eacf 100644
--- a/src/test/authentication/t/003_peer.pl
+++ b/src/test/authentication/t/003_peer.pl
@@ -72,6 +72,8 @@ sub test_role
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
 $node->append_conf('postgresql.conf', "log_connections = on\n");
+# Needed to allow connect_fails to inspect postmaster log:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->start;
 
 # Set pg_hba.conf with the peer authentication.
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 6748b109dec..2dc6bec9b89 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -66,6 +66,7 @@ $node->append_conf(
 listen_addresses = '$hostaddr'
 krb_server_keyfile = '$krb->{keytab}'
 log_connections = on
+log_min_messages = debug2
 lc_messages = 'C'
 });
 $node->start;
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 352b0fc1fa7..d1315ed5351 100644
--- a/src/test/ldap/t/001_auth.pl
+++ b/src/test/ldap/t/001_auth.pl
@@ -48,6 +48,8 @@ note "setting up PostgreSQL instance";
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
 $node->append_conf('postgresql.conf', "log_connections = on\n");
+# Needed to allow connect_fails to inspect postmaster log:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test0;');
diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index d88994abc24..4f035417a40 100644
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/src/test/modules/oauth_validator/t/001_server.pl
@@ -48,6 +48,8 @@ $node->init;
 $node->append_conf('postgresql.conf', "log_connections = on\n");
 $node->append_conf('postgresql.conf',
 	"oauth_validator_libraries = 'validator'\n");
+# Needed to allow connect_fails to inspect postmaster log:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test;');
diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 8759ed2cbba..7877cc8d994 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2624,7 +2624,12 @@ If this regular expression is set, matches it with the output generated.
 
 =item log_unlike => [ qr/prohibited message/ ]
 
-See C<log_check(...)>.
+See C<log_check(...)>.  CAUTION: use of either option requires that
+the server's log_min_messages be at least DEBUG2, and that no other
+client backend is launched concurrently.  These requirements allow
+C<connect_fails> to wait to see the postmaster-log report of backend
+exit, without which there is a race condition as to whether we will
+see the expected backend log output.
 
 =back
 
@@ -2652,7 +2657,14 @@ sub connect_fails
 		like($stderr, $params{expected_stderr}, "$test_name: matches");
 	}
 
-	$self->log_check($test_name, $log_location, %params);
+	if (defined($params{log_like}) or defined($params{log_unlike}))
+	{
+		$self->wait_for_log(
+			qr/DEBUG:  (00000: )?client backend.*exited with exit code \d/,
+			$log_location);
+
+		$self->log_check($test_name, $log_location, %params);
+	}
 }
 
 =pod
diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.pl
index 086abf3b8b3..8b0de2d8e7e 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -60,6 +60,8 @@ my $common_connstr;
 note "setting up data directory";
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init;
+# Needed to allow connect_fails to inspect postmaster log:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 
 # PGHOST is enforced here to set up the node, subsequent connections
 # will use a dedicated connection string.
@@ -807,10 +809,8 @@ $node->connect_fails(
 	expected_stderr =>
 	  qr/certificate authentication failed for user "anotheruser"/,
 	# certificate authentication should be logged even on failure
-	# temporarily(?) skip this check due to timing issue
-	#	log_like =>
-	#	  [qr/connection authenticated: identity="CN=ssltestuser" method=cert/],
-);
+	log_like =>
+	  [qr/connection authenticated: identity="CN=ssltestuser" method=cert/],);
 
 # revoked client cert
 $node->connect_fails(
@@ -818,11 +818,10 @@ $node->connect_fails(
 	  . sslkey('client-revoked.key'),
 	"certificate authorization fails with revoked client cert",
 	expected_stderr => qr|SSL error: ssl[a-z0-9/]* alert certificate revoked|,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 0: certificate revoked},
-	#		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656577, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
-	#	],
+	log_like => [
+		qr{Client certificate verification failed at depth 0: certificate revoked},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number \d+, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	],
 	# revoked certificates should not authenticate the user
 	log_unlike => [qr/connection authenticated:/],);
 
@@ -872,24 +871,20 @@ $node->connect_fails(
 	$common_connstr . " " . "sslmode=require sslcert=ssl/client.crt",
 	"intermediate client certificate is missing",
 	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
-	#		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656576, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
-	#	]
-);
+	log_like => [
+		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number \d+, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
 
 $node->connect_fails(
 	"$common_connstr sslmode=require sslcert=ssl/client-long.crt "
 	  . sslkey('client-long.key'),
 	"logged client certificate Subjects are truncated if they're too long",
 	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
-	#		qr{Failed certificate data \(unverified\): subject "\.\.\./CN=ssl-123456789012345678901234567890123456789012345678901234567890", serial number 2315418733629425152, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
-	#	]
-);
+	log_like => [
+		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "\.\.\./CN=ssl-123456789012345678901234567890123456789012345678901234567890", serial number \d+, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
 
 # Use an invalid cafile here so that the next test won't be able to verify the
 # client CA.
@@ -904,12 +899,10 @@ $node->connect_fails(
 	"$common_connstr sslmode=require sslcert=ssl/client+client_ca.crt",
 	"intermediate client certificate is untrusted",
 	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 1: unable to get local issuer certificate},
-	#		qr{Failed certificate data \(unverified\): subject "/CN=Test CA for PostgreSQL SSL regression test client certs", serial number 2315134995201656577, issuer "/CN=Test root CA for PostgreSQL SSL regression test suite"},
-	#	]
-);
+	log_like => [
+		qr{Client certificate verification failed at depth 1: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "/CN=Test CA for PostgreSQL SSL regression test client certs", serial number \d+, issuer "/CN=Test root CA for PostgreSQL SSL regression test suite"},
+	]);
 
 # test server-side CRL directory
 switch_server_cert(
@@ -923,12 +916,10 @@ $node->connect_fails(
 	  . sslkey('client-revoked.key'),
 	"certificate authorization fails with revoked client cert with server-side CRL directory",
 	expected_stderr => qr|SSL error: ssl[a-z0-9/]* alert certificate revoked|,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 0: certificate revoked},
-	#		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656577, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
-	#	]
-);
+	log_like => [
+		qr{Client certificate verification failed at depth 0: certificate revoked},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number \d+, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
 
 # revoked client cert, non-ASCII subject
 $node->connect_fails(
@@ -936,11 +927,9 @@ $node->connect_fails(
 	  . sslkey('client-revoked-utf8.key'),
 	"certificate authorization fails with revoked UTF-8 client cert with server-side CRL directory",
 	expected_stderr => qr|SSL error: ssl[a-z0-9/]* alert certificate revoked|,
-	# temporarily(?) skip this check due to timing issue
-	#	log_like => [
-	#		qr{Client certificate verification failed at depth 0: certificate revoked},
-	#		qr{Failed certificate data \(unverified\): subject "/CN=\\xce\\x9f\\xce\\xb4\\xcf\\x85\\xcf\\x83\\xcf\\x83\\xce\\xad\\xce\\xb1\\xcf\\x82", serial number 2315420958437414144, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
-	#	]
-);
+	log_like => [
+		qr{Client certificate verification failed at depth 0: certificate revoked},
+		qr{Failed certificate data \(unverified\): subject "/CN=\\xce\\x9f\\xce\\xb4\\xcf\\x85\\xcf\\x83\\xcf\\x83\\xce\\xad\\xce\\xb1\\xcf\\x82", serial number \d+, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
 
 done_testing();

---

From: Jacob Champion <[email-masked]>
Date: Fri, 18 Apr 2025 13:08:43 -0700

> eat the ensuing maintenance effort.

No, I think \d+ should be fine.

(I haven't stared closely at the racing code yet, but I like the
concept of the patch.)

Thanks!
--Jacob