From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@lists.postgresql.org
Subject: IPC::Run::time[r|out] vs our TAP tests
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <1100653.1712265791.0@sss.pgh.pa.us>
Date: Thu, 04 Apr 2024 17:24:05 -0400
Message-ID: <1100715.1712265845@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/1100715.1712265845%40sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <1100653.1712265791.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable

TIL that IPC::Run::timer is not the same as IPC::Run::timeout.
With a timer object you have to check $timer->is_expired to see
if the timeout has elapsed, but with a timeout object you don't
because it will throw a Perl exception upon timing out, probably
killing your test program.

It appears that a good chunk of our TAP codebase has not read this
memo, because I see plenty of places that are checking is_expired
in the naive belief that they'll still have control after a timeout
has fired.

The particular thing that started me down this road was wondering
why we are getting no useful failure details from buildfarm member
tanager's struggles with the tab-completion test case added by commit
927332b95 [1].  Apparently it's not seeing a match to what it expects
so it eventually times out, but all we get in the log is

[03:03:42.595](0.002s) ok 82 - complete an interpolated psql variable name
[03:03:42.597](0.002s) ok 83 - \\r works
IPC::Run: timeout on timer #1 at /usr/share/perl5/IPC/Run.pm line 2944.
# Postmaster PID for node "main" is 17308
### Stopping node "main" using mode immediate

We would have learned something useful if control had returned to
pump_until, or even better 010_tab_completion.pl's check_completion,
but it doesn't.

A minimum fix that seems to make this work better is as attached,
but I feel like somebody ought to examine all the IPC::Run::timer
and IPC::Run::timeout calls and see which ones are mistaken.
It's a little scary to convert a timeout to a timer because of
the hazard that someplace that would need to be checking for
is_expired isn't.

Also, the debug printout code at the bottom of check_completion
is quite useless, because control can never reach it since
BackgroundPsql::query_until will "die" on failure.  I think that
that code worked when written, and I'm suspicious that 664d75753
broke it, but I've not dug deeply into the history.

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dtanager&dt=3D=
2024-04-04%2016%3A56%3A14


------- =_aaaaaaaaaa0
Content-Type: text/x-diff;
	name="use-timer-not-timeout-in-BackgroundPsql.patch";
	charset="us-ascii"
Content-ID: <1100653.1712265791.2@sss.pgh.pa.us>
Content-Description: use-timer-not-timeout-in-BackgroundPsql.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm b/src/test/pe=
rl/PostgreSQL/Test/BackgroundPsql.pm
index 4091c311b8..72bb21e160 100644
--- a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
+++ b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
@@ -96,7 +96,7 @@ sub new
 	  "Forbidden caller of constructor: package: $package, file: $file:$line=
"
 	  unless $package->isa('PostgreSQL::Test::Cluster');
 =

-	$psql->{timeout} =3D IPC::Run::timeout(
+	$psql->{timeout} =3D IPC::Run::timer(
 		defined($timeout)
 		? $timeout
 		: $PostgreSQL::Test::Utils::timeout_default);
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/Postgr=
eSQL/Test/Utils.pm
index 42d5a50dc8..8fd0426d30 100644
--- a/src/test/perl/PostgreSQL/Test/Utils.pm
+++ b/src/test/perl/PostgreSQL/Test/Utils.pm
@@ -429,6 +429,7 @@ Pump until string is matched on the specified stream, =
or timeout occurs.
 sub pump_until
 {
 	my ($proc, $timeout, $stream, $until) =3D @_;
+	die "timeout should be a timer" if defined($timeout->exception);
 	$proc->pump_nb();
 	while (1)
 	{

------- =_aaaaaaaaaa0--