oauth_validator: Avoid races in log_check()

jchampio · jchampio · commit ab8af1db4303 · 2025-12-17T11:46:05.000-08:00
Commit e0f373e fixed up races in Cluster::connect_fails when using log_like. t/002_client.pl didn't get the memo, though, because it doesn't use Test::Cluster to perform its custom hook tests. (This is probably not an issue at the moment, since the log check is only done after authentication success and not failure, but there's no reason to wait for someone to hit it.) Introduce the fix, based on debug2 logging, to its use of log_check() as well, and move the logic into the test() helper so that any additions don't need to continually duplicate it. Reviewed-by: Chao Li <li.evan.chao@gmail.com> Discussion: https://postgr.es/m/CAOYmi%2BmrGg%2Bn_X2MOLgeWcj3v_M00gR8uz_D7mM8z%3DdX1JYVbg%40mail.gmail.com Backpatch-through: 18
diff --git a/src/test/modules/oauth_validator/t/002_client.pl b/src/test/modules/oauth_validator/t/002_client.pl
@@ -29,6 +29,8 @@
 $node->append_conf('postgresql.conf', "log_connections = all\n");
 $node->append_conf('postgresql.conf',
 	"oauth_validator_libraries = 'validator'\n");
+# Needed to inspect postmaster log after connection failure:
+$node->append_conf('postgresql.conf', "log_min_messages = debug2");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test;');
@@ -47,7 +49,7 @@
 });
 $node->reload;
 
-my $log_start = $node->wait_for_log(qr/reloading configuration files/);
+$node->wait_for_log(qr/reloading configuration files/);
 
 $ENV{PGOAUTHDEBUG} = "UNSAFE";
 
@@ -73,6 +75,7 @@ sub test
 	my @cmd = ("oauth_hook_client", @{$flags}, $common_connstr);
 	note "running '" . join("' '", @cmd) . "'";
 
+	my $log_start = -s $node->logfile;
 	my ($stdout, $stderr) = run_command(\@cmd);
 
 	if (defined($params{expected_stdout}))
@@ -88,6 +91,18 @@ sub test
 	{
 		is($stderr, "", "$test_name: no stderr");
 	}
+
+	if (defined($params{log_like}))
+	{
+		# See Cluster::connect_fails(). To avoid races, we have to wait for the
+		# postmaster to flush the log for the finished connection.
+		$node->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_start);
+
+		$node->log_check("$test_name: log matches",
+			$log_start, log_like => $params{log_like});
+	}
 }
 
 test(
@@ -97,11 +112,8 @@ sub test
 		"--expected-uri", "$issuer/.well-known/openid-configuration",
 		"--expected-scope", $scope,
 	],
-	expected_stdout => qr/connection succeeded/);
-
-$node->log_check("validator receives correct token",
-	$log_start,
-	log_like => [ qr/oauth_validator: token="my-token", role="$user"/, ]);
+	expected_stdout => qr/connection succeeded/,
+	log_like => [qr/oauth_validator: token="my-token", role="$user"/]);
 
 if ($ENV{with_libcurl} ne 'yes')
 {
