Hi,
On 2025-02-14 13:35:40 +0100, Daniel Gustafsson wrote:
> > On 13 Feb 2025, at 18:39, Andres Freund <and...@anarazel.de> wrote:
>
> > The banner being the same between queries made it hard to understand if a
> > banner that appeared in the output was from the current query or a past
> > query. Therefore I added a counter to it.
>
> + 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/);
>
> Won't this allow "QUERY_SEPARATOR 11" to match against "QUERY_SEPARATOR 1"?
> It's probably only of academic interest but appending an end-of-banner
> character like "_" or something after the query counter should fix that.
You're right. I went with ":".
Thanks for reviewing!
Updated patch attached.
I also applied similar changes to wait_connect(), it had the same issues as
query(). This mostly matters for interactive_psql() uses. The fact that we
matched on the \echo itself, lead to the first query() having additional query
output, along the lines of
\echo background_psql: ready
psql (18devel)
Type "help" for help.
postgres=# \echo background_psql: ready
background_psql: ready
Which is rather confusing and can throw off checks based on the query results.
It does seem rather weird that psql outputs its input twice in this case, but
that's a separate issue.
I was thinking that this really ought to be backported, debugging failures due
to the set of fied bugs is really painful (just cost me 1 1/2 days), but
unfortunately there have been a bunch of recent changes that haven't been
backpatched:
commit 70291a3c66e
Author: Michael Paquier <mich...@paquier.xyz>
Date: 2024-11-07 12:11:27 +0900
Improve handling of empty query results in BackgroundPsql::query()
commit ba08edb0654
Author: Michael Paquier <mich...@paquier.xyz>
Date: 2024-11-06 15:31:14 +0900
Extend Cluster.pm's background_psql() to be able to start asynchronously
Particularly the former makes it hard to backpatch, as it's a behavioural
difference that really interacts with the problems described in this thread.
Michael, Jacob, thoughts?
Greetings,
Andres Freund
>From 0bea4887adabd458cdefa4d9fcb4c1a4baefc12a Mon Sep 17 00:00:00 2001
From: Andres Freund <and...@anarazel.de>
Date: Thu, 13 Feb 2025 10:09:49 -0500
Subject: [PATCH v2] tests: BackgroundPsql: Fix potential for lost errors on
windows
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 <dan...@yesql.se>
Discussion: https://postgr.es/m/wmovm6xcbwh7twdtymxuboaoarbvwj2haasd3sikzlb3dkgz76@n45rzycluzft
Backpatch-through: 13
---
.../perl/PostgreSQL/Test/BackgroundPsql.pm | 74 +++++++++++++++----
1 file changed, 59 insertions(+), 15 deletions(-)
diff --git a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
index dbfd82e4fac..2fd44c1f867 100644
--- 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,24 @@ 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 +233,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;
+
+ 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};
-
- # 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;
+ $output =~ s/$banner_match//;
+ $self->{stderr} =~ s/$banner_match//;
# clear out output for the next query
$self->{stdout} = '';
--
2.48.1.76.g4e746b1a31.dirty
