tests: BackgroundPsql: Fix potential for lost errors on windows

anarazel · anarazel · commit bb2bf22761e1 · 2025-02-19T10:46:49.000-05:00
This addresses various corner cases in BackgroundPsql: - On windows stdout and stderr may arrive out of order, leading to errors not being reported, or attributed to the wrong statement. To fix, emit the "query-separation banner" on both stdout and stderr and wait for both. - Very occasionally the "query-separation banner" would not get removed, because we waited until the banner arrived, but then replaced the banner plus newline. To fix, wait for banner and newline. - For interactive psql replacing $banner\n is not sufficient, interactive psql outputs \r\n. - For interactive psql, where commands are echoed to stdout, the \echo command, rather than its output, would be matched. This would sometimes lead to output from the prior query, or wait_connect(), being returned in the next command. This also affected wait_connect(), leading to sometimes sending queries to psql before the connection actually was established. While debugging these issues I also found that it's hard to know whether a query separation banner was attributed to the right query. Make that easier by counting the queries each BackgroundPsql instance has emitted and include the number in the banner. Also emit psql stdout/stderr in query() and wait_connect() as Test::More notes, without that it's rather hard to debug some issues in CI and buildfarm. As this can cause issues not just to-be-added tests, but also existing ones, backpatch the fix to all supported versions. Reviewed-by: Daniel Gustafsson <daniel@yesql.se> Reviewed-by: Noah Misch <noah@leadboat.com> Discussion: https://postgr.es/m/wmovm6xcbwh7twdtymxuboaoarbvwj2haasd3sikzlb3dkgz76@n45rzycluzft Backpatch-through: 13
diff --git a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
@@ -89,7 +89,8 @@ sub new
 		'stdin' => '',
 		'stdout' => '',
 		'stderr' => '',
-		'query_timer_restart' => undef
+		'query_timer_restart' => undef,
+		'query_cnt' => 1,
 	};
 	my $run;
 
@@ -148,11 +149,25 @@ sub wait_connect
 	# connection failures are caught here, relieving callers of the need to
 	# handle those.  (Right now, we have no particularly good handling for
 	# errors anyway, but that might be added later.)
+	#
+	# See query() for details about why/how the banner is used.
 	my $banner = "background_psql: ready";
-	$self->{stdin} .= "\\echo $banner\n";
+	my $banner_match = qr/(^|\n)$banner\r?\n/;
+	$self->{stdin} .= "\\echo $banner\n\\warn $banner\n";
 	$self->{run}->pump()
-	  until $self->{stdout} =~ /$banner/ || $self->{timeout}->is_expired;
-	$self->{stdout} = '';    # clear out banner
+	  until ($self->{stdout} =~ /$banner_match/
+		  && $self->{stderr} =~ /$banner\r?\n/)
+	  || $self->{timeout}->is_expired;
+
+	note "connect output:\n",
+	  explain {
+		stdout => $self->{stdout},
+		stderr => $self->{stderr},
+	  };
+
+	# clear out banners
+	$self->{stdout} = '';
+	$self->{stderr} = '';
 
 	die "psql startup timed out" if $self->{timeout}->is_expired;
 }
@@ -219,27 +234,57 @@ sub query
 	my ($self, $query) = @_;
 	my $ret;
 	my $output;
+	my $query_cnt = $self->{query_cnt}++;
+
 	local $Test::Builder::Level = $Test::Builder::Level + 1;
 
-	note "issuing query via background psql: $query";
+	note "issuing query $query_cnt via background psql: $query";
 
 	$self->{timeout}->start() if (defined($self->{query_timer_restart}));
 
 	# Feed the query to psql's stdin, followed by \n (so psql processes the
 	# line), by a ; (so that psql issues the query, if it doesn't include a ;
-	# itself), and a separator echoed with \echo, that we can wait on.
-	my $banner = "background_psql: QUERY_SEPARATOR";
-	$self->{stdin} .= "$query\n;\n\\echo $banner\n";
-
-	pump_until($self->{run}, $self->{timeout}, \$self->{stdout}, qr/$banner/);
+	# itself), and a separator echoed both with \echo and \warn, that we can
+	# wait on.
+	#
+	# To avoid somehow confusing the separator from separately issued queries,
+	# and to make it easier to debug, we include a per-psql query counter in
+	# the separator.
+	#
+	# We need both \echo (printing to stdout) and \warn (printing to stderr),
+	# because on windows we can get data on stdout before seeing data on
+	# stderr (or vice versa), even if psql printed them in the opposite
+	# order. We therefore wait on both.
+	#
+	# We need to match for the newline, because we try to remove it below, and
+	# it's possible to consume just the input *without* the newline. In
+	# interactive psql we emit \r\n, so we need to allow for that. Also need
+	# to be careful that we don't e.g. match the echoed \echo command, rather
+	# than its output.
+	my $banner = "background_psql: QUERY_SEPARATOR $query_cnt:";
+	my $banner_match = qr/(^|\n)$banner\r?\n/;
+	$self->{stdin} .= "$query\n;\n\\echo $banner\n\\warn $banner\n";
+	pump_until(
+		$self->{run}, $self->{timeout},
+		\$self->{stdout}, qr/$banner_match/);
+	pump_until(
+		$self->{run}, $self->{timeout},
+		\$self->{stderr}, qr/$banner_match/);
 
 	die "psql query timed out" if $self->{timeout}->is_expired;
-	$output = $self->{stdout};
 
-	# Remove banner again, our caller doesn't care.  The first newline is
-	# optional, as there would not be one if consuming an empty query
-	# result.
-	$output =~ s/\n?$banner\n$//s;
+	note "results query $query_cnt:\n",
+	  explain {
+		stdout => $self->{stdout},
+		stderr => $self->{stderr},
+	  };
+
+	# Remove banner from stdout and stderr, our caller doesn't care.  The
+	# first newline is optional, as there would not be one if consuming an
+	# empty query result.
+	$output = $self->{stdout};
+	$output =~ s/$banner_match//;
+	$self->{stderr} =~ s/$banner_match//;
 
 	# clear out output for the next query
 	$self->{stdout} = '';
