Subject: Re: Implement generalized sub routine find_in_log for tap test

From: Dagfinn Ilmari Mannsåker <[email-masked]>
Date: Thu, 25 May 2023 18:34:20 +0100

vignesh C <[email-masked]> writes:

> Hi,
>
> The recovery tap test has 4 implementations of find_in_log sub routine
> for various uses, I felt we can generalize these and have a single
> function for the same. The attached patch is an attempt to have a
> generalized sub routine find_in_log which can be used by all of them.
> Thoughts?

+1 on factoring out this common code. Just a few comments on the implementation.

> diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
> index a27fac83d2..5c9b2f6c03 100644
> --- a/src/test/perl/PostgreSQL/Test/Utils.pm
> +++ b/src/test/perl/PostgreSQL/Test/Utils.pm
> @@ -67,6 +67,7 @@ our @EXPORT = qw(
>    slurp_file
>    append_to_file
>    string_replace_file
> +  find_in_log
>    check_mode_recursive
>    chmod_recursive
>    check_pg_config
> @@ -579,6 +580,28 @@ sub string_replace_file
> 
>  =pod
>
> +
> +=item find_in_log(node, pattern, offset)
> +
> +Find pattern in logfile of node after offset byte.
> +
> +=cut
> +
> +sub find_in_log
> +{
> +	my ($node, $pattern, $offset) = @_;
> +
> +	$offset = 0 unless defined $offset;
> +	my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile);

Since this function is in the same package, there's no need to qualify
it with the full name.  I know the callers you copied it from did, but
they wouldn't have had to either, since it's exported by default (in the
@EXPORT array above), unless the use statement has an explicit argument
list that excludes it.

> +	return 0 if (length($log) <= 0 || length($log) <= $offset);
> +
> +	$log = substr($log, $offset);

Also, the existing callers don't seem to have got the memo that
slurp_file() takes an optinal offset parameter, which will cause it to
seek to that postion before slurping the file, which is more efficient
than reading the whole file in and substr-ing it.  There's not much
point in the length checks either, since regex-matching against an empty
string is very cheap (and if the provide pattern can match the empty
string the whole function call is rather pointless).

> +	return $log =~ m/$pattern/;
> +}

All in all, it could be simplified to:

    sub find_in_log {
        my ($node, $pattern, $offset) = @_;

        return slurp_file($node->logfile, $offset) =~ $pattern;
    }

However, none of the other functions in ::Utils know anything about node
objects, which makes me think it should be a method on the node itself
(i.e. in PostgreSQL::Test::Cluster) instead.  Also, I think log_contains
would be a better name, since it just returns a boolean.  The name
find_in_log makes me think it would return the log lines matching the
pattern, or the position of the match in the file.

In that case, the slurp_file() call would have to be fully qualified,
since ::Cluster uses an empty import list to avoid polluting the method
namespace with imported functions.

- ilmari

---

From: Michael Paquier <[email-masked]>
Date: Fri, 26 May 2023 07:39:17 +0900

> namespace with imported functions.

Hmm.  connect_ok() and connect_fails() in Cluster.pm have a similar
log comparison logic, feeding from the offset of a log file.  Couldn't
you use the same code across the board for everything?  Note that this
stuff is parameterized so as it is possible to check if patterns match
or do not match, for multiple patterns.  It seems to me that we could
use the new log finding routine there as well, so how about extending
it a bit more?  You would need, at least:
- One parameter for log entries matching.
- One parameter for log entries not matching.
--
Michael

---

From: vignesh C <[email-masked]>
Date: Fri, 26 May 2023 22:30:12 +0530

> @EXPORT array above), unless the use statement has an explicit argument

I have moved this function to Cluster.pm file now, since it is moved,
I had to qualify the name with the full name.

>         return slurp_file($node->logfile, $offset) =~ $pattern;

Modified in similar lines

> pattern, or the position of the match in the file.

Modified

> namespace with imported functions.

Modified.

Thanks for the comments, the attached v2 version patch has the changes
for the same.

Regards,
Vignesh
From 8df06d233de4e5b5abe7a4dd4bc314c215b2dfc2 Mon Sep 17 00:00:00 2001
From: Vignesh C <[email-masked]>
Date: Fri, 26 May 2023 20:07:30 +0530
Subject: [PATCH v2] Remove duplicate find_in_log sub routines from tap tests.

Remove duplicate find_in_log sub routines from tap tests.
---
 src/test/authentication/t/003_peer.pl         | 17 ++--------
 src/test/perl/PostgreSQL/Test/Cluster.pm      | 16 +++++++++
 src/test/recovery/t/019_replslot_limit.pl     | 33 +++++--------------
 src/test/recovery/t/033_replay_tsp_drops.pl   | 15 ++-------
 .../t/035_standby_logical_decoding.pl         | 26 +++------------
 5 files changed, 33 insertions(+), 74 deletions(-)

diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 3272e52cae..2a035c2d0d 100644
--- a/src/test/authentication/t/003_peer.pl
+++ b/src/test/authentication/t/003_peer.pl
@@ -69,17 +69,6 @@ sub test_role
 	}
 }
 
-# Find $pattern in log file of $node.
-sub find_in_log
-{
-	my ($node, $offset, $pattern) = @_;
-
-	my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile, $offset);
-	return 0 if (length($log) <= 0);
-
-	return $log =~ m/$pattern/;
-}
-
 my $node = PostgreSQL::Test::Cluster->new('node');
 $node->init;
 $node->append_conf('postgresql.conf', "log_connections = on\n");
@@ -91,9 +80,9 @@ reset_pg_hba($node, 'peer');
 # Check if peer authentication is supported on this platform.
 my $log_offset = -s $node->logfile;
 $node->psql('postgres');
-if (find_in_log(
-		$node, $log_offset,
-		qr/peer authentication is not supported on this platform/))
+if ($node->log_contains(
+		qr/peer authentication is not supported on this platform/),
+		$log_offset,)
 {
 	plan skip_all => 'peer authentication is not supported on this platform';
 }
diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index baea0fcd1c..f10e44ba51 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2536,6 +2536,22 @@ sub log_content
 }

+=pod
+
+=item log_contains(pattern, offset)
+
+Find pattern in logfile of node after offset byte.
+
+=cut
+
+sub log_contains
+{
+	my ($self, $pattern, $offset) = @_;
+
+	$offset = 0 unless defined $offset;
+	return PostgreSQL::Test::Utils::slurp_file($self->logfile, $offset) =~ m/$pattern/;
+}
+
 =pod
 
 =item $node->run_log(...)
diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index a1aba16e14..95acf9e357 100644
--- a/src/test/recovery/t/019_replslot_limit.pl
+++ b/src/test/recovery/t/019_replslot_limit.pl
@@ -161,8 +161,7 @@ $node_primary->wait_for_catchup($node_standby);
 
 $node_standby->stop;
 
-ok( !find_in_log(
-		$node_standby,
+ok( !$node_standby->log_contains(
 		"requested WAL segment [0-9A-F]+ has already been removed"),
 	'check that required WAL segments are still available');
 
@@ -184,8 +183,8 @@ $node_primary->safe_psql('postgres', "CHECKPOINT;");
 my $invalidated = 0;
 for (my $i = 0; $i < 10 * $PostgreSQL::Test::Utils::timeout_default; $i++)
 {
-	if (find_in_log(
-			$node_primary, 'invalidating obsolete replication slot "rep1"',
+	if ($node_primary->log_contains(
+			'invalidating obsolete replication slot "rep1"',
 			$logstart))
 	{
 		$invalidated = 1;
@@ -207,7 +206,7 @@ is($result, "rep1|f|t|lost|",
 my $checkpoint_ended = 0;
 for (my $i = 0; $i < 10 * $PostgreSQL::Test::Utils::timeout_default; $i++)
 {
-	if (find_in_log($node_primary, "checkpoint complete: ", $logstart))
+	if ($node_primary->log_contains("checkpoint complete: ", $logstart))
 	{
 		$checkpoint_ended = 1;
 		last;
@@ -237,8 +236,7 @@ $node_standby->start;
 my $failed = 0;
 for (my $i = 0; $i < 10 * $PostgreSQL::Test::Utils::timeout_default; $i++)
 {
-	if (find_in_log(
-			$node_standby,
+	if ($node_standby->log_contains(
 			"requested WAL segment [0-9A-F]+ has already been removed",
 			$logstart))
 	{
@@ -381,8 +379,7 @@ my $msg_logged = 0;
 my $max_attempts = $PostgreSQL::Test::Utils::timeout_default;
 while ($max_attempts-- >= 0)
 {
-	if (find_in_log(
-			$node_primary3,
+	if ($node_primary3->log_contains(
 			"terminating process $senderpid to release replication slot \"rep3\"",
 			$logstart))
 	{
@@ -406,8 +403,8 @@ $msg_logged = 0;
 $max_attempts = $PostgreSQL::Test::Utils::timeout_default;
 while ($max_attempts-- >= 0)
 {
-	if (find_in_log(
-			$node_primary3, 'invalidating obsolete replication slot "rep3"',
+	if ($node_primary3->log_contains(
+			'invalidating obsolete replication slot "rep3"',
 			$logstart))
 	{
 		$msg_logged = 1;
@@ -446,18 +443,4 @@ sub get_log_size
 	return (stat $node->logfile)[7];
 }
 
-# find $pat in logfile of $node after $off-th byte
-sub find_in_log
-{
-	my ($node, $pat, $off) = @_;
-
-	$off = 0 unless defined $off;
-	my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile);
-	return 0 if (length($log) <= $off);
-
-	$log = substr($log, $off);
-
-	return $log =~ m/$pat/;
-}
-
 done_testing();
diff --git a/src/test/recovery/t/033_replay_tsp_drops.pl b/src/test/recovery/t/033_replay_tsp_drops.pl
index 0a35a7bda6..307c30bc6b 100644
--- a/src/test/recovery/t/033_replay_tsp_drops.pl
+++ b/src/test/recovery/t/033_replay_tsp_drops.pl
@@ -135,22 +135,11 @@ while ($max_attempts-- >= 0)
 {
 	last
 	  if (
-		find_in_log(
-			$node_standby,
+		$node_standby->log_contains(
 			qr!WARNING: ( [A-Z0-9]+:)? creating missing directory: pg_tblspc/!,
 			$logstart));
 	usleep(100_000);
 }
 ok($max_attempts > 0, "invalid directory creation is detected");
 
-done_testing();
-
-# find $pat in logfile of $node after $off-th byte
-sub find_in_log
-{
-	my ($node, $pat, $off) = @_;
-
-	my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile, $off);
-
-	return $log =~ m/$pat/;
-}
+done_testing();
\ No newline at end of file
diff --git a/src/test/recovery/t/035_standby_logical_decoding.pl b/src/test/recovery/t/035_standby_logical_decoding.pl
index 64beec4bd3..480e6d6caa 100644
--- a/src/test/recovery/t/035_standby_logical_decoding.pl
+++ b/src/test/recovery/t/035_standby_logical_decoding.pl
@@ -28,20 +28,6 @@ my $res;
 my $primary_slotname = 'primary_physical';
 my $standby_physical_slotname = 'standby_physical';
 
-# find $pat in logfile of $node after $off-th byte
-sub find_in_log
-{
-	my ($node, $pat, $off) = @_;
-
-	$off = 0 unless defined $off;
-	my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile);
-	return 0 if (length($log) <= $off);
-
-	$log = substr($log, $off);
-
-	return $log =~ m/$pat/;
-}
-
 # Fetch xmin columns from slot's pg_replication_slots row, after waiting for
 # given boolean condition to be true to ensure we've reached a quiescent state.
 sub wait_for_xmins
@@ -235,14 +221,12 @@ sub check_for_invalidation
 	my $inactive_slot = $slot_prefix . 'inactiveslot';
 
 	# message should be issued
-	ok( find_in_log(
-			$node_standby,
+	ok( $node_standby->log_contains(
 			"invalidating obsolete replication slot \"$inactive_slot\"",
 			$log_start),
 		"inactiveslot slot invalidation is logged $test_name");
 
-	ok( find_in_log(
-			$node_standby,
+	ok( $node_standby->log_contains(
 			"invalidating obsolete replication slot \"$active_slot\"",
 			$log_start),
 		"activeslot slot invalidation is logged $test_name");
@@ -657,14 +641,12 @@ $node_primary->safe_psql(
 $node_primary->wait_for_replay_catchup($node_standby);
 
 # message should not be issued
-ok( !find_in_log(
-		$node_standby,
+ok( !$node_standby->log_contains(
 		"invalidating obsolete slot \"no_conflict_inactiveslot\"", $logstart),
 	'inactiveslot slot invalidation is not logged with vacuum on conflict_test'
 );
 
-ok( !find_in_log(
-		$node_standby,
+ok( !$node_standby->log_contains(
 		"invalidating obsolete slot \"no_conflict_activeslot\"", $logstart),
 	'activeslot slot invalidation is not logged with vacuum on conflict_test'
 );
-- 
2.34.1

---

From: vignesh C <[email-masked]>
Date: Sat, 27 May 2023 06:05:24 +0530

> - One parameter for log entries not matching.

I felt adding these to log_contains was making the function slightly
complex with multiple checks. I was not able to make it simple with
the approach I tried. How about having a common function
check_connect_log_contents which has the common log contents check for
connect_ok and connect_fails function like the v2-0002 patch attached.

Regards,
Vignesh
From 1e835b6d032ea380bc213ff130e87fbb250be77f Mon Sep 17 00:00:00 2001
From: Vignesh C <[email-masked]>
Date: Fri, 26 May 2023 20:07:30 +0530
Subject: [PATCH v2 1/2] Remove duplicate find_in_log sub routines from tap
 tests.

 

+=pod
+

 $node_standby->stop;
 
-ok( !find_in_log(
-		$node_standby,

 
-done_testing();
-

 
-	ok( find_in_log(
-			$node_standby,

-ok( !find_in_log(
-		$node_standby,

From aa587e7cedd92d60e93075d643cb8ad93ca07c5b Mon Sep 17 00:00:00 2001
From: Vignesh C <[email-masked]>
Date: Sat, 27 May 2023 05:36:34 +0530
Subject: [PATCH v2 2/2] Move common connection log content verification code
 to a common function.

Move common connection log content verification code to a common
function.
---
 src/test/perl/PostgreSQL/Test/Cluster.pm | 122 +++++++++++------------
 1 file changed, 60 insertions(+), 62 deletions(-)

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index f10e44ba51..7458406ee6 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2168,21 +2168,19 @@ sub pgbench
 
 =pod
 
-=item $node->connect_ok($connstr, $test_name, %params)
+=item $node->check_connect_log_contents($offset, $test_name, %parameters)
 
-Attempt a connection with a custom connection string.  This is expected
-to succeed.
+Check connection log contents.
 
 =over
 
-=item sql => B<value>
+=item $test_name
 
-If this parameter is set, this query is used for the connection attempt
-instead of the default.
+Name of test for error messages.
 
-=item expected_stdout => B<value>
+=item $offset
 
-If this regular expression is set, matches it with the output generated.
+Offset of the log file.
 
 =item log_like => [ qr/required message/ ]
 
@@ -2200,6 +2198,58 @@ passed to C<Test::More::unlike()>.
 
 =cut
 
+sub check_connect_log_contents
+{
+	my ($self, $test_name, $offset, %params) = @_;
+
+	my (@log_like, @log_unlike);
+	if (defined($params{log_like}))
+	{
+		@log_like = @{ $params{log_like} };
+	}
+	if (defined($params{log_unlike}))
+	{
+		@log_unlike = @{ $params{log_unlike} };
+	}
+
+	if (@log_like or @log_unlike)
+	{
+		my $log_contents =
+		  PostgreSQL::Test::Utils::slurp_file($self->logfile, $offset);
+
+		while (my $regex = shift @log_like)
+		{
+			like($log_contents, $regex, "$test_name: log matches");
+		}
+		while (my $regex = shift @log_unlike)
+		{
+			unlike($log_contents, $regex, "$test_name: log does not match");
+		}
+	}
+}
+
+=pod
+
+=item $node->connect_ok($connstr, $test_name, %params)
+
+Attempt a connection with a custom connection string.  This is expected
+to succeed.
+
+=over
+
+=item sql => B<value>
+
+If this parameter is set, this query is used for the connection attempt
+instead of the default.
+
+=item expected_stdout => B<value>
+
+If this regular expression is set, matches it with the output generated.
+
+=back
+
+=cut
+
 sub connect_ok
 {
 	local $Test::Builder::Level = $Test::Builder::Level + 1;
@@ -2215,16 +2265,6 @@ sub connect_ok
 		$sql = "SELECT \$\$connected with $connstr\$\$";
 	}
 
-	my (@log_like, @log_unlike);
-	if (defined($params{log_like}))
-	{
-		@log_like = @{ $params{log_like} };
-	}
-	if (defined($params{log_unlike}))
-	{
-		@log_unlike = @{ $params{log_unlike} };
-	}
-
 	my $log_location = -s $self->logfile;
 
 	# Never prompt for a password, any callers of this routine should
@@ -2245,20 +2285,7 @@ sub connect_ok
 
 	is($stderr, "", "$test_name: no stderr");
 
-	if (@log_like or @log_unlike)
-	{
-		my $log_contents =
-		  PostgreSQL::Test::Utils::slurp_file($self->logfile, $log_location);
-
-		while (my $regex = shift @log_like)
-		{
-			like($log_contents, $regex, "$test_name: log matches");
-		}
-		while (my $regex = shift @log_unlike)
-		{
-			unlike($log_contents, $regex, "$test_name: log does not match");
-		}
-	}
+	$self->check_connect_log_contents($test_name, $log_location, %params);
 }
 
 =pod
@@ -2274,12 +2301,6 @@ to fail.
 
 If this regular expression is set, matches it with the output generated.
 
-=item log_like => [ qr/required message/ ]
-
-=item log_unlike => [ qr/prohibited message/ ]
-
-See C<connect_ok(...)>, above.
-
 =back
 
 =cut
@@ -2289,16 +2310,6 @@ sub connect_fails
 	local $Test::Builder::Level = $Test::Builder::Level + 1;
 	my ($self, $connstr, $test_name, %params) = @_;
 
-	my (@log_like, @log_unlike);
-	if (defined($params{log_like}))
-	{
-		@log_like = @{ $params{log_like} };
-	}
-	if (defined($params{log_unlike}))
-	{
-		@log_unlike = @{ $params{log_unlike} };
-	}
-
 	my $log_location = -s $self->logfile;
 
 	# Never prompt for a password, any callers of this routine should
@@ -2316,20 +2327,7 @@ sub connect_fails
 		like($stderr, $params{expected_stderr}, "$test_name: matches");
 	}
 
-	if (@log_like or @log_unlike)
-	{
-		my $log_contents =
-		  PostgreSQL::Test::Utils::slurp_file($self->logfile, $log_location);
-
-		while (my $regex = shift @log_like)
-		{
-			like($log_contents, $regex, "$test_name: log matches");
-		}
-		while (my $regex = shift @log_unlike)
-		{
-			unlike($log_contents, $regex, "$test_name: log does not match");
-		}
-	}
+	$self->check_connect_log_contents($test_name, $log_location, %params);
 }
 
 =pod
-- 
2.34.1