Thread: disabled SSL log_like tests
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. (noticed when looking into a different issue). cheers andrew -- Andrew Dunstan EDB: https://www.enterprisedb.com
Andrew Dunstan <andrew@dunslane.net> 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
On 2025-04-17 Th 10:56 AM, Tom Lane wrote: > Andrew Dunstan <andrew@dunslane.net> 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? > > 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
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();
On Fri, Apr 18, 2025 at 12:46 PM Tom Lane <tgl@sss.pgh.pa.us> wrote: > * 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. 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
I wrote:
> * 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?
Nope, apparently not. The failure depends on the kernel's scheduler,
so unsurprisingly it's quite platform-dependent. But I can reproduce
it reliably on mamba's host (NetBSD 10/macppc) if I enable the
001_ssltests.pl log_like tests without applying the connect_fails
changes.
The fact that mamba hasn't been failing on the other affected
tests is a bit puzzling. mamba isn't running kerberos or ldap
or oauth_validator, so the lack of failures there is expected.
authentication/t/001_password.pl appears accidentally not vulnerable:
it's not using log_like in any connect_fails tests. (It is using
log_unlike, so those tests could be giving silent false negatives.)
But authentication/t/003_peer.pl has 8 test cases that look
vulnerable. I guess there must be some extra dollop of timing
weirdness in the ssl tests that's not there in 003_peer.pl.
Unfortunately ... it sometimes fails even with the connect_fails
changes, for example
# Failed test 'intermediate client certificate is missing: log matches'
# at /home/tgl/pgsql/src/test/ssl/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 2666.
# '2025-04-18 17:59:19.358 EDT [1460] DEBUG: assigned pm child slot 2 for backend
# 2025-04-18 17:59:19.359 EDT [1460] DEBUG: forked new client backend, pid=599 socket=8
# 2025-04-18 17:59:19.369 EDT [599] [unknown] LOG: connection received: host=localhost port=63709
# 2025-04-18 17:59:19.436 EDT [1460] DEBUG: releasing pm child slot 1
# 2025-04-18 17:59:19.436 EDT [1460] DEBUG: client backend (PID 25401) exited with exit code 0
# '
# doesn't match '(?^:Client certificate verification failed at depth 0: unable to get local issuer certificate)'
What I think happened here is that a previous backend hadn't exited
yet when we start the test, and when its report does come out,
connect_fails prematurely stops waiting. (In the above, evidently
the child process we want to wait for is 599, but we're fooled by
a delayed report for 25401.) So my v1 patch needs work.
Maybe we can make the test compare the PIDs in the "forked new client
backend" and "client backend exited" log messages. Stay tuned...
regards, tom lane
I wrote:
> What I think happened here is that a previous backend hadn't exited
> yet when we start the test, and when its report does come out,
> connect_fails prematurely stops waiting. (In the above, evidently
> the child process we want to wait for is 599, but we're fooled by
> a delayed report for 25401.) So my v1 patch needs work.
> Maybe we can make the test compare the PIDs in the "forked new client
> backend" and "client backend exited" log messages. Stay tuned...
Okay, this version seems more reliable.
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..4b858900139 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2618,13 +2618,19 @@ to fail.
=item expected_stderr => B<value>
-If this regular expression is set, matches it with the output generated.
+If this regular expression is set, matches it to the output generated
+by B<psql>.
=item log_like => [ qr/required message/ ]
=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 +2658,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: )?forked new client backend, pid=(\d+) socket.*DEBUG: (?:00000: )?client backend
\(PID\1\) exited with exit code \d/s,
+ $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();
On 2025-04-18 Fr 7:26 PM, Tom Lane wrote: > I wrote: >> What I think happened here is that a previous backend hadn't exited >> yet when we start the test, and when its report does come out, >> connect_fails prematurely stops waiting. (In the above, evidently >> the child process we want to wait for is 599, but we're fooled by >> a delayed report for 25401.) So my v1 patch needs work. >> Maybe we can make the test compare the PIDs in the "forked new client >> backend" and "client backend exited" log messages. Stay tuned... > Okay, this version seems more reliable. > +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. That seems a little fragile. I can imagine test authors easily forgetting this. Is it worth sanity checking to make sure log_min_messages is appropriately set? cheers andrew > -- Andrew Dunstan EDB: https://www.enterprisedb.com
Andrew Dunstan <andrew@dunslane.net> writes:
> On 2025-04-18 Fr 7:26 PM, Tom Lane wrote:
> +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.
> That seems a little fragile. I can imagine test authors easily
> forgetting this. Is it worth sanity checking to make sure
> log_min_messages is appropriately set?
Setting log_min_messages is not so easily forgotten, because
connect_fails will just hang until timeout if you didn't.
I'm more worried about the "no other backend" requirement.
I think v2 is reasonably proof against that, but whether it's
sufficiently bulletproof to withstand the buildfarm environment
remains to be seen. I wish there were a better way to
determine the backend PID for a failed connection...
regards, tom lane