Re: disabled SSL log_like tests - Mailing list pgsql-hackers

Andrew Dunstan <andrew@dunslane.net> writes:
> On 2025-04-17 Th 10:56 AM, Tom Lane wrote:
>> However, I wonder whether Andres' work at 8b886a4e3 could be used
>> 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.

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
forPostgreSQL 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
forPostgreSQL 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=TestCA 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
PostgreSQLSSL 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
forPostgreSQL 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=TestCA for PostgreSQL SSL regression test client certs"}, 
+    ]);

 done_testing();