projects / postgresql.git / commitdiff
summary | shortlog | log | commit | commitdiff | tree
raw | patch | inline | side by side (parent: da83b1e)
Re-enable SSL connect_fails tests, and fix related race conditions.
authorTom Lane <tgl@sss.pgh.pa.us>
Tue, 22 Apr 2025 19:10:50 +0000 (15:10 -0400)
committerTom Lane <tgl@sss.pgh.pa.us>
Tue, 22 Apr 2025 19:10:50 +0000 (15:10 -0400)
Cluster.pm's connect_fails routine has long had the ability to
sniff the postmaster log file for expected messages after a
connection failure.  However, that's always had a race condition:
on some platforms it's possible for psql to exit and the test
script to slurp up the postmaster log before the backend process
has been able to write out its final log messages.  Back in
commit 55828a6b6 we disabled a bunch of tests after discovering
that, and the aim of this patch is to re-enable them.

(The sibling function connect_ok doesn't seem to have a similar
problem, mainly because the messages we look for come out during
the authentication handshake, so that if psql reports successful
connection they should certainly have been emitted already.)

The solution used here is borrowed from 002_connection_limits.pl's
connect_fails_wait routine: set the server's log_min_messages setting
to DEBUG2 so that the postmaster will log child-process exit, and then
wait till we see that log entry before checking for the messages we
are actually interested in.

If a TAP test uses connect_fails' log_like or log_unlike options, and
forgets to set log_min_messages, those connect_fails calls will now
hang until timeout.  Fixing up the existing callers shows that we had
several other TAP tests that were in theory vulnerable to the same
problem.  It's unclear whether the lack of failures is just luck, or
lack of buildfarm coverage, or perhaps there is some obscure timing
effect that only manifests in SSL connections.  In any case, this
change should in principle make those other call sites more robust.
I'm not inclined to back-patch though, unless sometime we observe
an actual failure in one of them.

Reported-by: Andrew Dunstan <andrew@dunslane.net>
Author: Tom Lane <tgl@sss.pgh.pa.us>
Discussion: https://postgr.es/m/984fca80-85a8-4c6f-a5cc-bb860950b435@dunslane.net

src/test/authentication/t/001_password.pl patch | blob | blame | history
src/test/authentication/t/003_peer.pl patch | blob | blame | history
src/test/kerberos/t/001_auth.pl patch | blob | blame | history
src/test/ldap/t/001_auth.pl patch | blob | blame | history
src/test/modules/oauth_validator/t/001_server.pl patch | blob | blame | history
src/test/perl/PostgreSQL/Test/Cluster.pm patch | blob | blame | history
src/test/ssl/t/001_ssltests.pl patch | blob | blame | history

diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 756b414605006f8ef52fdf911f55d70d02cfbc2c..37d96d95a1aebdd75957ed59ec32e2b021195878 100644 (file)
--- 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 69ba73bd2b9ae6280a59293e4577c308f57e9a8c..2879800eacfd2b94bb33032356be5bdfde9cee9e 100644 (file)
--- 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 6748b109decf763f9c81306afcdce8428cb463f7..2dc6bec9b89995da559db30616b6e6ba2c746bdf 100644 (file)
--- 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 352b0fc1fa7b2fe14f0e9c5937a3235b0651c99e..d1315ed5351beb6507894a25f94ae639a1b0e5fe 100644 (file)
--- 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 d88994abc2431761ea194a1c093ddb0f17d661db..4f035417a40debf6aefd6975d6ca1e474dbf0989 100644 (file)
--- 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 8759ed2cbba108a1c797d97f271651b09b66e37d..aa5b53167688a95d71e296e411595d8f0e174bc3 100644 (file)
--- 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 086abf3b8b3943c4d230e1a33e6fc2000e1b9b12..8b0de2d8e7e70b02a1a87077de872393cb63658b 100644 (file)
--- 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();
This is the main PostgreSQL git repository.