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

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