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 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();
