Date: Wed, 5 Mar 2025 20:49:33 -0800
From: Noah Misch <noah@leadboat.com>
To: Andres Freund <andres@anarazel.de>
Cc: Tomas Vondra <tomas@vondra.me>, Heikki Linnakangas <hlinnaka@iki.fi>,
	Thomas Munro <thomas.munro@gmail.com>,
	"pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Subject: Re: Refactoring postmaster's code to cleanup after child exit
Message-ID: <20250306044933.7a.nmisch@google.com>
References: <a77061d9-1a76-470c-b18c-4f238342d124@iki.fi>
 <8f2118b9-79e3-4af7-b2c9-bd5818193ca4@iki.fi>
 <CA+hUKGKWqSFoJXzRC9D0owFj1Xby0qvWr-k6p8z9gQzT7+nr7w@mail.gmail.com>
 <e9e58efa-a364-4f4f-b112-a11d62af952a@iki.fi>
 <a102f15f-eac4-4ff2-af02-f9ff209ec66f@iki.fi>
 <poxjp7ireyrvk37o4rq3vm2b3otzhmg3ui4ptnfilyiemns4jt@pbqmi2u5y5rb>
 <8e710eaa-fcfe-4a0b-ae90-87743083e777@iki.fi>
 <af1f0c44-c23c-42f0-98fb-e715ef780f76@iki.fi>
 <82eb454e-f9e0-433c-89f5-69f03b09ca32@vondra.me>
 <sllzoxbck2wlnbqcqa36i7fge4l6rkiwy4lp56tmn556b4phhy@45ogfqbsd32i>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <sllzoxbck2wlnbqcqa36i7fge4l6rkiwy4lp56tmn556b4phhy@45ogfqbsd32i>
User-Agent: Mutt/2.2.12 (2023-09-09)
Archived-At: 
 <https://www.postgresql.org/message-id/20250306044933.7a.nmisch%40google.com>
Precedence: bulk

On Tue, Mar 04, 2025 at 05:50:34PM -0500, Andres Freund wrote:
> On 2024-12-09 00:12:32 +0100, Tomas Vondra wrote:
> > [23:48:44.444](1.129s) ok 3 - reserved_connections limit
> > [23:48:44.445](0.001s) ok 4 - reserved_connections limit: matches
> > process ended prematurely at
> > /home/user/work/postgres/src/test/postmaster/../../../src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
> > line 154.
> > # Postmaster PID for node "primary" is 198592
> 
> 
> I just saw this failure on skink in the BF:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2025-03-04%2015%3A43%3A23
> 
> [17:05:56.438](0.247s) ok 3 - reserved_connections limit
> [17:05:56.438](0.000s) ok 4 - reserved_connections limit: matches
> process ended prematurely at /home/bf/bf-build/skink-master/HEAD/pgsql/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm line 160.
> 
> 
> > That BackgroundPsql.pm line is this in wait_connect()
> > 
> >   $self->{run}->pump()
> >     until $self->{stdout} =~ /$banner/ || $self->{timeout}->is_expired;
> 
> A big part of the problem here imo is the exception behaviour that
> IPC::Run::pump() has:
> 
>   If pump() is called after all harnessed activities have completed, a "process
>   ended prematurely" exception to be thrown.  This allows for simple scripting
>   of external applications without having to add lots of error handling code at
>   each step of the script:
> 
> Which is, uh, not very compatible with how we use IPC::Run (here and
> elsewhere).  Just ending the test because a connection failed is pretty awful.

Historically, I think we've avoided this sort of trouble by doing pipe I/O
only on processes where we feel able to predict when the process will exit.
Commit f44b9b6 is one example (simpler case, not involving pump()).  It would
be a nice improvement to do better, since there's always some risk of
unexpected exit.

> This behaviour makes it really hard to debug problems. It'd have been a lot
> easier to understand the problem if we'd seen psql's stderr before the test
> died.
> 
> I guess that mean at the very least we'd need to put an eval {} around the
> ->pump() call., print $self->{stdout}, ->{stderr} and reraise an error?

That sounds right.

Officially, you could call ->pumpable() before ->pump().  It's defined as
'Returns TRUE if calling pump() won't throw an immediate "process ended
prematurely" exception.'  I lack high confidence that it avoids the exception,
because the pump() still calls pumpable()->reap_nb()->waitpid(WNOHANG) and may
decide "process ended prematurely" based on the new finding.  In other words,
I bet there would be a TOCTOU defect in "$h->pump if $h->pumpable".

> Presumably not just in in wait_connect(), but also at least in pump_until()?

If the goal is to have it capture maximum data from processes that exit when
we don't expect it (seems good to me), yes.