Andrew Dunstan <and...@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 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();
