Refactor routine to find single log content pattern in TAP tests

The same routine to check if a specific pattern can be found in the
server logs was copied over four different test scripts.  This refactors
the whole to use a single routine located in PostgreSQL::Test::Cluster,
named log_contains, to grab the contents of the server logs and check
for a specific pattern.

On HEAD, the code previously used assumed that slurp_file() could not
handle an undefined offset, setting it to zero, but slurp_file() does
do an extra fseek() before retrieving the log contents only if an offset
is defined.  In two places, the test was retrieving the full log
contents with slurp_file() after calling substr() to apply an offset,
ignoring that slurp_file() would be able to handle that.

Backpatch all the way down to ease the introduction of new tests that
could rely on the new routine.

Author: Vignesh C
Reviewed-by: Andrew Dunstan, Dagfinn Ilmari Mannsåker, Michael Paquier
Discussion: https://postgr.es/m/CALDaNm0YSiLpjCmajwLfidQrFOrLNKPQir7s__PeVvh9U3uoTQ@mail.gmail.com
Backpatch-through: 11

diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl
index 3272e52cae880b9259dcd9a28b4dbc8a6786248b..d8e49760726a289a5be2dd43e0de5a75347df678 100644 (file)
--- 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 2c2cd14a7fe230a2ee823434cfc0b213774f8311..5e161dbee60758f5a1935829289bbd6ded877ab4 100644 (file)
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2547,6 +2547,22 @@ sub log_check
 
 =pod
 
+=item log_contains(pattern, offset)
+
+Find pattern in logfile of node after offset byte.
+
+=cut
+
+sub log_contains
+{
+       my ($self, $pattern, $offset) = @_;
+
+       return PostgreSQL::Test::Utils::slurp_file($self->logfile, $offset) =~
+         m/$pattern/;
+}
+
+=pod
+
 =item $node->run_log(...)
 
 Runs a shell command like PostgreSQL::Test::Utils::run_log, but with connection parameters set

diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl
index a1aba16e145fcd6ee3a3641e6d0962ee87014742..33e50ad933be2da588015529ace048a736a7ba9d 100644 (file)
--- 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,9 +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"',
-                       $logstart))
+       if ($node_primary->log_contains(
+                       'invalidating obsolete replication slot "rep1"', $logstart))
        {
                $invalidated = 1;
                last;
@@ -207,7 +205,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 +235,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 +378,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,9 +402,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"',
-                       $logstart))
+       if ($node_primary3->log_contains(
+                       'invalidating obsolete replication slot "rep3"', $logstart))
        {
                $msg_logged = 1;
                last;
@@ -446,18 +441,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 0a35a7bda696ea746e8db7ffd97077ba6e9c49f1..af97ed9f70ad4abd1594556fe5b05fd79bfd00d6 100644 (file)
--- a/src/test/recovery/t/033_replay_tsp_drops.pl
+++ b/src/test/recovery/t/033_replay_tsp_drops.pl
@@ -135,8 +135,7 @@ 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);
@@ -144,13 +143,3 @@ while ($max_attempts-- >= 0)
 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/;
-}

diff --git a/src/test/recovery/t/035_standby_logical_decoding.pl b/src/test/recovery/t/035_standby_logical_decoding.pl
index 64beec4bd343bc9bfa3e0ff9bf0ddd5775780b26..480e6d6caa5e8dd30e6e09bb8281a2ae6ae4a332 100644 (file)
--- 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'
 );