File truncation within PostgresNode::issues_sql_like() wrong on Windows
Hi all,
As fairywren has proved a couple of days ago, it is not really a good
idea to rely on a file truncation to check for patterns in the logs of
the backend:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fairywren&dt=2021-04-07%2013%3A29%3A28
Visibly, a logic based on the log file truncation fails on Windows
because of the concurrent access of the backend that outputs its logs
there. In PostgresNode.pm, connect_ok() and connect_access() enforce
a rotation of the log file before restarting the server on Windows to
make sure that a given step does not find logs generated by a previous
test, but that's not the case of issues_sql_like(). Looking at the
existing tests using this routine (src/bin/scripts/), I have found on
test in 090_reindexdb.pl that could lead to a false positive. The
test is marked in the patch attached, just for awareness.
Would there be any objections to change this routine so as we avoid
the file truncation on Windows? The patch attached achieves that.
Any thoughts?
--
Michael
Attachments:
tap-sql-like-truncate.patchtext/x-diff; charset=us-asciiDownload
diff --git a/src/bin/scripts/t/090_reindexdb.pl b/src/bin/scripts/t/090_reindexdb.pl
index 159b637230..8b06218d6b 100644
--- a/src/bin/scripts/t/090_reindexdb.pl
+++ b/src/bin/scripts/t/090_reindexdb.pl
@@ -174,6 +174,7 @@ $node->command_fails(
$node->command_fails(
[ 'reindexdb', '-j', '2', '-i', 'i1', 'postgres' ],
'parallel reindexdb cannot process indexes');
+# XXX The first query maps with a test above.
$node->issues_sql_like(
[ 'reindexdb', '-j', '2', 'postgres' ],
qr/statement:\ REINDEX SYSTEM postgres;
diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
index e26b2b3f30..9daa438ccc 100644
--- a/src/test/perl/PostgresNode.pm
+++ b/src/test/perl/PostgresNode.pm
@@ -2195,7 +2195,8 @@ Run a command on the node, then verify that $expected_sql appears in the
server log file.
Reads the whole log file so be careful when working with large log outputs.
-The log file is truncated prior to running the command, however.
+The log file is truncated prior to running the command, and on Windows, a
+rotation of the log file is done before restarting the node.
=cut
@@ -2207,7 +2208,18 @@ sub issues_sql_like
local %ENV = $self->_get_env();
- truncate $self->logfile, 0;
+ # On Windows, the truncation would not work, so rotate the log
+ # file before restarting the server afresh.
+ if ($TestLib::windows_os)
+ {
+ $self->rotate_logfile;
+ $self->restart;
+ }
+ else
+ {
+ truncate $self->logfile, 0;
+ }
+
my $result = TestLib::run_log($cmd);
ok($result, "@$cmd exit code 0");
my $log = TestLib::slurp_file($self->logfile);
On 4/14/21 4:13 AM, Michael Paquier wrote:
Hi all,
As fairywren has proved a couple of days ago, it is not really a good
idea to rely on a file truncation to check for patterns in the logs of
the backend:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fairywren&dt=2021-04-07%2013%3A29%3A28Visibly, a logic based on the log file truncation fails on Windows
because of the concurrent access of the backend that outputs its logs
there. In PostgresNode.pm, connect_ok() and connect_access() enforce
a rotation of the log file before restarting the server on Windows to
make sure that a given step does not find logs generated by a previous
test, but that's not the case of issues_sql_like(). Looking at the
existing tests using this routine (src/bin/scripts/), I have found on
test in 090_reindexdb.pl that could lead to a false positive. The
test is marked in the patch attached, just for awareness.Would there be any objections to change this routine so as we avoid
the file truncation on Windows? The patch attached achieves that.Any thoughts?
That seems rather heavy-handed. The buildfarm's approach is a bit
different. Essentially it seeks to the previous position of the log file
before reading contents. Here is its equivalent of slurp_file:
use Fcntl qw(:seek);
sub file_lines
{
��� my $filename = shift;
��� my $filepos� = shift;
��� my $handle;
��� open($handle, '<', $filename) || croak "opening $filename: $!";
��� seek($handle, $filepos, SEEK_SET) if $filepos;
��� my @lines = <$handle>;
��� close $handle;
��� return @lines;
}
A client wanting what's done in PostgresNode would do something like:
my $logpos� = -s $logfile;
do_some_stuff();
my @lines = file_lines($logfile, $logpos);
This has the benefit of working the same on all platforms, and no
truncation, rotation, or restart is required.
cheers
andrew
--
Andrew Dunstan
EDB: https://www.enterprisedb.com
On Wed, Apr 14, 2021 at 05:10:41PM -0400, Andrew Dunstan wrote:
That seems rather heavy-handed. The buildfarm's approach is a bit
different. Essentially it seeks to the previous position of the log file
before reading contents. Here is its equivalent of slurp_file:use Fcntl qw(:seek);
sub file_lines
{
my $filename = shift;
my $filepos = shift;
my $handle;
open($handle, '<', $filename) || croak "opening $filename: $!";
seek($handle, $filepos, SEEK_SET) if $filepos;
my @lines = <$handle>;
close $handle;
return @lines;
}
That's a bit surprising to see that you can safely open a file handle
with perl like that without using Win32API::File, and I would have
assumed that this would have conflicted with the backend redirecting
its output to stderr the same way as a truncation on Windows.
A client wanting what's done in PostgresNode would do something like:
my $logpos = -s $logfile;
do_some_stuff();
my @lines = file_lines($logfile, $logpos);This has the benefit of working the same on all platforms, and no
truncation, rotation, or restart is required.
Jacob has suggested something like that a couple of days ago, but all
this code was not centralized yet in a single place.
For this code, the cleanest approach would be to extend slurp_file()
with an extra argument to seek the file before fetching its contents
based on a location given by the caller? Looking at the docs of
Win32API::File, we'd need to use SetFilePointer() instead of seek().
--
Michael
On 4/14/21 8:10 PM, Michael Paquier wrote:
On Wed, Apr 14, 2021 at 05:10:41PM -0400, Andrew Dunstan wrote:
That seems rather heavy-handed. The buildfarm's approach is a bit
different. Essentially it seeks to the previous position of the log file
before reading contents. Here is its equivalent of slurp_file:use Fcntl qw(:seek);
sub file_lines
{
��� my $filename = shift;
��� my $filepos� = shift;
��� my $handle;
��� open($handle, '<', $filename) || croak "opening $filename: $!";
��� seek($handle, $filepos, SEEK_SET) if $filepos;
��� my @lines = <$handle>;
��� close $handle;
��� return @lines;
}That's a bit surprising to see that you can safely open a file handle
with perl like that without using Win32API::File, and I would have
assumed that this would have conflicted with the backend redirecting
its output to stderr the same way as a truncation on Windows.A client wanting what's done in PostgresNode would do something like:
my $logpos� = -s $logfile;
do_some_stuff();
my @lines = file_lines($logfile, $logpos);This has the benefit of working the same on all platforms, and no
truncation, rotation, or restart is required.Jacob has suggested something like that a couple of days ago, but all
this code was not centralized yet in a single place.For this code, the cleanest approach would be to extend slurp_file()
with an extra argument to seek the file before fetching its contents
based on a location given by the caller? Looking at the docs of
Win32API::File, we'd need to use SetFilePointer() instead of seek().
Well, let me try it on fairywren tomorrow. Since we manage this on the
buildfarm without any use at all of Win32API::File it might not be
necessary in TAP code either, particularly if we're not truncating the file.
cheers
andrew
--
Andrew Dunstan
EDB: https://www.enterprisedb.com
On Wed, Apr 14, 2021 at 09:26:19PM -0400, Andrew Dunstan wrote:
Well, let me try it on fairywren tomorrow. Since we manage this on the
buildfarm without any use at all of Win32API::File it might not be
necessary in TAP code either, particularly if we're not truncating the file.
Thanks. If that proves to not be necessary, +1 to remove this code.
I have been playing with this stuff, and the attached patch seems to
work properly on Windows. On top of that, I have also tested the
non-Win32 path on an MSVC box to see that it was working, but my
environment is not really noisy usually with such compatibility
issues.
--
Michael
Attachments:
tap-sql-like-truncate-v2.patchtext/x-diff; charset=us-asciiDownload
diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
index e26b2b3f30..e209ea7163 100644
--- a/src/test/perl/PostgresNode.pm
+++ b/src/test/perl/PostgresNode.pm
@@ -1917,21 +1917,7 @@ sub connect_ok
@log_unlike = @{ $params{log_unlike} };
}
- if (@log_like or @log_unlike)
- {
- # Don't let previous log entries match for this connection.
- # On Windows, the truncation would not work, so rotate the log
- # file before restarting the server afresh.
- if ($TestLib::windows_os)
- {
- $self->rotate_logfile;
- $self->restart;
- }
- else
- {
- truncate $self->logfile, 0;
- }
- }
+ my $log_location = -s $self->logfile;
# Never prompt for a password, any callers of this routine should
# have set up things properly, and this should not block.
@@ -1950,7 +1936,8 @@ sub connect_ok
}
if (@log_like or @log_unlike)
{
- my $log_contents = TestLib::slurp_file($self->logfile);
+ my $log_contents = TestLib::slurp_file($self->logfile,
+ $log_location);
while (my $regex = shift @log_like)
{
@@ -2001,21 +1988,7 @@ sub connect_fails
@log_unlike = @{ $params{log_unlike} };
}
- if (@log_like or @log_unlike)
- {
- # Don't let previous log entries match for this connection.
- # On Windows, the truncation would not work, so rotate the log
- # file before restarting the server afresh.
- if ($TestLib::windows_os)
- {
- $self->rotate_logfile;
- $self->restart;
- }
- else
- {
- truncate $self->logfile, 0;
- }
- }
+ my $log_location = -s $self->logfile;
# Never prompt for a password, any callers of this routine should
# have set up things properly, and this should not block.
@@ -2034,7 +2007,8 @@ sub connect_fails
if (@log_like or @log_unlike)
{
- my $log_contents = TestLib::slurp_file($self->logfile);
+ my $log_contents = TestLib::slurp_file($self->logfile,
+ $log_location);
while (my $regex = shift @log_like)
{
@@ -2194,9 +2168,6 @@ sub command_checks_all
Run a command on the node, then verify that $expected_sql appears in the
server log file.
-Reads the whole log file so be careful when working with large log outputs.
-The log file is truncated prior to running the command, however.
-
=cut
sub issues_sql_like
@@ -2207,10 +2178,11 @@ sub issues_sql_like
local %ENV = $self->_get_env();
- truncate $self->logfile, 0;
+ my $log_location = -s $self->logfile;
+
my $result = TestLib::run_log($cmd);
ok($result, "@$cmd exit code 0");
- my $log = TestLib::slurp_file($self->logfile);
+ my $log = TestLib::slurp_file($self->logfile, $log_location);
like($log, $expected_sql, "$test_name: SQL found in server log");
return;
}
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index 1baf6bd001..017d0f08e0 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -124,7 +124,7 @@ BEGIN
if ($windows_os)
{
require Win32API::File;
- Win32API::File->import(qw(createFile OsFHandleOpen CloseHandle));
+ Win32API::File->import(qw(createFile OsFHandleOpen CloseHandle setFilePointer));
}
# Specifies whether to use Unix sockets for test setups. On
@@ -430,21 +430,27 @@ sub slurp_dir
=pod
-=item slurp_file(filename)
+=item slurp_file(filename [, $offset])
-Return the full contents of the specified file.
+Return the full contents of the specified file, beginning from an
+offset position if specified.
=cut
sub slurp_file
{
- my ($filename) = @_;
+ my ($filename, $offset) = @_;
local $/;
my $contents;
if ($Config{osname} ne 'MSWin32')
{
open(my $in, '<', $filename)
or croak "could not read \"$filename\": $!";
+ if (defined($offset))
+ {
+ seek($in, $offset, 0)
+ or croak "could not seek \"$filename\": $!";
+ }
$contents = <$in>;
close $in;
}
@@ -454,6 +460,11 @@ sub slurp_file
or croak "could not open \"$filename\": $^E";
OsFHandleOpen(my $fh = IO::Handle->new(), $fHandle, 'r')
or croak "could not read \"$filename\": $^E\n";
+ if (defined($offset))
+ {
+ setFilePointer($fh, $offset, qw(FILE_BEGIN))
+ or croak "could not seek \"$filename\": $^E\n";
+ }
$contents = <$fh>;
CloseHandle($fHandle)
or croak "could not close \"$filename\": $^E\n";
On 4/15/21 12:57 AM, Michael Paquier wrote:
On Wed, Apr 14, 2021 at 09:26:19PM -0400, Andrew Dunstan wrote:
Well, let me try it on fairywren tomorrow. Since we manage this on the
buildfarm without any use at all of Win32API::File it might not be
necessary in TAP code either, particularly if we're not truncating the file.Thanks. If that proves to not be necessary, +1 to remove this code.
I have been playing with this stuff, and the attached patch seems to
work properly on Windows. On top of that, I have also tested the
non-Win32 path on an MSVC box to see that it was working, but my
environment is not really noisy usually with such compatibility
issues.
Reviewing the history, I don't want to undo 114541d58e5. So I'm trying
your patch.
cheers
andrew
--
Andrew Dunstan
EDB: https://www.enterprisedb.com
On Thu, Apr 15, 2021 at 07:16:05AM -0400, Andrew Dunstan wrote:
Reviewing the history, I don't want to undo 114541d58e5.
Maybe we could remove it, but that may be better as a separate
discussion if it is proving to not improve the situation, and I don't
really want to take any risks in destabilizing the buildfarm these
days.
So I'm trying your patch.
Thanks! If you need any help, please feel free to ping me.
--
Michael
On 4/15/21 8:36 PM, Michael Paquier wrote:
On Thu, Apr 15, 2021 at 07:16:05AM -0400, Andrew Dunstan wrote:
Reviewing the history, I don't want to undo 114541d58e5.
Maybe we could remove it, but that may be better as a separate
discussion if it is proving to not improve the situation, and I don't
really want to take any risks in destabilizing the buildfarm these
days.So I'm trying your patch.
Thanks! If you need any help, please feel free to ping me.
It's worked on fairywren, I will double check on drongo and if all is
well will commit.
cheers
andrew
--
Andrew Dunstan
EDB: https://www.enterprisedb.com
On Thu, Apr 15, 2021 at 09:12:52PM -0400, Andrew Dunstan wrote:
It's worked on fairywren, I will double check on drongo and if all is
well will commit.
Thanks Andrew. For the archive's sake, this has been committed as of
3c5b068.
While reading the commit, I have noticed that you used SEEK_SET
instead of 0 as I did in my own patch. That makes the code easier to
understand. Could it be better to apply the same style to all the
perl scripts doing some seek() calls? Please see the attached.
--
Michael
Attachments:
tap-seek.patchtext/x-diff; charset=us-asciiDownload
diff --git a/src/bin/pg_amcheck/t/003_check.pl b/src/bin/pg_amcheck/t/003_check.pl
index 66dd14e498..2da9631da4 100644
--- a/src/bin/pg_amcheck/t/003_check.pl
+++ b/src/bin/pg_amcheck/t/003_check.pl
@@ -3,6 +3,8 @@ use warnings;
use PostgresNode;
use TestLib;
+
+use Fcntl qw(:seek);
use Test::More tests => 63;
my ($node, $port, %corrupt_page, %remove_relation);
@@ -84,7 +86,7 @@ sub corrupt_first_page
# Corrupt some line pointers. The values are chosen to hit the
# various line-pointer-corruption checks in verify_heapam.c
# on both little-endian and big-endian architectures.
- seek($fh, 32, 0)
+ seek($fh, 32, SEEK_SET)
or BAIL_OUT("seek failed: $!");
syswrite(
$fh,
diff --git a/src/bin/pg_amcheck/t/004_verify_heapam.pl b/src/bin/pg_amcheck/t/004_verify_heapam.pl
index 3c1277adf3..b842f7bc6d 100644
--- a/src/bin/pg_amcheck/t/004_verify_heapam.pl
+++ b/src/bin/pg_amcheck/t/004_verify_heapam.pl
@@ -4,6 +4,7 @@ use warnings;
use PostgresNode;
use TestLib;
+use Fcntl qw(:seek);
use Test::More;
# This regression test demonstrates that the pg_amcheck binary correctly
@@ -95,7 +96,7 @@ sub read_tuple
{
my ($fh, $offset) = @_;
my ($buffer, %tup);
- seek($fh, $offset, 0)
+ seek($fh, $offset, SEEK_SET)
or BAIL_OUT("seek failed: $!");
defined(sysread($fh, $buffer, HEAPTUPLE_PACK_LENGTH))
or BAIL_OUT("sysread failed: $!");
@@ -172,7 +173,7 @@ sub write_tuple
$tup->{c_va_extinfo},
$tup->{c_va_valueid},
$tup->{c_va_toastrelid});
- seek($fh, $offset, 0)
+ seek($fh, $offset, SEEK_SET)
or BAIL_OUT("seek failed: $!");
defined(syswrite($fh, $buffer, HEAPTUPLE_PACK_LENGTH))
or BAIL_OUT("syswrite failed: $!");
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index 089c9cb851..a9dfe88aaa 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -4,6 +4,7 @@ use Cwd;
use Config;
use File::Basename qw(basename dirname);
use File::Path qw(rmtree);
+use Fcntl qw(:seek);
use PostgresNode;
use TestLib;
use Test::More tests => 110;
@@ -555,7 +556,7 @@ my $block_size = $node->safe_psql('postgres', 'SHOW block_size;');
# induce corruption
system_or_bail 'pg_ctl', '-D', $pgdata, 'stop';
open $file, '+<', "$pgdata/$file_corrupt1";
-seek($file, $pageheader_size, 0);
+seek($file, $pageheader_size, SEEK_SET);
syswrite($file, "\0\0\0\0\0\0\0\0\0");
close $file;
system_or_bail 'pg_ctl', '-D', $pgdata, 'start';
@@ -574,7 +575,7 @@ open $file, '+<', "$pgdata/$file_corrupt1";
for my $i (1 .. 5)
{
my $offset = $pageheader_size + $i * $block_size;
- seek($file, $offset, 0);
+ seek($file, $offset, SEEK_SET);
syswrite($file, "\0\0\0\0\0\0\0\0\0");
}
close $file;
@@ -591,7 +592,7 @@ rmtree("$tempdir/backup_corrupt2");
# induce corruption in a second file
system_or_bail 'pg_ctl', '-D', $pgdata, 'stop';
open $file, '+<', "$pgdata/$file_corrupt2";
-seek($file, $pageheader_size, 0);
+seek($file, $pageheader_size, SEEK_SET);
syswrite($file, "\0\0\0\0\0\0\0\0\0");
close $file;
system_or_bail 'pg_ctl', '-D', $pgdata, 'start';
diff --git a/src/bin/pg_checksums/t/002_actions.pl b/src/bin/pg_checksums/t/002_actions.pl
index 8a81f36a06..d52bbac5fa 100644
--- a/src/bin/pg_checksums/t/002_actions.pl
+++ b/src/bin/pg_checksums/t/002_actions.pl
@@ -5,6 +5,8 @@ use strict;
use warnings;
use PostgresNode;
use TestLib;
+
+use Fcntl qw(:seek);
use Test::More tests => 63;
@@ -50,7 +52,7 @@ sub check_relation_corruption
# Time to create some corruption
open my $file, '+<', "$pgdata/$file_corrupted";
- seek($file, $pageheader_size, 0);
+ seek($file, $pageheader_size, SEEK_SET);
syswrite($file, "\0\0\0\0\0\0\0\0\0");
close $file;
diff --git a/contrib/amcheck/t/001_verify_heapam.pl b/contrib/amcheck/t/001_verify_heapam.pl
index 6050feb712..bf47c2ed37 100644
--- a/contrib/amcheck/t/001_verify_heapam.pl
+++ b/contrib/amcheck/t/001_verify_heapam.pl
@@ -4,6 +4,7 @@ use warnings;
use PostgresNode;
use TestLib;
+use Fcntl qw(:seek);
use Test::More tests => 80;
my ($node, $result);
@@ -124,7 +125,7 @@ sub corrupt_first_page
# Corrupt some line pointers. The values are chosen to hit the
# various line-pointer-corruption checks in verify_heapam.c
# on both little-endian and big-endian architectures.
- seek($fh, 32, 0)
+ seek($fh, 32, SEEK_SET)
or BAIL_OUT("seek failed: $!");
syswrite(
$fh,
On 4/17/21 9:04 AM, Michael Paquier wrote:
On Thu, Apr 15, 2021 at 09:12:52PM -0400, Andrew Dunstan wrote:
It's worked on fairywren, I will double check on drongo and if all is
well will commit.Thanks Andrew. For the archive's sake, this has been committed as of
3c5b068.While reading the commit, I have noticed that you used SEEK_SET
instead of 0 as I did in my own patch. That makes the code easier to
understand. Could it be better to apply the same style to all the
perl scripts doing some seek() calls? Please see the attached.
Yes please, much better to use a symbolic name rather than a magic
number. I wouldn't bother backpatching it though.
cheers
andrew
--
Andrew Dunstan
EDB: https://www.enterprisedb.com