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 <[email protected]>
Reviewed-by: Noah Misch <[email protected]>
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
index dbfd82e4fac2ba6b32e328772a2cdb30167462e7..c611a61cf4e63325ece117315f024c9c0b76539c 100644 (file)
--- 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} = '';