public inbox for [email protected]  
help / color / mirror / Atom feed
From: Daniel Gustafsson <[email protected]>
To: Tom Lane <[email protected]>
Cc: [email protected]
Subject: Re: IPC::Run::time[r|out] vs our TAP tests
Date: Tue, 9 Apr 2024 19:10:07 +0200
Message-ID: <[email protected]> (raw)
In-Reply-To: <[email protected]>
References: <[email protected]>
	<[email protected]>



> On 4 Apr 2024, at 23:46, Daniel Gustafsson <[email protected]> wrote:
> 
>> On 4 Apr 2024, at 23:24, Tom Lane <[email protected]> wrote:
> 
>> 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.
> 
> Skimming this and a few callsites it seems reasonable to use a timer instead of
> a timeout, but careful study is needed to make sure we're not introducing
> anything subtly wrong in the other direction.

Sharing a few preliminary results from looking at this, the attached passes
check-world but need more study/testing.

It seems wrong to me that we die() in query and query_until rather than giving
the caller the power to decide how to proceed.  We have even documented that we
do just this:

	"Dies on failure to invoke psql, or if psql fails to connect.  Errors
	occurring later are the caller's problem"

Turning the timeout into a timer and returning undef along with logging a test
failure in case of expiration seems a bit saner (maybe Andrew can suggest an
API which has a better Perl feel to it).  Most callsites don't need any changes
to accommodate for this, the attached 0002 implements this timer change and
modify the few sites that need it, converting one to plain query() where the
added complexity of query_until isn't required.

A few other comments on related things that stood out while reviewing:

The tab completion test can use the API call for automatically restart the
timer to reduce the complexity of check_completion a hair.  Done in 0001 (but
really not necessary).

Commit Af279ddd1c2 added this sequence to 040_standby_failover_slots_sync.pl in
the recovery tests:

	$back_q->query_until(
	    qr/logical_slot_get_changes/, q(
	   \echo logical_slot_get_changes
	   SELECT pg_logical_slot_get_changes('test_slot', NULL, NULL);
	));

	... <other tests> ...

	# Since there are no slots in standby_slot_names, the function
	# pg_logical_slot_get_changes should now return, and the session can be
	# stopped.
	$back_q->quit;

There is no guarantee that pg_logical_slot_get_changes has returned when
reaching this point.  This might still work as intended, but the comment is
slightly misleading IMO.


recovery/t/043_wal_replay_wait.pl calls pg_wal_replay_wait() since 06c418e163e
in a background session which it then skips terminating.  Calling ->quit is
mandated by the API, in turn required by IPC::Run.  Calling ->quit on the
process makes the test fail from the process having already exited, but we can
call ->finish directly like we do in test_misc/t/005_timeouts.pl.  0003 fixes
this.

--
Daniel Gustafsson





Attachments:

  [application/octet-stream] v1-0001-Configure-interactive-instance-to-restart-timer.patch (1.6K, ../[email protected]/2-v1-0001-Configure-interactive-instance-to-restart-timer.patch)
  download | inline diff:
From 18d5801553beaebb7575dee9a7122c375b3f2e17 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Tue, 9 Apr 2024 17:58:25 +0200
Subject: [PATCH v1 1/3] Configure interactive instance to restart timer

Use the published API from BackgroundPsql for automatically restarting
the timer rather than manually reaching into it to achieve the same
thing.
---
 src/bin/psql/t/010_tab_completion.pl | 7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/src/bin/psql/t/010_tab_completion.pl b/src/bin/psql/t/010_tab_completion.pl
index b45c39f0f5..54be55ade3 100644
--- a/src/bin/psql/t/010_tab_completion.pl
+++ b/src/bin/psql/t/010_tab_completion.pl
@@ -77,8 +77,10 @@ close $FH;
 # for possible debugging purposes.
 my $historyfile = "${PostgreSQL::Test::Utils::log_path}/010_psql_history.txt";
 
-# fire up an interactive psql session
+# fire up an interactive psql session and configure it such that each query
+# restarts the timer
 my $h = $node->interactive_psql('postgres', history_file => $historyfile);
+$h->set_query_timer_restart();
 
 # Simple test case: type something and see if psql responds as expected
 sub check_completion
@@ -88,9 +90,6 @@ sub check_completion
 	# report test failures from caller location
 	local $Test::Builder::Level = $Test::Builder::Level + 1;
 
-	# restart per-command timer
-	$h->{timeout}->start($PostgreSQL::Test::Utils::timeout_default);
-
 	# send the data to be sent and wait for its result
 	my $out = $h->query_until($pattern, $send);
 	my $okay = ($out =~ $pattern && !$h->{timeout}->is_expired);
-- 
2.39.3 (Apple Git-146)



  [application/octet-stream] v1-0002-Report-test-failure-rather-than-aborting-in-case-.patch (4.8K, ../[email protected]/3-v1-0002-Report-test-failure-rather-than-aborting-in-case-.patch)
  download | inline diff:
From 4e7187b824b1a1df3144775eceb40bd996a2f3df Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Tue, 9 Apr 2024 18:00:17 +0200
Subject: [PATCH v1 2/3] Report test failure rather than aborting in case of
 timeout

When an querying an interactive, or background, psql process the call
would die() in case of a timeout since it used the IPC::Run timeout
construct and not a timer. This aborts tests prematurely which makes
debugging harder, and stops getting results for the remaining tests
in the suite. This converts to using a timer object instead which
will transfer control back to the caller regardless, returning undef
in case of a timeout along with logging a test failure. Affected
callsites are also updated to reflect this.
---
 src/test/modules/test_misc/t/005_timeouts.pl    |  6 +-----
 src/test/perl/PostgreSQL/Test/BackgroundPsql.pm | 15 ++++++++++-----
 src/test/recovery/t/031_recovery_conflict.pl    |  4 +---
 src/test/recovery/t/037_invalid_database.pl     |  1 +
 4 files changed, 13 insertions(+), 13 deletions(-)

diff --git a/src/test/modules/test_misc/t/005_timeouts.pl b/src/test/modules/test_misc/t/005_timeouts.pl
index a792610231..8e7086402c 100644
--- a/src/test/modules/test_misc/t/005_timeouts.pl
+++ b/src/test/modules/test_misc/t/005_timeouts.pl
@@ -109,11 +109,7 @@ $node->safe_psql('postgres',
 
 # We just initialize the GUC and wait. No transaction is required.
 $psql_session = $node->background_psql('postgres');
-$psql_session->query_until(
-	qr/starting_bg_psql/, q(
-   \echo starting_bg_psql
-   SET idle_session_timeout to '10ms';
-));
+$psql_session->query(q(SET idle_session_timeout to '10ms';));
 
 # Wait until the backend enters the timeout injection point.
 $node->wait_for_event('client backend', 'idle-session-timeout');
diff --git a/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm b/src/test/perl/PostgreSQL/Test/BackgroundPsql.pm
index 4091c311b8..5df972a20d 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} = IPC::Run::timeout(
+	$psql->{timeout} = IPC::Run::timer(
 		defined($timeout)
 		? $timeout
 		: $PostgreSQL::Test::Utils::timeout_default);
@@ -148,7 +148,8 @@ sub _wait_connect
 =item $session->quit
 
 Close the session and clean up resources. Each test run must be closed with
-C<quit>.
+C<quit>.  Returns TRUE when the session was cleanly terminated, otherwise
+FALSE.  A testfailure will be issued in case the session failed to finish.
 
 =cut
 
@@ -158,7 +159,9 @@ sub quit
 
 	$self->{stdin} .= "\\q\n";
 
-	return $self->{run}->finish;
+	my $ret = $self->{run}->finish;
+	ok($ret, 'Terminating interactive psql session');
+	return $ret;
 }
 
 =pod
@@ -219,7 +222,8 @@ sub query
 
 	pump_until($self->{run}, $self->{timeout}, \$self->{stdout}, qr/$banner/);
 
-	die "psql query timed out" if $self->{timeout}->is_expired;
+	isnt($self->{timeout}->is_expired, 'psql query timed out');
+	return undef if $self->{timeout}->is_expired;
 	$output = $self->{stdout};
 
 	# remove banner again, our caller doesn't care
@@ -278,7 +282,8 @@ sub query_until
 
 	pump_until($self->{run}, $self->{timeout}, \$self->{stdout}, $until);
 
-	die "psql query timed out" if $self->{timeout}->is_expired;
+	isnt($self->{timeout}->is_expired, 'psql query_until timed out');
+	return undef if $self->{timeout}->is_expired;
 
 	$ret = $self->{stdout};
 
diff --git a/src/test/recovery/t/031_recovery_conflict.pl b/src/test/recovery/t/031_recovery_conflict.pl
index d87efa823f..62936f52d2 100644
--- a/src/test/recovery/t/031_recovery_conflict.pl
+++ b/src/test/recovery/t/031_recovery_conflict.pl
@@ -253,9 +253,7 @@ $res = $psql_standby->query_until(
     -- wait for lock held by prepared transaction
 	SELECT * FROM $table2;
     ]);
-ok(1,
-	"$sect: cursor holding conflicting pin, also waiting for lock, established"
-);
+isnt($res, undef, "$sect: cursor holding conflicting pin, also waiting for lock, established");
 
 # just to make sure we're waiting for lock already
 ok( $node_standby->poll_query_until(
diff --git a/src/test/recovery/t/037_invalid_database.pl b/src/test/recovery/t/037_invalid_database.pl
index 32b7d8af57..256314d165 100644
--- a/src/test/recovery/t/037_invalid_database.pl
+++ b/src/test/recovery/t/037_invalid_database.pl
@@ -87,6 +87,7 @@ is($node->psql('postgres', 'DROP DATABASE regression_invalid'),
 # dropping the database, making it a suitable point to wait.
 my $bgpsql = $node->background_psql('postgres', on_error_stop => 0);
 my $pid = $bgpsql->query('SELECT pg_backend_pid()');
+isnt($pid, undef, 'Get backend PID');
 
 # create the database, prevent drop database via lock held by a 2PC transaction
 ok( $bgpsql->query_safe(
-- 
2.39.3 (Apple Git-146)



  [application/octet-stream] v1-0003-Clean-up-BackgroundPsql-object-when-test-ends.patch (925B, ../[email protected]/4-v1-0003-Clean-up-BackgroundPsql-object-when-test-ends.patch)
  download | inline diff:
From 648898f8da9b3e75c56eaabaef44c1e493217ab4 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <[email protected]>
Date: Tue, 9 Apr 2024 18:05:19 +0200
Subject: [PATCH v1 3/3] Clean up BackgroundPsql object when test ends

The BackgroundPsql object must be cleaned up at the end of tests to
avoid leaks, ensure that finish() is called before exiting the suite
with done_testing().
---
 src/test/recovery/t/043_wal_replay_wait.pl | 1 +
 1 file changed, 1 insertion(+)

diff --git a/src/test/recovery/t/043_wal_replay_wait.pl b/src/test/recovery/t/043_wal_replay_wait.pl
index bbd64aa67b..3a469ddf59 100644
--- a/src/test/recovery/t/043_wal_replay_wait.pl
+++ b/src/test/recovery/t/043_wal_replay_wait.pl
@@ -94,4 +94,5 @@ $node_standby->wait_for_log('recovery is not in progress', $log_offset);
 
 $node_standby->stop;
 $node_primary->stop;
+$psql_session->{run}->finish;
 done_testing();
-- 
2.39.3 (Apple Git-146)



view thread (3+ messages)

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: [email protected]
  Cc: [email protected], [email protected], [email protected]
  Subject: Re: IPC::Run::time[r|out] vs our TAP tests
  In-Reply-To: <[email protected]>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox