Subject: Re: BackgroundPsql swallowing errors on windows

From: Andres Freund <[email-masked]>
Date: Sun, 16 Feb 2025 13:02:01 -0500

Hi,

On 2025-02-16 09:39:43 -0800, Noah Misch wrote:
> On Thu, Feb 13, 2025 at 12:39:04PM -0500, Andres Freund wrote:
> > I suspect what's happening is that the communication with the
> > external process allows for reordering between stdout/stderr.
> > 
> > And indeed, changing BackgroundPsql::query() to emit the banner on both stdout
> > and stderr and waiting on both seems to fix the issue.
> 
> That makes sense.  I wondered how one might fix IPC::Run to preserve the
> relative timing of stdout and stderr, not perturbing the timing the way that
> disrupted your test run.  I can think of two strategies:
> 
> - Remove the proxy.
> 
> - Make pipe data visible to Perl variables only when at least one of the
>   proxy<-program_under_test pipes had no data ready to read.  In other words,
>   if both pipes have data ready, make all that data visible to Perl code
>   simultaneously.  (When both the stdout pipe and the stderr pipe have data
>   ready, one can't determine data arrival order.)
> 
> Is there a possibly-less-invasive change that might work?

I don't really know enough about IPC::Run's internals to answer. My
interpretation of how it might work, purely from observation, is that it opens
one tcp connection for each "pipe" and that that's what's introducing the
potential of reordering, as the different sockets can have different delivery
timeframes.  If that's it, it seems proxying all the pipes through one
connection might be an option.

I did briefly look at IPC::Run's code, but couldn't figure out how it all fits
together quickly enough...

> v2 of the patch looks fine.

Thanks for reviewing!

Greetings,

Andres Freund

---

From: Noah Misch <[email-masked]>
Date: Sun, 16 Feb 2025 10:47:40 -0800

On Sun, Feb 16, 2025 at 01:02:01PM -0500, Andres Freund wrote:
> timeframes.

Right.

> If that's it, it seems proxying all the pipes through one

It would.  Thanks.  However, I think that would entail modifying the program
under test to cooperate with the arrangement.  When running an ordinary
program that does write(1, ...) and write(2, ...), the read end needs some way
to deal with the uncertainty about which write happened first.  dup2(1, 2)
solves the order ambiguity, but it loses other signal.

> together quickly enough...

We can ignore what IPC::Run does today.  The reordering is a general problem
of proxying >1 pipe.  (Proxying on non-Windows would have the same problem.)

---

From: Andres Freund <[email-masked]>
Date: Sun, 16 Feb 2025 15:55:10 -0500

Hi,

> solves the order ambiguity, but it loses other signal.

I think what's happening in this case must go beyond just that. Afaict just
doing ->pump_nb() would otherwise solve it. My uninformed theory is that two
tcp connections are used. With two pipes

P1: write(1)
P1: write(2)
P2: read(1)
P2: read(2)

wouldn't ever result in P2 not seeing data on either of reads. But with two
TCP sockets there can be time between the send() completing and recv() on the
other side reading the data, even on a local system (e.g. due to the tcp stack
waiting a while for more data before sending data).

To avoid that the proxy program could read from N pipes and then proxy them
through *one* socket by prefixing the data with information about which pipe
the data is from. Then IPC::Run could split the data again, using the added
prefix.

I don't think that would require modifying the program under test?

Greetings,

Andres Freund

---

From: Noah Misch <[email-masked]>
Date: Sun, 16 Feb 2025 14:39:51 -0800

> > > seems proxying all the pipes through one
> wouldn't ever result in P2 not seeing data on either of reads.

True.

> But with two

I think that gets an order anomaly when the proxy is slow and the program
under test does this:

write(2, "ERROR: 1")
write(1, "BANNER 1")
write(2, "ERROR: 2")
write(1, "BANNER 2")

If the proxy is sufficiently fast, it will wake up four times and perform two
read() calls on each of the two pipes.  On the flip side, if the proxy is
sufficiently slow, it will wake up once and perform one read() on each of the
two pipes.  In the slow case, the reads get "ERROR: 1ERROR: 2" and "BANNER
1BANNER 2".  The proxy sends the data onward as though the program under test
had done:

write(1, "BANNER 1BANNER 2")
write(2, "ERROR: 1ERROR: 2")

>From the slow proxy's perspective, it can't rule out the program under test
having done those two write() calls.  The proxy doesn't have enough
information to reconstruct the original four write() calls.  What prevents
that anomaly?

If the proxy were to convey this uncertainty so the consumer side knew to
handle these writes as an atomic unit, I think that would work:

write(n, "proxy-begin")
write(n, "fd-1[BANNER 1BANNER 2]")
write(n, "fd-2[ERROR: 1ERROR: 2]")
write(n, "proxy-commit")

---

From: Tom Lane <[email-masked]>
Date: Sun, 16 Feb 2025 18:18:44 -0500

> information to reconstruct the original four write() calls.  What prevents

Yeah, I think it's hopeless to expect that we can disambiguate the
order of writes to two different pipes.  For the problem at hand,
though, it seems like we don't really need to do that.  Rather, the
question is "when we detect that the program-under-test has exited,
can we be sure we have collected all of its output?".  I think that
IPC::Run may be screwing up here, because I have seen non-Windows
CI failures that look like it didn't read all the stderr output.
For example, this pgbench test failure on macOS from [1]:

# Running: pgbench -n -t 1 -Dfoo=bla -Dnull=null -Dtrue=true -Done=1 -Dzero=0.0 -Dbadtrue=trueXXX -Dmaxint=9223372036854775807 -Dminint=-9223372036854775808 -M prepared -f /Users/admin/pgsql/build/testrun/pgbench/001_pgbench_with_server/data/t_001_pgbench_with_server_main_data/001_pgbench_error_shell_bad_command
[17:27:47.408](0.061s) ok 273 - pgbench script error: shell bad command status (got 2 vs expected 2)
[17:27:47.409](0.000s) ok 274 - pgbench script error: shell bad command stdout /(?^:processed: 0/1)/
[17:27:47.409](0.000s) not ok 275 - pgbench script error: shell bad command stderr /(?^:\(shell\) .* meta-command failed)/
[17:27:47.409](0.000s) #   Failed test 'pgbench script error: shell bad command stderr /(?^:\(shell\) .* meta-command failed)/'
#   at /Users/admin/pgsql/src/bin/pgbench/t/001_pgbench_with_server.pl line 1466.
#                   ''
#     doesn't match '(?^:\(shell\) .* meta-command failed)'

The program's exited with a failure code as expected, and we saw (some
of?) the expected stdout output, but stderr output is reported to be
empty.

			regards, tom lane

[1] https://cirrus-ci.com/task/6221238034497536

---

From: Andres Freund <[email-masked]>
Date: Sun, 16 Feb 2025 18:58:29 -0500

Hi,

On 2025-02-16 18:18:44 -0500, Tom Lane wrote:
> can we be sure we have collected all of its output?".

That's what my patch upthread tries to achieve by having a query separator
both on stdout and stderr and waiting for both.

> I think that IPC::Run may be screwing up here, because I have seen
> non-Windows CI failures that look like it didn't read all the stderr output.

It's possible this is caused by the same issue as on windows. Or by one of the
other things fixed in the patch, a) there's afaict no guarantee that we'd read
from pipe A if we were waiting for A|B and B got ready b) that we weren't
actually waiting for quite all the output to be generated (missing the
newline).  Or it could be because psql doesn't actually flush stderr in all
patch, from what I can tell...

I hope it'll be easier to debug with the patch in place if it doesn't turn out
to already be fixed.

Greetings,

Andres Freund

---

From: Noah Misch <[email-masked]>
Date: Sun, 16 Feb 2025 15:58:43 -0800

> can we be sure we have collected all of its output?".

In the BackgroundPsql case, we have output collection moments for every query
while the psql-under-test is running, not just after exit.  If I understand
the original post right, the specifics are as follows.  If $stdout witnesses
the result of '\echo BANNER', $stderr should contain anything from psql
commands before the \echo.  That holds on non-Windows, but the IPC::Run proxy
makes it not hold on Windows.

> I think that

https://github.com/cpan-authors/IPC-Run/commit/2128df3bbcac7e733ac46302c4b1371ffb88fe14
fixed that one.

---

From: Tom Lane <[email-masked]>
Date: Sun, 16 Feb 2025 19:50:18 -0500

> https://github.com/cpan-authors/IPC-Run/commit/2128df3bbcac7e733ac46302c4b1371ffb88fe14

Ah.  Do we know whether that fix has made it into our CI images?
(Or anywhere else, for that matter?)

			regards, tom lane

---

From: Andres Freund <[email-masked]>
Date: Sun, 16 Feb 2025 20:42:50 -0500

Hi, 

>(Or anywhere else, for that matter?)

The CI images are regenerated three times a week, but for most OSs, they will only install perl modules via the applicable packaging method, so it'll depend on when they pick up that version.

On Windows cpan is used, so it should pick that new version fairly quickly if a release has been made.

On macos we can't currently use images, so we just cache all the installed macports packages. The cache is keyed by OS version and list of packages to be installed, with no other forced invalidation right now. So it's hard to predict when a new version of a package will be picked up and it will differ between git repositories.  I've been wondering whether the cached macports install should just be regularly generated instead, along the other ci images.

Greetings, 

Andres
-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

---

From: Noah Misch <[email-masked]>
Date: Sun, 16 Feb 2025 17:52:36 -0800

> On macos we can't currently use images, so we just cache all the installed macports packages. The cache is keyed by OS version and list of packages to be installed, with no other forced invalidatio…

The change is not in a release yet.  We could have macos install IPC::Run from
github, or I could get a release cut so it can make its way to macports.
https://ports.macports.org/port/p5.34-ipc-run/builds/ suggests it ingested the
last release within a couple days of release, so macports itself may add
negligible latency.

---

From: Andres Freund <[email-masked]>
Date: Sun, 16 Feb 2025 20:56:05 -0500

Hi, 

>On Windows cpan is used, so it should pick that new version fairly quickly if a release has been made.

Looks like no release has happened since late 2023:

https://github.com/cpan-authors/IPC-Run/blob/master/Changelog

So it won't be picked up for now. 

I guess we could make CI pick up the git version, but that doesn't really seem like a scalable approach.

Greetings, 

Andres

---

From: Tom Lane <[email-masked]>
Date: Sun, 16 Feb 2025 21:01:55 -0500

> last release within a couple days of release, so macports itself may add

Yeah, my experience is that macports is pretty quick about picking up
new releases.  If you can persuade upstream to make a release happen,
that'd be great.

			regards, tom lane

---

From: Thomas Munro <[email-masked]>
Date: Mon, 17 Feb 2025 15:18:01 +1300

> connection might be an option.

I had a couple of ideas about how to get rid of the intermediate
subprocess.  Obviously it can't convert "two pipes are ready" into two
separate socket send() calls that preserve the original order, as it
doesn't know them (unless perhaps it switches to completion-based
I/O).  But really, the whole design is ugly and slow.  If we have some
capacity to improve Run::IPC, I think we should try to get rid of the
pipe/socket bridge and plug either a pipe or a socket directly into
the target subprocess.  But which one?

1.  Pipes only:  Run::IPC could use IOCP or WaitForMultipleEvents()
instead of select()/poll().
2.  Sockets only: Apparently you can give sockets directly to
subprocesses as stdin/stdout/stderr:

https://stackoverflow.com/questions/4993119/redirect-io-of-process-to-windows-socket

The Run::IPC comments explain that the extra process was needed to be
able to forward all data even if the target subprocess exits without
closing the socket (the linger stuff we have met before in PostgreSQL
itself).  I suspect that if we went that way, maybe asynchronous I/O
would fix that too (see my other thread with guesses and demos on that
topic), but it might not be race-free.  I don't know.  I'd like to
know for PostgreSQL's own sake, but for Run::IPC I think I'd prefer
option 1 anyway: if you have to write new native Windows API
interactions either way, you might as well go with the normal native
way for Windows processes to connect standard I/O streams.

---

From: Andres Freund <[email-masked]>
Date: Sun, 9 Mar 2025 12:47:34 -0400

Hi,

On 2025-02-16 17:52:36 -0800, Noah Misch wrote:
> > On macos we can't currently use images, so we just cache all the installed
> > macports packages. The cache is keyed by OS version and list of packages
> > to be installed, with no other forced invalidation right now. So it's hard
> > to predict when a new version of a package will be picked up and it will
> > differ between git repositories.  I've been wondering whether the cached
> > macports install should just be regularly generated instead, along the
> > other ci images.
> 

It'd be great if we could get a release.  I guess I can figure out the magic
incantations to install it from git for CI, but that doesn't help every
individual developer encountering this issue. Only a release can eventually do
that...

I just hit it twice in an hour or so, once on CI and once locally on a mac
mini when trying to reproduce a separate issue.

Greetings,

Andres Freund

---

From: Noah Misch <[email-masked]>
Date: Sun, 9 Mar 2025 10:23:55 -0700

On Sun, Mar 09, 2025 at 12:47:34PM -0400, Andres Freund wrote:
> It'd be great if we could get a release.

Yep.  I put the tree in the necessary state, and I contacted the person on
2025-02-17 and again on 2025-03-04.  I'm scheduled to follow up again on
2025-03-11.

> I guess I can figure out the magic
> incantations to install it from git for CI

There's no need to build anything, so it suffices to do:

git clone https://github.com/cpan-authors/IPC-Run.git
export PERL5LIB=$PWD/IPC-Run/lib
# (or append, if you already have non-empty PERL5LIB)

---

From: Noah Misch <[email-masked]>
Date: Sun, 10 Aug 2025 11:48:21 -0700

On Sun, Mar 09, 2025 at 10:23:55AM -0700, Noah Misch wrote:
> Yep.  I put the tree in the necessary state, and [...]

https://metacpan.org/dist/IPC-Run is now a fresh release, and
https://ports.macports.org/search/?q=ipc-run&name=on shows that version.

---

From: Tom Lane <[email-masked]>
Date: Sun, 10 Aug 2025 15:07:43 -0400

> https://ports.macports.org/search/?q=ipc-run&name=on shows that version.

That's great news, but apparently there is some lag in new packages
actually becoming available for download:

$ sudo port selfupdate
--->  Checking for newer releases of MacPorts
MacPorts base version 2.11.4 installed,
MacPorts base version 2.11.4 available.
--->  MacPorts base is already the latest version
--->  Updating the ports tree

The ports tree has been updated.
All installed ports are up to date.
$ port installed | grep ipc
  p5.34-ipc-run @20231003.0.0_0 (active)

			regards, tom lane

---

From: Noah Misch <[email-masked]>
Date: Sat, 16 Aug 2025 10:59:03 -0700

>   p5.34-ipc-run @20231003.0.0_0 (active)

Hmm.  I've never used MacPorts, so I'll probably not be an informed
commentator on its release flow.  If relevant (probably not):
https://ports.macports.org/port/p5.34-ipc-run/details/ does show missing "Port
Health" for Sequoia (x86_64), Sonoma (arm64), and Sonoma (x86_64).  Meanwhile,
https://ports.macports.org/port/p5.34-ipc-run/builds/ shows all builds of this
version happening in a <10min span, with no failures.  If there's some "port"
command mode to force an install from source, that might bypass the blockage.

---

From: Tom Lane <[email-masked]>
Date: Sat, 16 Aug 2025 15:13:28 -0400

> Health" for Sequoia (x86_64), Sonoma (arm64), and Sonoma (x86_64).

Dunno, but it is there now: after another upgrade run,

$ port installed | grep ipc
  p5.34-ipc-run @20250809.0.0_0 (active)

I've updated all my macOS buildfarm animals to this version.

			regards, tom lane

---

From: Arseniy Mukhin <[email-masked]>
Date: Sat, 27 Sep 2025 21:39:07 +0300

Hi,

I think I encountered the bug that relates to the patch from this
thread so I decided to write a report here.

version(): PostgreSQL 19devel on x86_64-linux, compiled by gcc-13.3.0,
64-bit. (master)

While writing a TAP test I noticed that background_psql hangs on a
simple query without any reason. The most simple reproducer I came up
with:

my $psql = $node->background_psql('postgres', timeout => 3);
$psql->query(q(\warn AAAAA));
$psql->query("select 1");

Here $psql->query("select 1;") hangs until timeout.

Here what I managed to understand after some investigation:

Just to remind how banner and banner_match look like:

    my $banner = "background_psql: QUERY_SEPARATOR $query_cnt:";
    my $banner_match = qr/(^|\n)$banner\r?\n/;

psql->query() hangs in an endless loop in pump_until() as the
termination condition (last if $$stream =~ /$until/) is never met.
Unfortunately, logs don't show the reason why we are stuck here (maybe
I do something wrong but it seems that [0] explains why pump_until()
timeout diag code doesn't work), so to get more information we need to
add some additional logging in pump_until(). If we add logging of
$$stream and $until then we can see next lines for pump_until() stderr
call:

STREAM: AAAAAbackground_psql: QUERY_SEPARATOR 2:
UNTIL: (?^:(^|\n)background_psql: QUERY_SEPARATOR 2:\r?\n)

STREAM here is what we have in stderr and UNTIL is just a banner_match.

You can see that we have stderr from the previous query ('AAAAA')
concatenated with the banner on the same line. So it doesn't match
what we have in $until pattern as it requires (^|\n) to be before the
banner. This way we have an endless loop. It seems that the reason we
don't have line separator after 'AAAAA' is a difference between how we
inject and remove the banner:

Here is a how we inject banner:

$self->{stdin} .= "$query\n;\n\\echo $banner\n\\warn $banner\n";

How we remove banner from stderr

$self->{stderr} =~ s/$banner_match//;

We remove from stderr not only the banner we previously injected with
warn, but also the line separator before the banner.

[0] https://www.postgresql.org/message-id/flat/[email-masked]

Best regards,
Arseniy Mukhin