Improving log capture of TAP tests with IPC::Run
Hi all,
After looking at the issues with the TAP test suite that hamster faced
a couple of days ago, which is what has been discussed on this thread:
/messages/by-id/13002.1434307025@sss.pgh.pa.us
I have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
that is not able to help much) that has already been sent on the
thread above.
This patch looks worth having in the TAP suite to track problems,
hence this thread dedicated to it. The patch has been added as well to
the next CF.
Regards,
--
Michael
Attachments:
20150620_tap_improve_logs_v3.patchtext/x-patch; charset=US-ASCII; name=20150620_tap_improve_logs_v3.patchDownload
From 59fa3c2cd99bfbff970c6054ea279bb26a0a3413 Mon Sep 17 00:00:00 2001
From: Michael Paquier <michael@otacoo.com>
Date: Sat, 20 Jun 2015 17:44:39 +0900
Subject: [PATCH] Improve log capture of TAP tests and fix race conditions
All tests have their logs stored as regress_log/$TEST_NAME, with content
captured from the many commands run during the tests. Commands that were
previously called in silent mode are made verbose and have their output
written in the newly-created log files.
---
src/Makefile.global.in | 1 +
src/bin/pg_basebackup/t/010_pg_basebackup.pl | 4 +-
src/bin/pg_controldata/t/001_pg_controldata.pl | 2 +-
src/bin/pg_ctl/t/001_start_stop.pl | 2 +-
src/bin/pg_ctl/t/002_status.pl | 6 +--
src/bin/pg_rewind/.gitignore | 1 -
src/bin/pg_rewind/Makefile | 2 +-
src/bin/pg_rewind/RewindTest.pm | 74 ++++++++++++--------------
src/bin/pg_rewind/t/001_basic.pl | 1 -
src/bin/pg_rewind/t/002_databases.pl | 1 -
src/bin/pg_rewind/t/003_extrafiles.pl | 1 -
src/test/perl/TestLib.pm | 52 +++++++++++++-----
src/test/ssl/ServerSetup.pm | 6 +--
13 files changed, 83 insertions(+), 70 deletions(-)
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index c583b44..171d1e4 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -336,6 +336,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
+rm -rf $(srcdir)/tmp_check/log
cd $(srcdir) && TESTDIR='$(CURDIR)' $(with_temp_install) PGPORT='6$(DEF_PGPORT)' top_builddir='$(CURDIR)/$(top_builddir)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
endef
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index 3476ea6..b87ef29 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -22,7 +22,7 @@ print HBA "local replication all trust\n";
print HBA "host replication all 127.0.0.1/32 trust\n";
print HBA "host replication all ::1/128 trust\n";
close HBA;
-system_or_bail 'pg_ctl', '-s', '-D', "$tempdir/pgdata", 'reload';
+run_or_bail(['pg_ctl', '-D', "$tempdir/pgdata", 'reload']);
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
@@ -51,7 +51,7 @@ ok(-f "$tempdir/tarbackup/base.tar", 'backup tar was created');
my $superlongname = "superlongname_" . ("x" x 100);
-system_or_bail 'touch', "$tempdir/pgdata/$superlongname";
+run_or_bail(['touch', "$tempdir/pgdata/$superlongname"]);
command_fails([ 'pg_basebackup', '-D', "$tempdir/tarbackup_l1", '-Ft' ],
'pg_basebackup tar with long name fails');
unlink "$tempdir/pgdata/$superlongname";
diff --git a/src/bin/pg_controldata/t/001_pg_controldata.pl b/src/bin/pg_controldata/t/001_pg_controldata.pl
index a4180e7..0d1407e 100644
--- a/src/bin/pg_controldata/t/001_pg_controldata.pl
+++ b/src/bin/pg_controldata/t/001_pg_controldata.pl
@@ -11,6 +11,6 @@ program_options_handling_ok('pg_controldata');
command_fails(['pg_controldata'], 'pg_controldata without arguments fails');
command_fails([ 'pg_controldata', 'nonexistent' ],
'pg_controldata with nonexistent directory fails');
-system_or_bail "initdb -D '$tempdir'/data -A trust >/dev/null";
+run_or_bail(['initdb', '-D', "$tempdir/data", '-A', 'trust']);
command_like([ 'pg_controldata', "$tempdir/data" ],
qr/checkpoint/, 'pg_controldata produces output');
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 6c9ec5c..57563d7 100644
--- a/src/bin/pg_ctl/t/001_start_stop.pl
+++ b/src/bin/pg_ctl/t/001_start_stop.pl
@@ -36,4 +36,4 @@ command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
'pg_ctl restart with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast']);
diff --git a/src/bin/pg_ctl/t/002_status.pl b/src/bin/pg_ctl/t/002_status.pl
index 0558854..d1192f6 100644
--- a/src/bin/pg_ctl/t/002_status.pl
+++ b/src/bin/pg_ctl/t/002_status.pl
@@ -18,9 +18,9 @@ close CONF;
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
3, 'pg_ctl status with server not running');
-system_or_bail 'pg_ctl', '-s', '-l', "$tempdir/logfile", '-D',
- "$tempdir/data", '-w', 'start';
+run_or_bail(['pg_ctl', '-l', "$tempdir/logfile", '-D',
+ "$tempdir/data", '-w', 'start']);
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
0, 'pg_ctl status with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast']);
diff --git a/src/bin/pg_rewind/.gitignore b/src/bin/pg_rewind/.gitignore
index 9ade7ef..79ddca3 100644
--- a/src/bin/pg_rewind/.gitignore
+++ b/src/bin/pg_rewind/.gitignore
@@ -4,4 +4,3 @@
# Generated by test suite
/tmp_check/
-/regress_log/
diff --git a/src/bin/pg_rewind/Makefile b/src/bin/pg_rewind/Makefile
index 7d60715..92b5d20 100644
--- a/src/bin/pg_rewind/Makefile
+++ b/src/bin/pg_rewind/Makefile
@@ -45,7 +45,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_rewind$(X) $(OBJS) xlogreader.c
- rm -rf tmp_check regress_log
+ rm -rf tmp_check
check:
$(prove_check)
diff --git a/src/bin/pg_rewind/RewindTest.pm b/src/bin/pg_rewind/RewindTest.pm
index 5219ec9..814bffa 100644
--- a/src/bin/pg_rewind/RewindTest.pm
+++ b/src/bin/pg_rewind/RewindTest.pm
@@ -79,7 +79,6 @@ mkdir "regress_log";
my $port_master = $ENV{PGPORT};
my $port_standby = $port_master + 1;
-my $log_path;
my $tempdir_short;
my $connstr_master = "port=$port_master";
@@ -91,14 +90,16 @@ sub master_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_master -c \"$cmd\"");
+ run_or_bail(['psql', '-q', '--no-psqlrc', '-d', $connstr_master,
+ '-c', "$cmd"]);
}
sub standby_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_standby -c \"$cmd\"");
+ run_or_bail(['psql', '-q', '--no-psqlrc', '-d', $connstr_standby,
+ '-c', "$cmd"]);
}
# Run a query against the master, and check that the output matches what's
@@ -171,16 +172,6 @@ sub append_to_file
close $fh;
}
-sub init_rewind_test
-{
- my $testname = shift;
- my $test_mode = shift;
-
- $log_path = "regress_log/pg_rewind_log_${testname}_${test_mode}";
-
- remove_tree $log_path;
-}
-
sub setup_cluster
{
$tempdir_short = tempdir_short;
@@ -209,8 +200,10 @@ max_connections = 10
local replication all trust
));
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl' , '-w', '-D' , $test_master_datadir,
+ "-o", "-k $tempdir_short --listen-addresses='' -p $port_master",
+ 'start']
);
#### Now run the test-specific parts to initialize the master before setting
@@ -225,8 +218,9 @@ sub create_standby
remove_tree $test_standby_datadir;
# Base backup is taken with xlog files included
- system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_basebackup', '-D', $test_standby_datadir, '-p',
+ $port_master, '-x']);
append_to_file(
"$test_standby_datadir/recovery.conf", qq(
primary_conninfo='$connstr_master application_name=rewind_standby'
@@ -235,8 +229,9 @@ recovery_target_timeline='latest'
));
# Start standby
- system_or_bail(
-"pg_ctl -w -D $test_standby_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_standby\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_standby_datadir , '-o',
+ "-k $tempdir_short --listen-addresses='' -p $port_standby", 'start']
);
# Wait until the standby has caught up with the primary, by polling
@@ -255,8 +250,8 @@ sub promote_standby
# Now promote slave and insert some new data on master, this will put
# the master out-of-sync with the standby. Wait until the standby is
# out of recovery mode, and is ready to accept read-write connections.
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir promote >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_standby_datadir, 'promote']);
poll_query_until("SELECT NOT pg_is_in_recovery()", $connstr_standby)
or die "Timed out while waiting for promotion of standby";
@@ -274,8 +269,8 @@ sub run_pg_rewind
my $test_mode = shift;
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_master_datadir stop -m fast >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_ctl', '-D', $test_master_datadir, 'stop', '-m', 'fast']);
# At this point, the rewind processing is ready to run.
# We now have a very simple scenario with a few diverged WAL record.
@@ -294,31 +289,25 @@ sub run_pg_rewind
# Do rewind using a local pgdata as source
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir stop -m fast >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-D', $test_standby_datadir, 'stop', '-m', 'fast']
);
- my $result = run(
+ my $result = run_log(
[ 'pg_rewind',
"--debug",
"--source-pgdata=$test_standby_datadir",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
+ "--target-pgdata=$test_master_datadir" ]);
ok($result, 'pg_rewind local');
}
elsif ($test_mode eq "remote")
{
# Do rewind using a remote connection as source
- my $result = run(
+ my $result = run_log(
[ 'pg_rewind',
"--source-server",
"port=$port_standby dbname=postgres",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
+ "--target-pgdata=$test_master_datadir" ]);
ok($result, 'pg_rewind remote');
}
else
@@ -342,8 +331,9 @@ recovery_target_timeline='latest'
));
# Restart the master to check that rewind went correctly
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_master_datadir, '-o',
+ "-k $tempdir_short --listen-addresses='' -p $port_master", 'start']
);
#### Now run the test-specific parts to check the result
@@ -354,13 +344,15 @@ sub clean_rewind_test
{
if ($test_master_datadir)
{
- system
- "pg_ctl -D $test_master_datadir -s -m immediate stop 2> /dev/null";
+ run_log(
+ ['pg_ctl', '-D', $test_master_datadir, '-m', 'immediate',
+ 'stop']);
}
if ($test_standby_datadir)
{
- system
- "pg_ctl -D $test_standby_datadir -s -m immediate stop 2> /dev/null";
+ run_log(
+ ['pg_ctl', '-D', $test_standby_datadir, '-m', 'immediate',
+ 'stop']);
}
}
diff --git a/src/bin/pg_rewind/t/001_basic.pl b/src/bin/pg_rewind/t/001_basic.pl
index f60368b..be7d887 100644
--- a/src/bin/pg_rewind/t/001_basic.pl
+++ b/src/bin/pg_rewind/t/001_basic.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('basic', $test_mode);
RewindTest::setup_cluster();
# Create a test table and insert a row in master.
diff --git a/src/bin/pg_rewind/t/002_databases.pl b/src/bin/pg_rewind/t/002_databases.pl
index 7564fa9..b0b007a 100644
--- a/src/bin/pg_rewind/t/002_databases.pl
+++ b/src/bin/pg_rewind/t/002_databases.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('databases', $test_mode);
RewindTest::setup_cluster();
# Create a database in master.
diff --git a/src/bin/pg_rewind/t/003_extrafiles.pl b/src/bin/pg_rewind/t/003_extrafiles.pl
index 9a95268..0cd0ac4 100644
--- a/src/bin/pg_rewind/t/003_extrafiles.pl
+++ b/src/bin/pg_rewind/t/003_extrafiles.pl
@@ -14,7 +14,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('extrafiles', $test_mode);
RewindTest::setup_cluster();
my $test_master_datadir = $RewindTest::test_master_datadir;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index ef42366..98fefce 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -12,6 +12,8 @@ our @EXPORT = qw(
restart_test_server
psql
system_or_bail
+ run_or_bail
+ run_log
command_ok
command_fails
@@ -24,11 +26,20 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
use Test::More;
+# Log file location. For each test, the log file name uses the name of the
+# file launching this module, without its file prefix for readability.
+my $log_path = 'tmp_check/log';
+mkdir 'tmp_check';
+mkdir $log_path;
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = "$log_path/regress_log_$test_logfile";
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -77,9 +88,9 @@ sub tempdir_short
sub standard_initdb
{
my $pgdata = shift;
- system_or_bail("initdb -D '$pgdata' -A trust -N >/dev/null");
- system_or_bail("$ENV{top_builddir}/src/test/regress/pg_regress",
- '--config-auth', $pgdata);
+ run_or_bail(['initdb', '-D', "$pgdata", '-A' , 'trust', '-N']);
+ run_or_bail(["$ENV{top_builddir}/src/test/regress/pg_regress",
+ '--config-auth', $pgdata]);
}
my ($test_server_datadir, $test_server_logfile);
@@ -92,14 +103,14 @@ sub start_test_server
my $tempdir_short = tempdir_short;
standard_initdb "$tempdir/pgdata";
- $ret = system 'pg_ctl', '-D', "$tempdir/pgdata", '-s', '-w', '-l',
+ $ret = run_log(['pg_ctl', '-D', "$tempdir/pgdata", '-w', '-l',
"$tempdir/logfile", '-o',
-"--fsync=off -k $tempdir_short --listen-addresses='' --log-statement=all",
- 'start';
+"--fsync=off -k \"$tempdir_short\" --listen-addresses='' --log-statement=all",
+ 'start']);
- if ($ret != 0)
+ if (!$ret)
{
- system('cat', "$tempdir/logfile");
+ run_log(['cat', "$tempdir/logfile"]);
BAIL_OUT("pg_ctl failed");
}
@@ -110,16 +121,16 @@ sub start_test_server
sub restart_test_server
{
- system 'pg_ctl', '-s', '-D', $test_server_datadir, '-w', '-l',
- $test_server_logfile, 'restart';
+ run_log(['pg_ctl', '-D', $test_server_datadir, '-w', '-l',
+ $test_server_logfile, 'restart']);
}
END
{
if ($test_server_datadir)
{
- system 'pg_ctl', '-D', $test_server_datadir, '-s', '-w', '-m',
- 'immediate', 'stop';
+ run_log(['pg_ctl', '-D', $test_server_datadir, '-m',
+ 'immediate', 'stop']);
}
}
@@ -131,7 +142,22 @@ sub psql
sub system_or_bail
{
- system(@_) == 0 or BAIL_OUT("system @_ failed: $?");
+ system(@_) == 0 or BAIL_OUT("system $_[0] failed: $?");
+}
+
+sub run_log
+{
+ my $result = run (@_, '>>', $test_logfile, '2>&1');
+ return $result;
+}
+
+sub run_or_bail
+{
+ my $result = run (@_, '>>', $test_logfile, '2>&1');
+ if (!$result)
+ {
+ BAIL_OUT("run $_[0] failed: $?");
+ }
}
diff --git a/src/test/ssl/ServerSetup.pm b/src/test/ssl/ServerSetup.pm
index bbff99a..2293d1b 100644
--- a/src/test/ssl/ServerSetup.pm
+++ b/src/test/ssl/ServerSetup.pm
@@ -125,8 +125,6 @@ sub switch_server_cert
# restart_test_server() because that overrides listen_addresses to only all
# Unix domain socket connections.
- system_or_bail 'pg_ctl', 'stop', '-s', '-D', "$tempdir/pgdata", '-w';
- system_or_bail 'pg_ctl', 'start', '-s', '-D', "$tempdir/pgdata", '-w',
- '-l',
- "$tempdir/logfile";
+ run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/pgdata"]);
+ run_or_bail(['pg_ctl', 'start', '-D', "$tempdir/pgdata", '-w']);
}
--
2.4.4
On Thu, June 25, 2015 06:14, Michael Paquier wrote:
I have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
IPC::Run is not in perl core and will not always be available.
It looks like this patch doesn't take this into account (when no IPC::Run skip the test or whatever)
Shouldn't that be changed?
Thanks,
Erik Rijkers
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Jun 25, 2015 at 3:59 PM, Erik Rijkers <er@xs4all.nl> wrote:
IPC::Run is not in perl core and will not always be available.
It looks like this patch doesn't take this into account (when no IPC::Run skip the test or whatever)
Shouldn't that be changed?
Yes, there have been discussions on the matter already:
/messages/by-id/20141102190024.GA538247@tornado.leadboat.com
We may want to be able to capture easily the outputs of stdout and
stderr as well though and not only get the exit code. That looks
important to improve the debuggability of the whole thing when kicking
in commands. And to have that working on Windows as well..
Regards,
--
Michael
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 06/25/2015 07:14 AM, Michael Paquier wrote:
After looking at the issues with the TAP test suite that hamster faced
a couple of days ago, which is what has been discussed on this thread:
/messages/by-id/13002.1434307025@sss.pgh.pa.usI have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
that is not able to help much) that has already been sent on the
thread above.
This is a massive improvement to the usability of TAP tests. They are
practically impossible to debug currently. Thanks for working on this!
The patch redirects the output of all "system_or_bail" commands to a log
file. That's a good start, but I wish we could get *everything* in the
same log file. That includes also:
* stdout and stderr of *all* commands. Including all the commands run
with command_ok/command_fails.
* the command line of commands being executed. It's difficult to follow
the log when you don't know which output corresponds to which command.
* whenever a test case is reported as success/fail.
Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes a copy of them (when? at program startup I guess..). That would be
much more convenient than decorating every run call with ">> logfile".
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Jul 8, 2015 at 6:10 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:
On 06/25/2015 07:14 AM, Michael Paquier wrote:
After looking at the issues with the TAP test suite that hamster faced
a couple of days ago, which is what has been discussed on this thread:
/messages/by-id/13002.1434307025@sss.pgh.pa.usI have developed a patch to improve log capture of the TAP tests by
being able to collect stderr and stdout output of each command run in
the tests by using more extensively IPC::Run::run (instead of system()
that is not able to help much) that has already been sent on the
thread above.This is a massive improvement to the usability of TAP tests. They are
practically impossible to debug currently. Thanks for working on this!The patch redirects the output of all "system_or_bail" commands to a log
file. That's a good start, but I wish we could get *everything* in the same
log file. That includes also:* stdout and stderr of *all* commands. Including all the commands run with
command_ok/command_fails.
That makes sense. I have switched command_ok, command_exit_is and
command_fails to show up their output instead of having them sent to
void.
* the command line of commands being executed. It's difficult to follow the
log when you don't know which output corresponds to which command.
OK, I have added some stuff for that. Let me know your thoughts. Each
command started is printed in the log file before starting with a
message mentioning what is the type of test used.
* whenever a test case is reported as success/fail.
Just to be sure, does this concern the "ok/not ok" messages printed
out by each test run? Or is it a custom message that you have in mind?
Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More takes
a copy of them (when? at program startup I guess..). That would be much more
convenient than decorating every run call with ">> logfile".
Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;
While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file. Also, the output can be correctly captured by just
appending that to a couple of places:
[ '>>', $test_logfile, '2>&1']
And this solution proves to work as well on Windows...
--
Michael
Attachments:
20150708_tap_improve_logs_v4.patchtext/x-diff; charset=US-ASCII; name=20150708_tap_improve_logs_v4.patchDownload
From dccb8d2226ea2ffa40fd9702cbc26196f214471d Mon Sep 17 00:00:00 2001
From: Michael Paquier <michael@otacoo.com>
Date: Wed, 8 Jul 2015 17:24:24 +0900
Subject: [PATCH] Improve log capture of TAP tests and fix race conditions
All tests have their logs stored as regress_log/$TEST_NAME, with content
captured from the many commands run during the tests. Commands that were
previously called in silent mode are made verbose and have their output
written in the newly-created log files.
---
src/Makefile.global.in | 1 +
src/bin/pg_basebackup/t/010_pg_basebackup.pl | 4 +-
src/bin/pg_controldata/t/001_pg_controldata.pl | 2 +-
src/bin/pg_ctl/t/001_start_stop.pl | 2 +-
src/bin/pg_ctl/t/002_status.pl | 6 +-
src/bin/pg_rewind/.gitignore | 1 -
src/bin/pg_rewind/Makefile | 2 +-
src/bin/pg_rewind/RewindTest.pm | 74 ++++++++++-------------
src/bin/pg_rewind/t/001_basic.pl | 1 -
src/bin/pg_rewind/t/002_databases.pl | 1 -
src/bin/pg_rewind/t/003_extrafiles.pl | 1 -
src/test/perl/TestLib.pm | 83 ++++++++++++++++++++------
src/test/ssl/ServerSetup.pm | 6 +-
13 files changed, 109 insertions(+), 75 deletions(-)
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index 8eab178..8d1250d 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -337,6 +337,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
+rm -rf $(srcdir)/tmp_check/log
cd $(srcdir) && TESTDIR='$(CURDIR)' $(with_temp_install) PGPORT='6$(DEF_PGPORT)' top_builddir='$(CURDIR)/$(top_builddir)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
endef
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index c8c9250..10a523b 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -30,7 +30,7 @@ print HBA "local replication all trust\n";
print HBA "host replication all 127.0.0.1/32 trust\n";
print HBA "host replication all ::1/128 trust\n";
close HBA;
-system_or_bail 'pg_ctl', '-s', '-D', "$tempdir/pgdata", 'reload';
+run_or_bail(['pg_ctl', '-D', "$tempdir/pgdata", 'reload']);
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
@@ -59,7 +59,7 @@ ok(-f "$tempdir/tarbackup/base.tar", 'backup tar was created');
my $superlongname = "superlongname_" . ("x" x 100);
-system_or_bail 'touch', "$tempdir/pgdata/$superlongname";
+run_or_bail(['touch', "$tempdir/pgdata/$superlongname"]);
command_fails([ 'pg_basebackup', '-D', "$tempdir/tarbackup_l1", '-Ft' ],
'pg_basebackup tar with long name fails');
unlink "$tempdir/pgdata/$superlongname";
diff --git a/src/bin/pg_controldata/t/001_pg_controldata.pl b/src/bin/pg_controldata/t/001_pg_controldata.pl
index a4180e7..0d1407e 100644
--- a/src/bin/pg_controldata/t/001_pg_controldata.pl
+++ b/src/bin/pg_controldata/t/001_pg_controldata.pl
@@ -11,6 +11,6 @@ program_options_handling_ok('pg_controldata');
command_fails(['pg_controldata'], 'pg_controldata without arguments fails');
command_fails([ 'pg_controldata', 'nonexistent' ],
'pg_controldata with nonexistent directory fails');
-system_or_bail "initdb -D '$tempdir'/data -A trust >/dev/null";
+run_or_bail(['initdb', '-D', "$tempdir/data", '-A', 'trust']);
command_like([ 'pg_controldata', "$tempdir/data" ],
qr/checkpoint/, 'pg_controldata produces output');
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 6c9ec5c..57563d7 100644
--- a/src/bin/pg_ctl/t/001_start_stop.pl
+++ b/src/bin/pg_ctl/t/001_start_stop.pl
@@ -36,4 +36,4 @@ command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
'pg_ctl restart with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast']);
diff --git a/src/bin/pg_ctl/t/002_status.pl b/src/bin/pg_ctl/t/002_status.pl
index 0558854..d1192f6 100644
--- a/src/bin/pg_ctl/t/002_status.pl
+++ b/src/bin/pg_ctl/t/002_status.pl
@@ -18,9 +18,9 @@ close CONF;
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
3, 'pg_ctl status with server not running');
-system_or_bail 'pg_ctl', '-s', '-l', "$tempdir/logfile", '-D',
- "$tempdir/data", '-w', 'start';
+run_or_bail(['pg_ctl', '-l', "$tempdir/logfile", '-D',
+ "$tempdir/data", '-w', 'start']);
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
0, 'pg_ctl status with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast']);
diff --git a/src/bin/pg_rewind/.gitignore b/src/bin/pg_rewind/.gitignore
index 9ade7ef..79ddca3 100644
--- a/src/bin/pg_rewind/.gitignore
+++ b/src/bin/pg_rewind/.gitignore
@@ -4,4 +4,3 @@
# Generated by test suite
/tmp_check/
-/regress_log/
diff --git a/src/bin/pg_rewind/Makefile b/src/bin/pg_rewind/Makefile
index 7d60715..92b5d20 100644
--- a/src/bin/pg_rewind/Makefile
+++ b/src/bin/pg_rewind/Makefile
@@ -45,7 +45,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_rewind$(X) $(OBJS) xlogreader.c
- rm -rf tmp_check regress_log
+ rm -rf tmp_check
check:
$(prove_check)
diff --git a/src/bin/pg_rewind/RewindTest.pm b/src/bin/pg_rewind/RewindTest.pm
index 5219ec9..814bffa 100644
--- a/src/bin/pg_rewind/RewindTest.pm
+++ b/src/bin/pg_rewind/RewindTest.pm
@@ -79,7 +79,6 @@ mkdir "regress_log";
my $port_master = $ENV{PGPORT};
my $port_standby = $port_master + 1;
-my $log_path;
my $tempdir_short;
my $connstr_master = "port=$port_master";
@@ -91,14 +90,16 @@ sub master_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_master -c \"$cmd\"");
+ run_or_bail(['psql', '-q', '--no-psqlrc', '-d', $connstr_master,
+ '-c', "$cmd"]);
}
sub standby_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_standby -c \"$cmd\"");
+ run_or_bail(['psql', '-q', '--no-psqlrc', '-d', $connstr_standby,
+ '-c', "$cmd"]);
}
# Run a query against the master, and check that the output matches what's
@@ -171,16 +172,6 @@ sub append_to_file
close $fh;
}
-sub init_rewind_test
-{
- my $testname = shift;
- my $test_mode = shift;
-
- $log_path = "regress_log/pg_rewind_log_${testname}_${test_mode}";
-
- remove_tree $log_path;
-}
-
sub setup_cluster
{
$tempdir_short = tempdir_short;
@@ -209,8 +200,10 @@ max_connections = 10
local replication all trust
));
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl' , '-w', '-D' , $test_master_datadir,
+ "-o", "-k $tempdir_short --listen-addresses='' -p $port_master",
+ 'start']
);
#### Now run the test-specific parts to initialize the master before setting
@@ -225,8 +218,9 @@ sub create_standby
remove_tree $test_standby_datadir;
# Base backup is taken with xlog files included
- system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_basebackup', '-D', $test_standby_datadir, '-p',
+ $port_master, '-x']);
append_to_file(
"$test_standby_datadir/recovery.conf", qq(
primary_conninfo='$connstr_master application_name=rewind_standby'
@@ -235,8 +229,9 @@ recovery_target_timeline='latest'
));
# Start standby
- system_or_bail(
-"pg_ctl -w -D $test_standby_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_standby\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_standby_datadir , '-o',
+ "-k $tempdir_short --listen-addresses='' -p $port_standby", 'start']
);
# Wait until the standby has caught up with the primary, by polling
@@ -255,8 +250,8 @@ sub promote_standby
# Now promote slave and insert some new data on master, this will put
# the master out-of-sync with the standby. Wait until the standby is
# out of recovery mode, and is ready to accept read-write connections.
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir promote >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_standby_datadir, 'promote']);
poll_query_until("SELECT NOT pg_is_in_recovery()", $connstr_standby)
or die "Timed out while waiting for promotion of standby";
@@ -274,8 +269,8 @@ sub run_pg_rewind
my $test_mode = shift;
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_master_datadir stop -m fast >>$log_path 2>&1");
+ run_or_bail(
+ ['pg_ctl', '-D', $test_master_datadir, 'stop', '-m', 'fast']);
# At this point, the rewind processing is ready to run.
# We now have a very simple scenario with a few diverged WAL record.
@@ -294,31 +289,25 @@ sub run_pg_rewind
# Do rewind using a local pgdata as source
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir stop -m fast >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-D', $test_standby_datadir, 'stop', '-m', 'fast']
);
- my $result = run(
+ my $result = run_log(
[ 'pg_rewind',
"--debug",
"--source-pgdata=$test_standby_datadir",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
+ "--target-pgdata=$test_master_datadir" ]);
ok($result, 'pg_rewind local');
}
elsif ($test_mode eq "remote")
{
# Do rewind using a remote connection as source
- my $result = run(
+ my $result = run_log(
[ 'pg_rewind',
"--source-server",
"port=$port_standby dbname=postgres",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
+ "--target-pgdata=$test_master_datadir" ]);
ok($result, 'pg_rewind remote');
}
else
@@ -342,8 +331,9 @@ recovery_target_timeline='latest'
));
# Restart the master to check that rewind went correctly
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
+ run_or_bail(
+ ['pg_ctl', '-w', '-D', $test_master_datadir, '-o',
+ "-k $tempdir_short --listen-addresses='' -p $port_master", 'start']
);
#### Now run the test-specific parts to check the result
@@ -354,13 +344,15 @@ sub clean_rewind_test
{
if ($test_master_datadir)
{
- system
- "pg_ctl -D $test_master_datadir -s -m immediate stop 2> /dev/null";
+ run_log(
+ ['pg_ctl', '-D', $test_master_datadir, '-m', 'immediate',
+ 'stop']);
}
if ($test_standby_datadir)
{
- system
- "pg_ctl -D $test_standby_datadir -s -m immediate stop 2> /dev/null";
+ run_log(
+ ['pg_ctl', '-D', $test_standby_datadir, '-m', 'immediate',
+ 'stop']);
}
}
diff --git a/src/bin/pg_rewind/t/001_basic.pl b/src/bin/pg_rewind/t/001_basic.pl
index f60368b..be7d887 100644
--- a/src/bin/pg_rewind/t/001_basic.pl
+++ b/src/bin/pg_rewind/t/001_basic.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('basic', $test_mode);
RewindTest::setup_cluster();
# Create a test table and insert a row in master.
diff --git a/src/bin/pg_rewind/t/002_databases.pl b/src/bin/pg_rewind/t/002_databases.pl
index 7564fa9..b0b007a 100644
--- a/src/bin/pg_rewind/t/002_databases.pl
+++ b/src/bin/pg_rewind/t/002_databases.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('databases', $test_mode);
RewindTest::setup_cluster();
# Create a database in master.
diff --git a/src/bin/pg_rewind/t/003_extrafiles.pl b/src/bin/pg_rewind/t/003_extrafiles.pl
index 9a95268..0cd0ac4 100644
--- a/src/bin/pg_rewind/t/003_extrafiles.pl
+++ b/src/bin/pg_rewind/t/003_extrafiles.pl
@@ -14,7 +14,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('extrafiles', $test_mode);
RewindTest::setup_cluster();
my $test_master_datadir = $RewindTest::test_master_datadir;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index ef42366..40a5236 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -12,6 +12,8 @@ our @EXPORT = qw(
restart_test_server
psql
system_or_bail
+ run_or_bail
+ run_log
command_ok
command_fails
@@ -24,11 +26,20 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
use Test::More;
+# Log file location. For each test, the log file name uses the name of the
+# file launching this module, without its file prefix for readability.
+my $log_path = 'tmp_check/log';
+mkdir 'tmp_check';
+mkdir $log_path;
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = "$log_path/regress_log_$test_logfile";
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -77,9 +88,9 @@ sub tempdir_short
sub standard_initdb
{
my $pgdata = shift;
- system_or_bail("initdb -D '$pgdata' -A trust -N >/dev/null");
- system_or_bail("$ENV{top_builddir}/src/test/regress/pg_regress",
- '--config-auth', $pgdata);
+ run_or_bail(['initdb', '-D', "$pgdata", '-A' , 'trust', '-N']);
+ run_or_bail(["$ENV{top_builddir}/src/test/regress/pg_regress",
+ '--config-auth', $pgdata]);
}
my ($test_server_datadir, $test_server_logfile);
@@ -92,14 +103,14 @@ sub start_test_server
my $tempdir_short = tempdir_short;
standard_initdb "$tempdir/pgdata";
- $ret = system 'pg_ctl', '-D', "$tempdir/pgdata", '-s', '-w', '-l',
+ $ret = run_log(['pg_ctl', '-D', "$tempdir/pgdata", '-w', '-l',
"$tempdir/logfile", '-o',
-"--fsync=off -k $tempdir_short --listen-addresses='' --log-statement=all",
- 'start';
+"--fsync=off -k \"$tempdir_short\" --listen-addresses='' --log-statement=all",
+ 'start']);
- if ($ret != 0)
+ if (!$ret)
{
- system('cat', "$tempdir/logfile");
+ run_log(['cat', "$tempdir/logfile"]);
BAIL_OUT("pg_ctl failed");
}
@@ -110,16 +121,16 @@ sub start_test_server
sub restart_test_server
{
- system 'pg_ctl', '-s', '-D', $test_server_datadir, '-w', '-l',
- $test_server_logfile, 'restart';
+ run_log(['pg_ctl', '-D', $test_server_datadir, '-w', '-l',
+ $test_server_logfile, 'restart']);
}
END
{
if ($test_server_datadir)
{
- system 'pg_ctl', '-D', $test_server_datadir, '-s', '-w', '-m',
- 'immediate', 'stop';
+ run_log(['pg_ctl', '-D', $test_server_datadir, '-m',
+ 'immediate', 'stop']);
}
}
@@ -131,11 +142,41 @@ sub psql
sub system_or_bail
{
- system(@_) == 0 or BAIL_OUT("system @_ failed: $?");
+ system(@_) == 0 or BAIL_OUT("system $_[0] failed: $?");
+}
+
+sub run_log
+{
+ my $result = run (@_, '>>', $test_logfile, '2>&1');
+ return $result;
+}
+
+sub run_or_bail
+{
+ my $result = run (@_, '>>', $test_logfile, '2>&1');
+ if (!$result)
+ {
+ BAIL_OUT("run $_[0] failed: $?");
+ }
}
#
+# Log functions
+#
+sub log_start
+{
+ my $cmd = shift;
+ my $description = shift;
+
+ open LOGFILE, ">> $test_logfile";
+ print LOGFILE "$description\n";
+ print LOGFILE "Command: ", join(" ", @{$cmd});
+ print LOGFILE "\n\n";
+ close LOGFILE;
+}
+
+#
# Test functions
#
@@ -143,15 +184,16 @@ sub system_or_bail
sub command_ok
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ log_start($cmd, "command OK: Starting test $test_name");
+ my $result = run $cmd, '>>', $test_logfile, '2>&1';
ok($result, $test_name);
}
sub command_fails
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
+ log_start($cmd, "command fails: Starting test $test_name");
+ my $result = run $cmd, '>>', $test_logfile, '2>&1';
File::Spec->devnull();
ok(!$result, $test_name);
}
@@ -159,8 +201,8 @@ sub command_fails
sub command_exit_is
{
my ($cmd, $expected, $test_name) = @_;
- my $h = start $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ log_start($cmd, "command exit code: Starting test $test_name");
+ my $h = start $cmd, '>>', $test_logfile, '2>&1';
$h->finish();
is($h->result(0), $expected, $test_name);
}
@@ -169,6 +211,7 @@ sub program_help_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ log_start([ $cmd ], "Running test help OK");
my $result = run [ $cmd, '--help' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --help exit code 0");
isnt($stdout, '', "$cmd --help goes to stdout");
@@ -179,6 +222,7 @@ sub program_version_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ log_start([ $cmd ], "Running test version OK");
my $result = run [ $cmd, '--version' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --version exit code 0");
isnt($stdout, '', "$cmd --version goes to stdout");
@@ -189,6 +233,7 @@ sub program_options_handling_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ log_start([ $cmd ], "Running test of option handling");
my $result = run [ $cmd, '--not-a-valid-option' ], '>', \$stdout, '2>',
\$stderr;
ok(!$result, "$cmd with invalid option nonzero exit code");
@@ -199,6 +244,7 @@ sub command_like
{
my ($cmd, $expected_stdout, $test_name) = @_;
my ($stdout, $stderr);
+ log_start($cmd, "command like: Test $test_name");
my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
ok($result, "@$cmd exit code 0");
is($stderr, '', "@$cmd no stderr");
@@ -210,6 +256,7 @@ sub issues_sql_like
my ($cmd, $expected_sql, $test_name) = @_;
my ($stdout, $stderr);
truncate $test_server_logfile, 0;
+ log_start($cmd, "issues SQL like: Test $test_name");
my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
ok($result, "@$cmd exit code 0");
my $log = `cat '$test_server_logfile'`;
diff --git a/src/test/ssl/ServerSetup.pm b/src/test/ssl/ServerSetup.pm
index bbff99a..2293d1b 100644
--- a/src/test/ssl/ServerSetup.pm
+++ b/src/test/ssl/ServerSetup.pm
@@ -125,8 +125,6 @@ sub switch_server_cert
# restart_test_server() because that overrides listen_addresses to only all
# Unix domain socket connections.
- system_or_bail 'pg_ctl', 'stop', '-s', '-D', "$tempdir/pgdata", '-w';
- system_or_bail 'pg_ctl', 'start', '-s', '-D', "$tempdir/pgdata", '-w',
- '-l',
- "$tempdir/logfile";
+ run_or_bail(['pg_ctl', 'stop', '-D', "$tempdir/pgdata"]);
+ run_or_bail(['pg_ctl', 'start', '-D', "$tempdir/pgdata", '-w']);
}
--
2.4.5
On 07/08/2015 11:26 AM, Michael Paquier wrote:
On Wed, Jul 8, 2015 at 6:10 AM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:
* whenever a test case is reported as success/fail.
Just to be sure, does this concern the "ok/not ok" messages printed
out by each test run? Or is it a custom message that you have in mind?
Right. It would be nice to have the same output that's printed to the
console also in the log.
Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More takes
a copy of them (when? at program startup I guess..). That would be much more
convenient than decorating every run call with ">> logfile".Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.
Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But
it's Windows, so who knows..
I came up with the attached, which does that. It also plays some tricks
with perl "tie", to copy the "ok - ..." lines that go to the console, to
the log.
I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?
Also, the output can be correctly captured by just
appending that to a couple of places:
[ '>>', $test_logfile, '2>&1']
And this solution proves to work as well on Windows...
Yeah, but that's tedious.
- Heikki
Attachments:
improve-TAP-logging-2.patchtext/x-diff; name=improve-TAP-logging-2.patchDownload
commit 70b922632412c2719c0d21b00a4abf0cb6062f5b
Author: Heikki Linnakangas <heikki.linnakangas@iki.fi>
Date: Wed Jul 8 18:14:16 2015 +0300
Improve logging in TAP tests
WIP
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index 8eab178..8d1250d 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -337,6 +337,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
+rm -rf $(srcdir)/tmp_check/log
cd $(srcdir) && TESTDIR='$(CURDIR)' $(with_temp_install) PGPORT='6$(DEF_PGPORT)' top_builddir='$(CURDIR)/$(top_builddir)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
endef
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index c8c9250..e47c3a0 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -30,7 +30,7 @@ print HBA "local replication all trust\n";
print HBA "host replication all 127.0.0.1/32 trust\n";
print HBA "host replication all ::1/128 trust\n";
close HBA;
-system_or_bail 'pg_ctl', '-s', '-D', "$tempdir/pgdata", 'reload';
+system_or_bail 'pg_ctl', '-D', "$tempdir/pgdata", 'reload';
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
diff --git a/src/bin/pg_controldata/t/001_pg_controldata.pl b/src/bin/pg_controldata/t/001_pg_controldata.pl
index a4180e7..e36fa2d 100644
--- a/src/bin/pg_controldata/t/001_pg_controldata.pl
+++ b/src/bin/pg_controldata/t/001_pg_controldata.pl
@@ -11,6 +11,6 @@ program_options_handling_ok('pg_controldata');
command_fails(['pg_controldata'], 'pg_controldata without arguments fails');
command_fails([ 'pg_controldata', 'nonexistent' ],
'pg_controldata with nonexistent directory fails');
-system_or_bail "initdb -D '$tempdir'/data -A trust >/dev/null";
+system_or_bail 'initdb', '-D', "$tempdir/data", '-A', 'trust';
command_like([ 'pg_controldata', "$tempdir/data" ],
qr/checkpoint/, 'pg_controldata produces output');
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 6c9ec5c..bcceb57d 100644
--- a/src/bin/pg_ctl/t/001_start_stop.pl
+++ b/src/bin/pg_ctl/t/001_start_stop.pl
@@ -36,4 +36,4 @@ command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
'pg_ctl restart with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/bin/pg_ctl/t/002_status.pl b/src/bin/pg_ctl/t/002_status.pl
index 0558854..ec0a2a7 100644
--- a/src/bin/pg_ctl/t/002_status.pl
+++ b/src/bin/pg_ctl/t/002_status.pl
@@ -18,9 +18,9 @@ close CONF;
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
3, 'pg_ctl status with server not running');
-system_or_bail 'pg_ctl', '-s', '-l', "$tempdir/logfile", '-D',
+system_or_bail 'pg_ctl', '-l', "$tempdir/logfile", '-D',
"$tempdir/data", '-w', 'start';
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
0, 'pg_ctl status with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/bin/pg_rewind/.gitignore b/src/bin/pg_rewind/.gitignore
index 9ade7ef..79ddca3 100644
--- a/src/bin/pg_rewind/.gitignore
+++ b/src/bin/pg_rewind/.gitignore
@@ -4,4 +4,3 @@
# Generated by test suite
/tmp_check/
-/regress_log/
diff --git a/src/bin/pg_rewind/Makefile b/src/bin/pg_rewind/Makefile
index 7d60715..92b5d20 100644
--- a/src/bin/pg_rewind/Makefile
+++ b/src/bin/pg_rewind/Makefile
@@ -45,7 +45,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_rewind$(X) $(OBJS) xlogreader.c
- rm -rf tmp_check regress_log
+ rm -rf tmp_check
check:
$(prove_check)
diff --git a/src/bin/pg_rewind/RewindTest.pm b/src/bin/pg_rewind/RewindTest.pm
index 5219ec9..af2d73b 100644
--- a/src/bin/pg_rewind/RewindTest.pm
+++ b/src/bin/pg_rewind/RewindTest.pm
@@ -79,7 +79,6 @@ mkdir "regress_log";
my $port_master = $ENV{PGPORT};
my $port_standby = $port_master + 1;
-my $log_path;
my $tempdir_short;
my $connstr_master = "port=$port_master";
@@ -91,14 +90,16 @@ sub master_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_master -c \"$cmd\"");
+ system_or_bail 'psql', '-q', '--no-psqlrc', '-d', $connstr_master,
+ '-c', "$cmd";
}
sub standby_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_standby -c \"$cmd\"");
+ system_or_bail 'psql', '-q', '--no-psqlrc', '-d', $connstr_standby,
+ '-c', "$cmd";
}
# Run a query against the master, and check that the output matches what's
@@ -171,16 +172,6 @@ sub append_to_file
close $fh;
}
-sub init_rewind_test
-{
- my $testname = shift;
- my $test_mode = shift;
-
- $log_path = "regress_log/pg_rewind_log_${testname}_${test_mode}";
-
- remove_tree $log_path;
-}
-
sub setup_cluster
{
$tempdir_short = tempdir_short;
@@ -209,9 +200,10 @@ max_connections = 10
local replication all trust
));
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
- );
+ system_or_bail('pg_ctl' , '-w',
+ '-D' , $test_master_datadir,
+ "-o", "-k $tempdir_short --listen-addresses='' -p $port_master",
+ 'start');
#### Now run the test-specific parts to initialize the master before setting
# up standby
@@ -225,8 +217,8 @@ sub create_standby
remove_tree $test_standby_datadir;
# Base backup is taken with xlog files included
- system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+ system_or_bail('pg_basebackup', '-D', $test_standby_datadir,
+ '-p', $port_master, '-x';
append_to_file(
"$test_standby_datadir/recovery.conf", qq(
primary_conninfo='$connstr_master application_name=rewind_standby'
@@ -235,9 +227,9 @@ recovery_target_timeline='latest'
));
# Start standby
- system_or_bail(
-"pg_ctl -w -D $test_standby_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_standby\" start >>$log_path 2>&1"
- );
+ system_or_bail('pg_ctl', '-w', '-D', $test_standby_datadir,
+ '-o', "-k $tempdir_short --listen-addresses='' -p $port_standby",
+ 'start');
# Wait until the standby has caught up with the primary, by polling
# pg_stat_replication.
@@ -255,8 +247,7 @@ sub promote_standby
# Now promote slave and insert some new data on master, this will put
# the master out-of-sync with the standby. Wait until the standby is
# out of recovery mode, and is ready to accept read-write connections.
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir promote >>$log_path 2>&1");
+ system_or_bail('pg_ctl', '-w', '-D', $test_standby_datadir, 'promote');
poll_query_until("SELECT NOT pg_is_in_recovery()", $connstr_standby)
or die "Timed out while waiting for promotion of standby";
@@ -274,8 +265,7 @@ sub run_pg_rewind
my $test_mode = shift;
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_master_datadir stop -m fast >>$log_path 2>&1");
+ system_or_bail('pg_ctl', '-D', $test_master_datadir, 'stop', '-m', 'fast');
# At this point, the rewind processing is ready to run.
# We now have a very simple scenario with a few diverged WAL record.
@@ -291,35 +281,24 @@ sub run_pg_rewind
# Now run pg_rewind
if ($test_mode eq "local")
{
-
# Do rewind using a local pgdata as source
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir stop -m fast >>$log_path 2>&1"
- );
- my $result = run(
- [ 'pg_rewind',
- "--debug",
- "--source-pgdata=$test_standby_datadir",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
- ok($result, 'pg_rewind local');
+ system_or_bail('pg_ctl', '-D', $test_standby_datadir, 'stop',
+ '-m', 'fast');
+ command_ok(['pg_rewind',
+ "--debug",
+ "--source-pgdata=$test_standby_datadir",
+ "--target-pgdata=$test_master_datadir"],
+ 'pg_rewind local');
}
elsif ($test_mode eq "remote")
{
-
# Do rewind using a remote connection as source
- my $result = run(
- [ 'pg_rewind',
- "--source-server",
- "port=$port_standby dbname=postgres",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
- ok($result, 'pg_rewind remote');
+ command_ok(['pg_rewind',
+ "--source-server",
+ "port=$port_standby dbname=postgres",
+ "--target-pgdata=$test_master_datadir"],
+ 'pg_rewind remote');
}
else
{
@@ -342,9 +321,9 @@ recovery_target_timeline='latest'
));
# Restart the master to check that rewind went correctly
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
- );
+ system_or_bail('pg_ctl', '-w', '-D', $test_master_datadir,
+ '-o', "-k $tempdir_short --listen-addresses='' -p $port_master",
+ 'start');
#### Now run the test-specific parts to check the result
}
@@ -355,12 +334,12 @@ sub clean_rewind_test
if ($test_master_datadir)
{
system
- "pg_ctl -D $test_master_datadir -s -m immediate stop 2> /dev/null";
+ 'pg_ctl', '-D', $test_master_datadir, '-m', 'immediate', 'stop';
}
if ($test_standby_datadir)
{
system
- "pg_ctl -D $test_standby_datadir -s -m immediate stop 2> /dev/null";
+ 'pg_ctl', '-D', $test_standby_datadir, '-m', 'immediate', 'stop';
}
}
diff --git a/src/bin/pg_rewind/t/001_basic.pl b/src/bin/pg_rewind/t/001_basic.pl
index f60368b..be7d887 100644
--- a/src/bin/pg_rewind/t/001_basic.pl
+++ b/src/bin/pg_rewind/t/001_basic.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('basic', $test_mode);
RewindTest::setup_cluster();
# Create a test table and insert a row in master.
diff --git a/src/bin/pg_rewind/t/002_databases.pl b/src/bin/pg_rewind/t/002_databases.pl
index 7564fa9..b0b007a 100644
--- a/src/bin/pg_rewind/t/002_databases.pl
+++ b/src/bin/pg_rewind/t/002_databases.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('databases', $test_mode);
RewindTest::setup_cluster();
# Create a database in master.
diff --git a/src/bin/pg_rewind/t/003_extrafiles.pl b/src/bin/pg_rewind/t/003_extrafiles.pl
index 9a95268..0cd0ac4 100644
--- a/src/bin/pg_rewind/t/003_extrafiles.pl
+++ b/src/bin/pg_rewind/t/003_extrafiles.pl
@@ -14,7 +14,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('extrafiles', $test_mode);
RewindTest::setup_cluster();
my $test_master_datadir = $RewindTest::test_master_datadir;
diff --git a/src/test/perl/SimpleTee.pm b/src/test/perl/SimpleTee.pm
new file mode 100644
index 0000000..8d31a40
--- /dev/null
+++ b/src/test/perl/SimpleTee.pm
@@ -0,0 +1,27 @@
+# A simple 'tee' implementation, using perl tie.
+#
+# Whenever you print to the handle, it gets forwarded to a list of
+# handles. The list of output filehandles is passed to the constructor.
+#
+# This is similar to IO::Tee, but only used for output. Only the PRINT
+# method is currently implemented; that's all we need. We don't want to
+# depend on IO::Tee just for this.
+
+package SimpleTee;
+use strict;
+
+sub TIEHANDLE {
+ my $self = shift;
+ bless \@_, $self;
+}
+
+sub PRINT {
+ my $self = shift;
+ my $ok = 1;
+ for my $fh (@$self) {
+ print $fh @_ or $ok = 0;
+ }
+ return $ok;
+}
+
+1;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index ef42366..8cf3fc1 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -12,6 +12,8 @@ our @EXPORT = qw(
restart_test_server
psql
system_or_bail
+ system_log
+ run_log
command_ok
command_fails
@@ -24,11 +26,47 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
+
+use SimpleTee;
+
use Test::More;
+# Open log file. For each test, the log file name uses the name of the
+# file launching this module, without its file prefix for readability.
+my $log_path = 'tmp_check/log';
+mkdir 'tmp_check';
+mkdir $log_path;
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = "$log_path/regress_log_$test_logfile";
+open TESTLOG, '>', $test_logfile or die "Cannot open STDOUT to logfile: $!";
+
+# Hijack STDOUT and STDERR to the log file
+open(ORIG_STDOUT, ">&STDOUT");
+open(ORIG_STDERR, ">&STDERR");
+open(STDOUT, ">&TESTLOG");
+open(STDERR, ">&TESTLOG");
+
+# The test output (ok ...) needs to be printed to the original STDOUT
+# so that the 'prove' program can parse it, and also display it to the
+# user in real time. But also copy it to the log file, to provide more
+# context in the log file.
+my $builder = Test::More->builder;
+my $fh = $builder->output;
+tie *$fh, "SimpleTee", *ORIG_STDOUT, *TESTLOG;
+$fh = $builder->failure_output;
+tie *$fh, "SimpleTee", *ORIG_STDERR, *TESTLOG;
+
+# Enable auto-flushing for all the file handles. Stderr and stdout are
+# redirected to the same file, and buffering causes the lines to appear
+# in the log in confusing order.
+autoflush STDOUT 1;
+autoflush STDERR 1;
+autoflush TESTLOG 1;
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -52,7 +90,6 @@ if (!$ENV{PGPORT})
$ENV{PGPORT} = int($ENV{PGPORT}) % 65536;
-
#
# Helper functions
#
@@ -77,7 +114,7 @@ sub tempdir_short
sub standard_initdb
{
my $pgdata = shift;
- system_or_bail("initdb -D '$pgdata' -A trust -N >/dev/null");
+ system_or_bail('initdb', '-D', "$pgdata", '-A' , 'trust', '-N');
system_or_bail("$ENV{top_builddir}/src/test/regress/pg_regress",
'--config-auth', $pgdata);
}
@@ -91,14 +128,15 @@ sub start_test_server
my $tempdir_short = tempdir_short;
+ print("### Starting test server in $tempdir\n");
standard_initdb "$tempdir/pgdata";
- $ret = system 'pg_ctl', '-D', "$tempdir/pgdata", '-s', '-w', '-l',
+ $ret = system_log('pg_ctl', '-D', "$tempdir/pgdata", '-w', '-l',
"$tempdir/logfile", '-o',
-"--fsync=off -k $tempdir_short --listen-addresses='' --log-statement=all",
- 'start';
-
+"--fsync=off -k \"$tempdir_short\" --listen-addresses='' --log-statement=all",
+ 'start');
if ($ret != 0)
{
+ print "# pg_ctl failed; logfile:\n";
system('cat', "$tempdir/logfile");
BAIL_OUT("pg_ctl failed");
}
@@ -110,28 +148,45 @@ sub start_test_server
sub restart_test_server
{
- system 'pg_ctl', '-s', '-D', $test_server_datadir, '-w', '-l',
- $test_server_logfile, 'restart';
+ print("### Restarting test server\n");
+ system_log('pg_ctl', '-D', $test_server_datadir, '-w', '-l',
+ $test_server_logfile, 'restart');
}
END
{
if ($test_server_datadir)
{
- system 'pg_ctl', '-D', $test_server_datadir, '-s', '-w', '-m',
- 'immediate', 'stop';
+ system_log('pg_ctl', '-D', $test_server_datadir, '-m',
+ 'immediate', 'stop');
}
}
sub psql
{
my ($dbname, $sql) = @_;
+ print("# Running SQL command: $sql\n");
run [ 'psql', '-X', '-q', '-d', $dbname, '-f', '-' ], '<', \$sql or die;
}
sub system_or_bail
{
- system(@_) == 0 or BAIL_OUT("system @_ failed: $?");
+ if (system_log(@_) != 0)
+ {
+ BAIL_OUT("system $_[0] failed: $?");
+ }
+}
+
+sub system_log
+{
+ print("# Running: " . join(" ", @_) ."\n");
+ return system(@_);
+}
+
+sub run_log
+{
+ print("# Running: " . join(" ", @{$_[0]}) ."\n");
+ return run (@_);
}
@@ -143,24 +198,22 @@ sub system_or_bail
sub command_ok
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok($result, $test_name);
}
sub command_fails
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok(!$result, $test_name);
}
sub command_exit_is
{
my ($cmd, $expected, $test_name) = @_;
- my $h = start $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ print("# Running: " . join(" ", @{$cmd}) ."\n");
+ my $h = start $cmd;
$h->finish();
is($h->result(0), $expected, $test_name);
}
@@ -169,6 +222,7 @@ sub program_help_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --help\n");
my $result = run [ $cmd, '--help' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --help exit code 0");
isnt($stdout, '', "$cmd --help goes to stdout");
@@ -179,6 +233,7 @@ sub program_version_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --version\n");
my $result = run [ $cmd, '--version' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --version exit code 0");
isnt($stdout, '', "$cmd --version goes to stdout");
@@ -189,6 +244,7 @@ sub program_options_handling_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --not-a-valid-option\n");
my $result = run [ $cmd, '--not-a-valid-option' ], '>', \$stdout, '2>',
\$stderr;
ok(!$result, "$cmd with invalid option nonzero exit code");
@@ -199,6 +255,7 @@ sub command_like
{
my ($cmd, $expected_stdout, $test_name) = @_;
my ($stdout, $stderr);
+ print("# Running: " . join(" ", @{$cmd}) . "\n");
my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
ok($result, "@$cmd exit code 0");
is($stderr, '', "@$cmd no stderr");
@@ -208,9 +265,8 @@ sub command_like
sub issues_sql_like
{
my ($cmd, $expected_sql, $test_name) = @_;
- my ($stdout, $stderr);
truncate $test_server_logfile, 0;
- my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
+ my $result = run_log($cmd);
ok($result, "@$cmd exit code 0");
my $log = `cat '$test_server_logfile'`;
like($log, $expected_sql, "$test_name: SQL found in server log");
diff --git a/src/test/ssl/ServerSetup.pm b/src/test/ssl/ServerSetup.pm
index bbff99a..8c1b517 100644
--- a/src/test/ssl/ServerSetup.pm
+++ b/src/test/ssl/ServerSetup.pm
@@ -125,8 +125,6 @@ sub switch_server_cert
# restart_test_server() because that overrides listen_addresses to only all
# Unix domain socket connections.
- system_or_bail 'pg_ctl', 'stop', '-s', '-D', "$tempdir/pgdata", '-w';
- system_or_bail 'pg_ctl', 'start', '-s', '-D', "$tempdir/pgdata", '-w',
- '-l',
- "$tempdir/logfile";
+ system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/pgdata";
+ system_or_bail 'pg_ctl', 'start', '-D', "$tempdir/pgdata", '-w';
}
On Thu, Jul 9, 2015 at 12:49 AM, Heikki Linnakangas wrote:
Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes
a copy of them (when? at program startup I guess..). That would be much
more
convenient than decorating every run call with ">> logfile".Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the
tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But it's
Windows, so who knows..
And actually your patch works even on Windows. Tests are running and
log can be captured in the same shape as Linux and OSX!
I came up with the attached, which does that. It also plays some tricks with
perl "tie", to copy the "ok - ..." lines that go to the console, to the log.I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?
I simply downloaded them from CPAN and put them in PERL5LIB. And it
worked. For Windows, you will also need some adjustments to make the
tests able to run (see the other thread related to support TAP in MSVC
/messages/by-id/CAB7nPqTQwphkDfZP07w7yBnbFNDhW_JBAMyCFAkarE2VWg8irQ@mail.gmail.com)
like using SSPI for connection, adjusting listen_addresses. The patch
attached, which is a merge of your patch and my MSVC stuff, is able to
do that. This is just intended for testing, so feel free to use it if
you want to check by yourself how logs are captured. I'll repost a new
version of it on the other thread depending on the outcome here.
- system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
+ system_or_bail('pg_basebackup', '-D', $test_standby_datadir,
+ '-p', $port_master, '-x';
A parenthesis is missing here.
- my $result = run(
- [ 'pg_rewind',
- "--source-server",
- "port=$port_standby dbname=postgres",
- "--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
- ok($result, 'pg_rewind remote');
+ command_ok(['pg_rewind',
+ "--source-server",
+ "port=$port_standby dbname=postgres",
+ "--target-pgdata=$test_master_datadir"],
+ 'pg_rewind remote');
As long as we are on it, I think that we should add --debug here to
make the logs more useful.
Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.
Regards,
--
Michael
Attachments:
20150709_tap_msvc_logs.patchtext/x-diff; charset=US-ASCII; name=20150709_tap_msvc_logs.patchDownload
diff --git a/doc/src/sgml/install-windows.sgml b/doc/src/sgml/install-windows.sgml
index d154b44..2047790 100644
--- a/doc/src/sgml/install-windows.sgml
+++ b/doc/src/sgml/install-windows.sgml
@@ -439,6 +439,7 @@ $ENV{CONFIG}="Debug";
<userinput>vcregress modulescheck</userinput>
<userinput>vcregress ecpgcheck</userinput>
<userinput>vcregress isolationcheck</userinput>
+<userinput>vcregress tapcheck</userinput>
<userinput>vcregress upgradecheck</userinput>
</screen>
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index 8eab178..29bc874 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -337,7 +337,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
-cd $(srcdir) && TESTDIR='$(CURDIR)' $(with_temp_install) PGPORT='6$(DEF_PGPORT)' top_builddir='$(CURDIR)/$(top_builddir)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
+cd $(srcdir) && TESTDIR='$(CURDIR)' TESTREGRESS='$(top_builddir)/src/test/regress/pg_regress' $(with_temp_install) PGPORT='6$(DEF_PGPORT)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
endef
else
diff --git a/src/bin/initdb/t/001_initdb.pl b/src/bin/initdb/t/001_initdb.pl
index 299dcf5..095cbf3 100644
--- a/src/bin/initdb/t/001_initdb.pl
+++ b/src/bin/initdb/t/001_initdb.pl
@@ -4,6 +4,7 @@
use strict;
use warnings;
+use Config;
use TestLib;
use Test::More tests => 14;
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index c8c9250..59e8cb4 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -1,8 +1,9 @@
use strict;
use warnings;
use Cwd;
+use Config;
use TestLib;
-use Test::More tests => 35;
+use Test::More tests => ($Config{osname} eq "MSWin32") ? 25 : 35;
program_help_ok('pg_basebackup');
program_version_ok('pg_basebackup');
@@ -25,12 +26,22 @@ if (open BADCHARS, ">>$tempdir/pgdata/FOO\xe0\xe0\xe0BAR")
close BADCHARS;
}
+# Use SSPI on Windows, node has been initialized already accordingly
+# by pg_regress --config-auth.
open HBA, ">>$tempdir/pgdata/pg_hba.conf";
-print HBA "local replication all trust\n";
-print HBA "host replication all 127.0.0.1/32 trust\n";
-print HBA "host replication all ::1/128 trust\n";
+if ($Config{osname} ne "MSWin32")
+{
+ print HBA "local replication all trust\n";
+ print HBA "host replication all 127.0.0.1/32 trust\n";
+ print HBA "host replication all ::1/128 trust\n";
+}
+else
+{
+ print HBA "host replication all 127.0.0.1/32 sspi include_realm=1 map=regress\n";
+ print HBA "host replication all ::1/128 sspi include_realm=1 map=regress\n";
+}
close HBA;
-system_or_bail 'pg_ctl', '-s', '-D', "$tempdir/pgdata", 'reload';
+system_or_bail 'pg_ctl', '-D', "$tempdir/pgdata", 'reload';
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
@@ -64,6 +75,33 @@ command_fails([ 'pg_basebackup', '-D', "$tempdir/tarbackup_l1", '-Ft' ],
'pg_basebackup tar with long name fails');
unlink "$tempdir/pgdata/$superlongname";
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T=/foo" ],
+ '-T with empty old directory fails');
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T/foo=" ],
+ '-T with empty new directory fails');
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp',
+ "-T/foo=/bar=/baz" ],
+ '-T with multiple = fails');
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-Tfoo=/bar" ],
+ '-T with old directory not absolute fails');
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T/foo=bar" ],
+ '-T with new directory not absolute fails');
+command_fails(
+ [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-Tfoo" ],
+ '-T with invalid format fails');
+
+# Windows does not support symlink, which is what the rest of the tests
+# need, so simply leave.
+if ($Config{osname} eq "MSWin32")
+{
+ exit 0;
+}
+
# Create a temporary directory in the system location and symlink it
# to our physical temp location. That way we can use shorter names
# for the tablespace directories, which hopefully won't run afoul of
@@ -109,29 +147,8 @@ command_ok(
"-T$shorter_tempdir/tbl\\=spc2=$tempdir/tbackup/tbl\\=spc2" ],
'mapping tablespace with = sign in path');
ok(-d "$tempdir/tbackup/tbl=spc2", 'tablespace with = sign was relocated');
-
psql 'postgres', "DROP TABLESPACE tblspc2;";
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T=/foo" ],
- '-T with empty old directory fails');
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T/foo=" ],
- '-T with empty new directory fails');
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp',
- "-T/foo=/bar=/baz" ],
- '-T with multiple = fails');
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-Tfoo=/bar" ],
- '-T with old directory not absolute fails');
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-T/foo=bar" ],
- '-T with new directory not absolute fails');
-command_fails(
- [ 'pg_basebackup', '-D', "$tempdir/backup_foo", '-Fp', "-Tfoo" ],
- '-T with invalid format fails');
-
mkdir "$tempdir/$superlongname";
psql 'postgres',
"CREATE TABLESPACE tblspc3 LOCATION '$tempdir/$superlongname';";
diff --git a/src/bin/pg_controldata/t/001_pg_controldata.pl b/src/bin/pg_controldata/t/001_pg_controldata.pl
index a4180e7..0ef1de7 100644
--- a/src/bin/pg_controldata/t/001_pg_controldata.pl
+++ b/src/bin/pg_controldata/t/001_pg_controldata.pl
@@ -1,5 +1,6 @@
use strict;
use warnings;
+use Config;
use TestLib;
use Test::More tests => 13;
@@ -11,6 +12,7 @@ program_options_handling_ok('pg_controldata');
command_fails(['pg_controldata'], 'pg_controldata without arguments fails');
command_fails([ 'pg_controldata', 'nonexistent' ],
'pg_controldata with nonexistent directory fails');
-system_or_bail "initdb -D '$tempdir'/data -A trust >/dev/null";
+
+system_or_bail "initdb -D $tempdir/data -A trust";
command_like([ 'pg_controldata', "$tempdir/data" ],
qr/checkpoint/, 'pg_controldata produces output');
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 6c9ec5c..bebcd6e 100644
--- a/src/bin/pg_ctl/t/001_start_stop.pl
+++ b/src/bin/pg_ctl/t/001_start_stop.pl
@@ -1,5 +1,6 @@
use strict;
use warnings;
+use Config;
use TestLib;
use Test::More tests => 17;
@@ -15,12 +16,19 @@ command_exit_is([ 'pg_ctl', 'start', '-D', "$tempdir/nonexistent" ],
command_ok([ 'pg_ctl', 'initdb', '-D', "$tempdir/data" ], 'pg_ctl initdb');
command_ok(
- [ "$ENV{top_builddir}/src/test/regress/pg_regress", '--config-auth',
+ [ $ENV{TESTREGRESS}, '--config-auth',
"$tempdir/data" ],
'configure authentication');
open CONF, ">>$tempdir/data/postgresql.conf";
-print CONF "listen_addresses = ''\n";
-print CONF "unix_socket_directories = '$tempdir_short'\n";
+if ($Config{osname} eq "MSWin32")
+{
+ print CONF "listen_addresses = '127.0.0.1'\n";
+}
+else
+{
+ print CONF "listen_addresses = ''\n";
+ print CONF "unix_socket_directories = '$tempdir_short'\n";
+}
close CONF;
command_ok([ 'pg_ctl', 'start', '-D', "$tempdir/data", '-w' ],
'pg_ctl start -w');
@@ -36,4 +44,4 @@ command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
'pg_ctl restart with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/bin/pg_ctl/t/002_status.pl b/src/bin/pg_ctl/t/002_status.pl
index 0558854..f68cd62 100644
--- a/src/bin/pg_ctl/t/002_status.pl
+++ b/src/bin/pg_ctl/t/002_status.pl
@@ -1,5 +1,6 @@
use strict;
use warnings;
+use Config;
use TestLib;
use Test::More tests => 3;
@@ -11,16 +12,23 @@ command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/nonexistent" ],
standard_initdb "$tempdir/data";
open CONF, ">>$tempdir/data/postgresql.conf";
-print CONF "listen_addresses = ''\n";
-print CONF "unix_socket_directories = '$tempdir_short'\n";
+if ($Config{osname} eq "MSWin32")
+{
+ print CONF "listen_addresses = '127.0.0.1'\n";
+}
+else
+{
+ print CONF "listen_addresses = ''\n";
+ print CONF "unix_socket_directories = '$tempdir_short'\n";
+}
close CONF;
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
3, 'pg_ctl status with server not running');
-system_or_bail 'pg_ctl', '-s', '-l', "$tempdir/logfile", '-D',
+system_or_bail 'pg_ctl', '-l', "$tempdir/logfile", '-D',
"$tempdir/data", '-w', 'start';
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
0, 'pg_ctl status with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/bin/pg_rewind/.gitignore b/src/bin/pg_rewind/.gitignore
index 9ade7ef..79ddca3 100644
--- a/src/bin/pg_rewind/.gitignore
+++ b/src/bin/pg_rewind/.gitignore
@@ -4,4 +4,3 @@
# Generated by test suite
/tmp_check/
-/regress_log/
diff --git a/src/bin/pg_rewind/Makefile b/src/bin/pg_rewind/Makefile
index 7d60715..92b5d20 100644
--- a/src/bin/pg_rewind/Makefile
+++ b/src/bin/pg_rewind/Makefile
@@ -45,7 +45,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_rewind$(X) $(OBJS) xlogreader.c
- rm -rf tmp_check regress_log
+ rm -rf tmp_check
check:
$(prove_check)
diff --git a/src/bin/pg_rewind/RewindTest.pm b/src/bin/pg_rewind/RewindTest.pm
index 5219ec9..3c9e34c 100644
--- a/src/bin/pg_rewind/RewindTest.pm
+++ b/src/bin/pg_rewind/RewindTest.pm
@@ -38,6 +38,7 @@ use warnings;
use TestLib;
use Test::More;
+use Config;
use File::Copy;
use File::Path qw(remove_tree);
use IPC::Run qw(run start);
@@ -91,14 +92,16 @@ sub master_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_master -c \"$cmd\"");
+ system_or_bail 'psql', '-q', '--no-psqlrc', '-d', $connstr_master,
+ '-c', "$cmd";
}
sub standby_psql
{
my $cmd = shift;
- system_or_bail("psql -q --no-psqlrc -d $connstr_standby -c \"$cmd\"");
+ system_or_bail 'psql', '-q', '--no-psqlrc', '-d', $connstr_standby,
+ '-c', "$cmd";
}
# Run a query against the master, and check that the output matches what's
@@ -177,7 +180,6 @@ sub init_rewind_test
my $test_mode = shift;
$log_path = "regress_log/pg_rewind_log_${testname}_${test_mode}";
-
remove_tree $log_path;
}
@@ -204,18 +206,30 @@ max_connections = 10
));
# Accept replication connections on master
- append_to_file(
- "$test_master_datadir/pg_hba.conf", qq(
+ if ($Config{osname} eq "MSWin32")
+ {
+ append_to_file("$test_master_datadir/pg_hba.conf", qq(
+host replication all 127.0.0.1/32 sspi include_realm=1 map=regress
+host replication all ::1/128 sspi include_realm=1 map=regress
+));
+ }
+ else
+ {
+ append_to_file("$test_master_datadir/pg_hba.conf", qq(
local replication all trust
));
+ }
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
- );
+ my $ctl_options = ($Config{osname} eq "MSWin32") ?
+ "--listen-addresses=127.0.0.1 -p $port_master" :
+ "-k $tempdir_short --listen-addresses='' -p $port_master";
+
+ system_or_bail("pg_ctl -w -D $test_master_datadir -o \"$ctl_options\" start");
#### Now run the test-specific parts to initialize the master before setting
# up standby
- $ENV{PGHOST} = $tempdir_short;
+ $ENV{PGHOST} = ($Config{osname} eq "MSWin32") ?
+ "127.0.0.1" : $tempdir_short;
}
sub create_standby
@@ -225,19 +239,19 @@ sub create_standby
remove_tree $test_standby_datadir;
# Base backup is taken with xlog files included
- system_or_bail(
-"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1");
- append_to_file(
- "$test_standby_datadir/recovery.conf", qq(
+ system_or_bail("pg_basebackup -D $test_standby_datadir -p $port_master -x");
+ append_to_file("$test_standby_datadir/recovery.conf", qq(
primary_conninfo='$connstr_master application_name=rewind_standby'
standby_mode=on
recovery_target_timeline='latest'
));
+ my $ctl_options = ($Config{osname} eq "MSWin32") ?
+ "--listen-addresses=127.0.0.1 -p $port_standby" :
+ "-k $tempdir_short --listen-addresses='' -p $port_standby";
+
# Start standby
- system_or_bail(
-"pg_ctl -w -D $test_standby_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_standby\" start >>$log_path 2>&1"
- );
+ system_or_bail("pg_ctl -w -D $test_standby_datadir -o \"$ctl_options\" start");
# Wait until the standby has caught up with the primary, by polling
# pg_stat_replication.
@@ -255,8 +269,7 @@ sub promote_standby
# Now promote slave and insert some new data on master, this will put
# the master out-of-sync with the standby. Wait until the standby is
# out of recovery mode, and is ready to accept read-write connections.
- system_or_bail(
- "pg_ctl -w -D $test_standby_datadir promote >>$log_path 2>&1");
+ system_or_bail('pg_ctl', '-w', '-D', $test_standby_datadir, 'promote');
poll_query_until("SELECT NOT pg_is_in_recovery()", $connstr_standby)
or die "Timed out while waiting for promotion of standby";
@@ -274,8 +287,7 @@ sub run_pg_rewind
my $test_mode = shift;
# Stop the master and be ready to perform the rewind
- system_or_bail(
- "pg_ctl -w -D $test_master_datadir stop -m fast >>$log_path 2>&1");
+ system_or_bail("pg_ctl -w -D $test_master_datadir -m fast stop");
# At this point, the rewind processing is ready to run.
# We now have a very simple scenario with a few diverged WAL record.
@@ -291,39 +303,31 @@ sub run_pg_rewind
# Now run pg_rewind
if ($test_mode eq "local")
{
-
# Do rewind using a local pgdata as source
# Stop the master and be ready to perform the rewind
system_or_bail(
- "pg_ctl -w -D $test_standby_datadir stop -m fast >>$log_path 2>&1"
+ "pg_ctl -w -D $test_standby_datadir -m fast stop"
);
- my $result = run(
+ command_ok(
[ 'pg_rewind',
"--debug",
"--source-pgdata=$test_standby_datadir",
"--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
- ok($result, 'pg_rewind local');
+ 'pg_rewind local');
}
elsif ($test_mode eq "remote")
{
-
# Do rewind using a remote connection as source
- my $result = run(
+ command_ok(
[ 'pg_rewind',
+ "--debug",
"--source-server",
"port=$port_standby dbname=postgres",
"--target-pgdata=$test_master_datadir" ],
- '>>',
- $log_path,
- '2>&1');
- ok($result, 'pg_rewind remote');
+ 'pg_rewind remote');
}
else
{
-
# Cannot come here normally
die("Incorrect test mode specified");
}
@@ -341,10 +345,12 @@ standby_mode=on
recovery_target_timeline='latest'
));
+ my $ctl_options = ($Config{osname} eq "MSWin32") ?
+ "--listen-addresses=127.0.0.1 -p $port_master" :
+ "-k $tempdir_short --listen-addresses='' -p $port_master";
+
# Restart the master to check that rewind went correctly
- system_or_bail(
-"pg_ctl -w -D $test_master_datadir -o \"-k $tempdir_short --listen-addresses='' -p $port_master\" start >>$log_path 2>&1"
- );
+ system_or_bail("pg_ctl -w -D $test_master_datadir -o \"$ctl_options\" start");
#### Now run the test-specific parts to check the result
}
@@ -354,13 +360,13 @@ sub clean_rewind_test
{
if ($test_master_datadir)
{
- system
- "pg_ctl -D $test_master_datadir -s -m immediate stop 2> /dev/null";
+ system_log('pg_ctl', '-D', $test_master_datadir, '-w', '-m',
+ 'immediate', 'stop');
}
if ($test_standby_datadir)
{
- system
- "pg_ctl -D $test_standby_datadir -s -m immediate stop 2> /dev/null";
+ system_log('pg_ctl', '-D', $test_standby_datadir, '-w', '-m',
+ 'immediate', 'stop');
}
}
diff --git a/src/bin/pg_rewind/t/001_basic.pl b/src/bin/pg_rewind/t/001_basic.pl
index f60368b..be7d887 100644
--- a/src/bin/pg_rewind/t/001_basic.pl
+++ b/src/bin/pg_rewind/t/001_basic.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('basic', $test_mode);
RewindTest::setup_cluster();
# Create a test table and insert a row in master.
diff --git a/src/bin/pg_rewind/t/002_databases.pl b/src/bin/pg_rewind/t/002_databases.pl
index 7564fa9..b0b007a 100644
--- a/src/bin/pg_rewind/t/002_databases.pl
+++ b/src/bin/pg_rewind/t/002_databases.pl
@@ -9,7 +9,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('databases', $test_mode);
RewindTest::setup_cluster();
# Create a database in master.
diff --git a/src/bin/pg_rewind/t/003_extrafiles.pl b/src/bin/pg_rewind/t/003_extrafiles.pl
index 9a95268..0cd0ac4 100644
--- a/src/bin/pg_rewind/t/003_extrafiles.pl
+++ b/src/bin/pg_rewind/t/003_extrafiles.pl
@@ -14,7 +14,6 @@ sub run_test
{
my $test_mode = shift;
- RewindTest::init_rewind_test('extrafiles', $test_mode);
RewindTest::setup_cluster();
my $test_master_datadir = $RewindTest::test_master_datadir;
diff --git a/src/bin/scripts/t/020_createdb.pl b/src/bin/scripts/t/020_createdb.pl
index a44283c..7e769e4 100644
--- a/src/bin/scripts/t/020_createdb.pl
+++ b/src/bin/scripts/t/020_createdb.pl
@@ -1,5 +1,6 @@
use strict;
use warnings;
+use Config;
use TestLib;
use Test::More tests => 13;
@@ -14,6 +15,8 @@ issues_sql_like(
[ 'createdb', 'foobar1' ],
qr/statement: CREATE DATABASE foobar1/,
'SQL CREATE DATABASE run');
+
+my $encoding = ($Config{osname} eq "MSWin32") ? "win1252" : "LATIN1" ;
issues_sql_like(
[ 'createdb', '-l', 'C', '-E', 'LATIN1', '-T', 'template0', 'foobar2' ],
qr/statement: CREATE DATABASE foobar2 ENCODING 'LATIN1'/,
diff --git a/src/test/perl/SimpleTee.pm b/src/test/perl/SimpleTee.pm
new file mode 100644
index 0000000..8d31a40
--- /dev/null
+++ b/src/test/perl/SimpleTee.pm
@@ -0,0 +1,27 @@
+# A simple 'tee' implementation, using perl tie.
+#
+# Whenever you print to the handle, it gets forwarded to a list of
+# handles. The list of output filehandles is passed to the constructor.
+#
+# This is similar to IO::Tee, but only used for output. Only the PRINT
+# method is currently implemented; that's all we need. We don't want to
+# depend on IO::Tee just for this.
+
+package SimpleTee;
+use strict;
+
+sub TIEHANDLE {
+ my $self = shift;
+ bless \@_, $self;
+}
+
+sub PRINT {
+ my $self = shift;
+ my $ok = 1;
+ for my $fh (@$self) {
+ print $fh @_ or $ok = 0;
+ }
+ return $ok;
+}
+
+1;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index ef42366..35ea94f 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -3,6 +3,7 @@ package TestLib;
use strict;
use warnings;
+use Config;
use Exporter 'import';
our @EXPORT = qw(
tempdir
@@ -12,6 +13,8 @@ our @EXPORT = qw(
restart_test_server
psql
system_or_bail
+ system_log
+ run_log
command_ok
command_fails
@@ -24,11 +27,47 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
+
+use SimpleTee;
+
use Test::More;
+# Open log file. For each test, the log file name uses the name of the
+# file launching this module, without its file prefix for readability.
+my $log_path = 'tmp_check/log';
+mkdir 'tmp_check';
+mkdir $log_path;
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = "$log_path/regress_log_$test_logfile";
+open TESTLOG, '>', $test_logfile or die "Cannot open STDOUT to logfile: $!";
+
+# Hijack STDOUT and STDERR to the log file
+open(ORIG_STDOUT, ">&STDOUT");
+open(ORIG_STDERR, ">&STDERR");
+open(STDOUT, ">&TESTLOG");
+open(STDERR, ">&TESTLOG");
+
+# The test output (ok ...) needs to be printed to the original STDOUT
+# so that the 'prove' program can parse it, and also display it to the
+# user in real time. But also copy it to the log file, to provide more
+# context in the log file.
+my $builder = Test::More->builder;
+my $fh = $builder->output;
+tie *$fh, "SimpleTee", *ORIG_STDOUT, *TESTLOG;
+$fh = $builder->failure_output;
+tie *$fh, "SimpleTee", *ORIG_STDERR, *TESTLOG;
+
+# Enable auto-flushing for all the file handles. Stderr and stdout are
+# redirected to the same file, and buffering causes the lines to appear
+# in the log in confusing order.
+autoflush STDOUT 1;
+autoflush STDERR 1;
+autoflush TESTLOG 1;
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -52,7 +91,6 @@ if (!$ENV{PGPORT})
$ENV{PGPORT} = int($ENV{PGPORT}) % 65536;
-
#
# Helper functions
#
@@ -77,9 +115,9 @@ sub tempdir_short
sub standard_initdb
{
my $pgdata = shift;
- system_or_bail("initdb -D '$pgdata' -A trust -N >/dev/null");
- system_or_bail("$ENV{top_builddir}/src/test/regress/pg_regress",
- '--config-auth', $pgdata);
+ system_or_bail('initdb', '-D', "$pgdata", '-A' , 'trust', '-N');
+ system_or_bail($ENV{TESTREGRESS},
+ '--config-auth', $pgdata);
}
my ($test_server_datadir, $test_server_logfile);
@@ -91,47 +129,68 @@ sub start_test_server
my $tempdir_short = tempdir_short;
+ my $listen_addresses = ($Config{osname} eq "MSWin32") ? "127.0.0.1" : "''";
+
+ print("### Starting test server in $tempdir\n");
standard_initdb "$tempdir/pgdata";
- $ret = system 'pg_ctl', '-D', "$tempdir/pgdata", '-s', '-w', '-l',
+ $ret = system_log('pg_ctl', '-D', "$tempdir/pgdata", '-w', '-l',
"$tempdir/logfile", '-o',
-"--fsync=off -k $tempdir_short --listen-addresses='' --log-statement=all",
- 'start';
+ "--fsync=off --listen-addresses=$listen_addresses --log-statement=all",
+ 'start');
if ($ret != 0)
{
+ print "# pg_ctl failed; logfile:\n";
system('cat', "$tempdir/logfile");
BAIL_OUT("pg_ctl failed");
}
- $ENV{PGHOST} = $tempdir_short;
+ $ENV{PGHOST} = ($Config{osname} eq "MSWin32") ? "127.0.0.1" : $tempdir_short;
$test_server_datadir = "$tempdir/pgdata";
$test_server_logfile = "$tempdir/logfile";
}
sub restart_test_server
{
- system 'pg_ctl', '-s', '-D', $test_server_datadir, '-w', '-l',
- $test_server_logfile, 'restart';
+ print("### Restarting test server\n");
+ system_log('pg_ctl', '-D', $test_server_datadir, '-w', '-l',
+ $test_server_logfile, 'restart');
}
END
{
if ($test_server_datadir)
{
- system 'pg_ctl', '-D', $test_server_datadir, '-s', '-w', '-m',
- 'immediate', 'stop';
+ system_log('pg_ctl', '-D', $test_server_datadir, '-m',
+ 'immediate', 'stop');
}
}
sub psql
{
my ($dbname, $sql) = @_;
+ print("# Running SQL command: $sql\n");
run [ 'psql', '-X', '-q', '-d', $dbname, '-f', '-' ], '<', \$sql or die;
}
sub system_or_bail
{
- system(@_) == 0 or BAIL_OUT("system @_ failed: $?");
+ if (system_log(@_) != 0)
+ {
+ BAIL_OUT("system $_[0] failed: $?");
+ }
+}
+
+sub system_log
+{
+ print("# Running: " . join(" ", @_) ."\n");
+ return system(@_);
+}
+
+sub run_log
+{
+ print("# Running: " . join(" ", @{$_[0]}) ."\n");
+ return run (@_);
}
@@ -143,32 +202,33 @@ sub system_or_bail
sub command_ok
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok($result, $test_name);
}
sub command_fails
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok(!$result, $test_name);
}
sub command_exit_is
{
my ($cmd, $expected, $test_name) = @_;
- my $h = start $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ print("# Running: " . join(" ", @{$cmd}) ."\n");
+ my $h = start $cmd;
$h->finish();
- is($h->result(0), $expected, $test_name);
+ my $result = ($Config{osname} eq "MSWin32") ?
+ ($h->full_results)[0] : $h->result(0);
+ is($result, $expected, $test_name);
}
sub program_help_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --help\n");
my $result = run [ $cmd, '--help' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --help exit code 0");
isnt($stdout, '', "$cmd --help goes to stdout");
@@ -179,6 +239,7 @@ sub program_version_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --version\n");
my $result = run [ $cmd, '--version' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --version exit code 0");
isnt($stdout, '', "$cmd --version goes to stdout");
@@ -189,6 +250,7 @@ sub program_options_handling_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --not-a-valid-option\n");
my $result = run [ $cmd, '--not-a-valid-option' ], '>', \$stdout, '2>',
\$stderr;
ok(!$result, "$cmd with invalid option nonzero exit code");
@@ -199,6 +261,7 @@ sub command_like
{
my ($cmd, $expected_stdout, $test_name) = @_;
my ($stdout, $stderr);
+ print("# Running: " . join(" ", @{$cmd}) . "\n");
my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
ok($result, "@$cmd exit code 0");
is($stderr, '', "@$cmd no stderr");
@@ -208,9 +271,8 @@ sub command_like
sub issues_sql_like
{
my ($cmd, $expected_sql, $test_name) = @_;
- my ($stdout, $stderr);
truncate $test_server_logfile, 0;
- my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
+ my $result = run_log($cmd);
ok($result, "@$cmd exit code 0");
my $log = `cat '$test_server_logfile'`;
like($log, $expected_sql, "$test_name: SQL found in server log");
diff --git a/src/test/ssl/ServerSetup.pm b/src/test/ssl/ServerSetup.pm
index bbff99a..8c1b517 100644
--- a/src/test/ssl/ServerSetup.pm
+++ b/src/test/ssl/ServerSetup.pm
@@ -125,8 +125,6 @@ sub switch_server_cert
# restart_test_server() because that overrides listen_addresses to only all
# Unix domain socket connections.
- system_or_bail 'pg_ctl', 'stop', '-s', '-D', "$tempdir/pgdata", '-w';
- system_or_bail 'pg_ctl', 'start', '-s', '-D', "$tempdir/pgdata", '-w',
- '-l',
- "$tempdir/logfile";
+ system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/pgdata";
+ system_or_bail 'pg_ctl', 'start', '-D', "$tempdir/pgdata", '-w';
}
diff --git a/src/tools/msvc/Solution.pm b/src/tools/msvc/Solution.pm
index 6b16e69..8abc81d 100644
--- a/src/tools/msvc/Solution.pm
+++ b/src/tools/msvc/Solution.pm
@@ -619,6 +619,7 @@ sub GetFakeConfigure
$cfg .= ' --enable-integer-datetimes'
if ($self->{options}->{integer_datetimes});
$cfg .= ' --enable-nls' if ($self->{options}->{nls});
+ $cfg .= ' --enable-tap-tests' if ($self->{options}->{taptest});
$cfg .= ' --with-ldap' if ($self->{options}->{ldap});
$cfg .= ' --without-zlib' unless ($self->{options}->{zlib});
$cfg .= ' --with-extra-version' if ($self->{options}->{extraver});
diff --git a/src/tools/msvc/config_default.pl b/src/tools/msvc/config_default.pl
index b9f2ff4..5b8c8cd 100644
--- a/src/tools/msvc/config_default.pl
+++ b/src/tools/msvc/config_default.pl
@@ -14,6 +14,7 @@ our $config = {
# wal_blocksize => 8, # --with-wal-blocksize, 8kB by default
# wal_segsize => 16, # --with-wal-segsize, 16MB by default
ldap => 1, # --with-ldap
+ taptest => undef, # --enable-tap-tests
extraver => undef, # --with-extra-version=<string>
nls => undef, # --enable-nls=<path>
tcl => undef, # --with-tls=<path>
diff --git a/src/tools/msvc/vcregress.pl b/src/tools/msvc/vcregress.pl
index 6196383..4dcc155 100644
--- a/src/tools/msvc/vcregress.pl
+++ b/src/tools/msvc/vcregress.pl
@@ -7,7 +7,9 @@ use strict;
our $config;
use Cwd;
+use File::Basename;
use File::Copy;
+use File::Find ();
use Install qw(Install);
@@ -32,7 +34,7 @@ if (-e "src/tools/msvc/buildenv.pl")
my $what = shift || "";
if ($what =~
-/^(check|installcheck|plcheck|contribcheck|modulescheck|ecpgcheck|isolationcheck|upgradecheck)$/i
+/^(check|installcheck|plcheck|contribcheck|modulescheck|ecpgcheck|isolationcheck|upgradecheck|tapcheck)$/i
)
{
$what = uc $what;
@@ -79,6 +81,7 @@ my %command = (
CONTRIBCHECK => \&contribcheck,
MODULESCHECK => \&modulescheck,
ISOLATIONCHECK => \&isolationcheck,
+ TAPCHECK => \&tapcheck,
UPGRADECHECK => \&upgradecheck,);
my $proc = $command{$what};
@@ -172,6 +175,49 @@ sub isolationcheck
exit $status if $status;
}
+sub tapcheck
+{
+ if (!defined($config->{taptest}))
+ {
+ print "TAP tests not enabled\n";
+ exit 0;
+ }
+
+ InstallTemp();
+
+ my @args = ( "prove", "--verbose", "t/*.pl");
+
+ $ENV{PATH} = "$tmp_installdir/bin;$ENV{PATH}";
+ $ENV{PERL5LIB} = "$topdir/src/test/perl;$ENV{PERL5LIB}";
+ $ENV{TESTREGRESS} = "$topdir/$Config/pg_regress/pg_regress";
+
+ # Find out all the existing TAP tests by simply looking for t/
+ # in the tree.
+ my $tap_dirs = [];
+ my @top_dir = ($topdir);
+ File::Find::find(
+ { wanted => sub {
+ /^t\z/s
+ && push(@$tap_dirs, $File::Find::name);
+ }
+ },
+ @top_dir);
+
+ # Process each test
+ foreach my $test_path (@$tap_dirs)
+ {
+ next if ($test_path =~ /\/ssl\// && !defined($config->{openssl}));
+
+ my $dir = dirname($test_path);
+ chdir $dir;
+ # Reset those values, they may have been changed by another test.
+ $ENV{TESTDIR} = "$dir";
+ system(@args);
+ my $status = $? >> 8;
+ exit $status if $status;
+ }
+}
+
sub plcheck
{
chdir $startdir;
On 07/09/2015 04:50 AM, Michael Paquier wrote:
On Thu, Jul 9, 2015 at 12:49 AM, Heikki Linnakangas wrote:
Looking at the manual page of Test::More, it looks like you could change
where the perl script's STDOUT and STDERR point to, because Test::More
takes
a copy of them (when? at program startup I guess..). That would be much
more
convenient than decorating every run call with ">> logfile".Hm. There are two types of logs we want to capture:
1) stdout and stderr from the subprocesses kicked by IPC::Run::run
2) Status messages written in the log file by the process running the
tests.
Perhaps we could redirect the output of stdout and stderr but I think
that this is going to need an fd open from the beginning of the test
until the end, with something like that:
open my $test_logfile_fd, '>>', $test_logfile;
*STDOUT = $test_logfile_fd;
*STDERR = $test_logfile_fd;While that would work on OSX and Linux for sure, I suspect that this
will not on Windows where two concurrent processes cannot write to the
same file.Hmm, as long as you make sure all the processes use the same filehandle,
rather than open the log file separately, I think it should work. But it's
Windows, so who knows..And actually your patch works even on Windows. Tests are running and
log can be captured in the same shape as Linux and OSX!
Great!
I came up with the attached, which does that. It also plays some tricks with
perl "tie", to copy the "ok - ..." lines that go to the console, to the log.I tried to test that on my Windows system, but I don't have IPC::Run
installed. How did you get that on Windows? Can you test this?I simply downloaded them from CPAN and put them in PERL5LIB. And it
worked. For Windows, you will also need some adjustments to make the
tests able to run (see the other thread related to support TAP in MSVC
/messages/by-id/CAB7nPqTQwphkDfZP07w7yBnbFNDhW_JBAMyCFAkarE2VWg8irQ@mail.gmail.com)
like using SSPI for connection, adjusting listen_addresses. The patch
attached, which is a merge of your patch and my MSVC stuff, is able to
do that. This is just intended for testing, so feel free to use it if
you want to check by yourself how logs are captured. I'll repost a new
version of it on the other thread depending on the outcome here.- system_or_bail( -"pg_basebackup -D $test_standby_datadir -p $port_master -x >>$log_path 2>&1"); + system_or_bail('pg_basebackup', '-D', $test_standby_datadir, + '-p', $port_master, '-x'; A parenthesis is missing here.- my $result = run( - [ 'pg_rewind', - "--source-server", - "port=$port_standby dbname=postgres", - "--target-pgdata=$test_master_datadir" ], - '>>', - $log_path, - '2>&1'); - ok($result, 'pg_rewind remote'); + command_ok(['pg_rewind', + "--source-server", + "port=$port_standby dbname=postgres", + "--target-pgdata=$test_master_datadir"], + 'pg_rewind remote'); As long as we are on it, I think that we should add --debug here to make the logs more useful.Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.
Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Jul 9, 2015 at 7:29 PM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:
Thanks, fixed the parenthesis and committed.
Thanks. I imagine that this is going to need some tuning with the
buildfarm before this becomes really useful. I will re-enable the TAP
tests of hamster once that's the case.
@Andrew: do you need a patch for the buildfarm client?
The missing --debug is a separate issue.
I won't argue against that, but is it worth creating a new thread just
for this one-liner? The local mode of pg_rewind uses it already.
--
Michael
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 07/09/2015 04:09 PM, Michael Paquier wrote:
On Thu, Jul 9, 2015 at 7:29 PM, Heikki Linnakangas <hlinnaka@iki.fi> wrote:
The missing --debug is a separate issue.
I won't argue against that, but is it worth creating a new thread just
for this one-liner? The local mode of pg_rewind uses it already.
Pushed, thanks.
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Heikki Linnakangas <hlinnaka@iki.fi> writes:
Pushed, thanks.
Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Jul 9, 2015 at 10:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Heikki Linnakangas <hlinnaka@iki.fi> writes:
Pushed, thanks.
Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.
1ea0620 can be directly cherry-picked on REL9_5_STABLE. For
REL9_4_STABLE the attached looks to work fine.
buildfarm will need to be patched btw... Here is the result of a run
including the log improvements:
http://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=dangomushi&dt=2015-07-09%2019%3A53%3A02&stg=bin-check
--
Michael
Attachments:
20150710_improve_log_tap_94.patchtext/x-diff; charset=US-ASCII; name=20150710_improve_log_tap_94.patchDownload
From dc557fdbae810f22d7fccd9dbc4da1f5a9a0b029 Mon Sep 17 00:00:00 2001
From: Heikki Linnakangas <heikki.linnakangas@iki.fi>
Date: Thu, 9 Jul 2015 13:19:10 +0300
Subject: [PATCH] Improve logging of TAP tests.
Create a log file for each test run. Stdout and stderr of the test script,
as well as any subprocesses run as part of the test, are redirected to
the log file. This makes it a lot easier to debug test failures. Also print
the test output (ok 12 - ... messages) to the log file, and the command
line of any external programs executed with the system_or_bail and run_log
functions. This makes it a lot easier to debug failing tests.
Modify some of the pg_ctl and other command invocations to not use 'silent'
or 'quiet' options, and don't redirect output to /dev/null, so that you get
all the information in the log instead.
In the passing, construct some command lines in a way that works if $tempdir
contains quote-characters. I haven't systematically gone through all of
them or tested that, so I don't know if this is enough to make that work.
pg_rewind tests had a custom mechanism for creating a similar log file. Use
the new generic facility instead.
Michael Paquier and me.
---
src/Makefile.global.in | 1 +
src/bin/pg_basebackup/t/010_pg_basebackup.pl | 2 +-
src/bin/pg_controldata/t/001_pg_controldata.pl | 2 +-
src/bin/pg_ctl/t/001_start_stop.pl | 2 +-
src/bin/pg_ctl/t/002_status.pl | 4 +-
src/test/perl/SimpleTee.pm | 27 ++++++++
src/test/perl/TestLib.pm | 96 +++++++++++++++++++++-----
7 files changed, 110 insertions(+), 24 deletions(-)
create mode 100644 src/test/perl/SimpleTee.pm
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index aec6187..157fc21 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -322,6 +322,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
+rm -rf $(srcdir)/tmp_check/log
$(MKDIR_P) tmp_check/log
$(MAKE) -C $(top_builddir) DESTDIR='$(CURDIR)'/tmp_check/install install >'$(CURDIR)'/tmp_check/log/install.log 2>&1
cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(CURDIR)/tmp_check/install$(bindir):$$PATH" $(call add_to_path,$(ld_library_path_var),$(CURDIR)/tmp_check/install$(libdir)) top_builddir='$(CURDIR)/$(top_builddir)' PGPORT='6$(DEF_PGPORT)' $(PROVE) $(PG_PROVE_FLAGS) $(PROVE_FLAGS) t/*.pl
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index 24a828b..538ca0a 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -30,7 +30,7 @@ print HBA "local replication all trust\n";
print HBA "host replication all 127.0.0.1/32 trust\n";
print HBA "host replication all ::1/128 trust\n";
close HBA;
-system_or_bail 'pg_ctl', '-s', '-D', "$tempdir/pgdata", 'reload';
+system_or_bail 'pg_ctl', '-D', "$tempdir/pgdata", 'reload';
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
diff --git a/src/bin/pg_controldata/t/001_pg_controldata.pl b/src/bin/pg_controldata/t/001_pg_controldata.pl
index a4180e7..e36fa2d 100644
--- a/src/bin/pg_controldata/t/001_pg_controldata.pl
+++ b/src/bin/pg_controldata/t/001_pg_controldata.pl
@@ -11,6 +11,6 @@ program_options_handling_ok('pg_controldata');
command_fails(['pg_controldata'], 'pg_controldata without arguments fails');
command_fails([ 'pg_controldata', 'nonexistent' ],
'pg_controldata with nonexistent directory fails');
-system_or_bail "initdb -D '$tempdir'/data -A trust >/dev/null";
+system_or_bail 'initdb', '-D', "$tempdir/data", '-A', 'trust';
command_like([ 'pg_controldata', "$tempdir/data" ],
qr/checkpoint/, 'pg_controldata produces output');
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 0f62c14..dacdd3e 100644
--- a/src/bin/pg_ctl/t/001_start_stop.pl
+++ b/src/bin/pg_ctl/t/001_start_stop.pl
@@ -33,4 +33,4 @@ command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
command_ok([ 'pg_ctl', 'restart', '-D', "$tempdir/data", '-w', '-m', 'fast' ],
'pg_ctl restart with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/bin/pg_ctl/t/002_status.pl b/src/bin/pg_ctl/t/002_status.pl
index 9f84f38..86e8101 100644
--- a/src/bin/pg_ctl/t/002_status.pl
+++ b/src/bin/pg_ctl/t/002_status.pl
@@ -15,9 +15,9 @@ close CONF;
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
3, 'pg_ctl status with server not running');
-system_or_bail 'pg_ctl', '-s', '-l', "$tempdir/logfile", '-D',
+system_or_bail 'pg_ctl', '-l', "$tempdir/logfile", '-D',
"$tempdir/data", '-w', 'start';
command_exit_is([ 'pg_ctl', 'status', '-D', "$tempdir/data" ],
0, 'pg_ctl status with server running');
-system_or_bail 'pg_ctl', '-s', 'stop', '-D', "$tempdir/data", '-m', 'fast';
+system_or_bail 'pg_ctl', 'stop', '-D', "$tempdir/data", '-m', 'fast';
diff --git a/src/test/perl/SimpleTee.pm b/src/test/perl/SimpleTee.pm
new file mode 100644
index 0000000..8d31a40
--- /dev/null
+++ b/src/test/perl/SimpleTee.pm
@@ -0,0 +1,27 @@
+# A simple 'tee' implementation, using perl tie.
+#
+# Whenever you print to the handle, it gets forwarded to a list of
+# handles. The list of output filehandles is passed to the constructor.
+#
+# This is similar to IO::Tee, but only used for output. Only the PRINT
+# method is currently implemented; that's all we need. We don't want to
+# depend on IO::Tee just for this.
+
+package SimpleTee;
+use strict;
+
+sub TIEHANDLE {
+ my $self = shift;
+ bless \@_, $self;
+}
+
+sub PRINT {
+ my $self = shift;
+ my $ok = 1;
+ for my $fh (@$self) {
+ print $fh @_ or $ok = 0;
+ }
+ return $ok;
+}
+
+1;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index 003cd9a..37a1bc1 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -12,6 +12,8 @@ our @EXPORT = qw(
restart_test_server
psql
system_or_bail
+ system_log
+ run_log
command_ok
command_fails
@@ -24,11 +26,47 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
+
+use SimpleTee;
+
use Test::More;
+# Open log file. For each test, the log file name uses the name of the
+# file launching this module, without the .pl suffix.
+my $log_path = 'tmp_check/log';
+mkdir 'tmp_check';
+mkdir $log_path;
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = "$log_path/regress_log_$test_logfile";
+open TESTLOG, '>', $test_logfile or die "Cannot open STDOUT to logfile: $!";
+
+# Hijack STDOUT and STDERR to the log file
+open(ORIG_STDOUT, ">&STDOUT");
+open(ORIG_STDERR, ">&STDERR");
+open(STDOUT, ">&TESTLOG");
+open(STDERR, ">&TESTLOG");
+
+# The test output (ok ...) needs to be printed to the original STDOUT so
+# that the 'prove' program can parse it, and display it to the user in
+# real time. But also copy it to the log file, to provide more context
+# in the log.
+my $builder = Test::More->builder;
+my $fh = $builder->output;
+tie *$fh, "SimpleTee", *ORIG_STDOUT, *TESTLOG;
+$fh = $builder->failure_output;
+tie *$fh, "SimpleTee", *ORIG_STDERR, *TESTLOG;
+
+# Enable auto-flushing for all the file handles. Stderr and stdout are
+# redirected to the same file, and buffering causes the lines to appear
+# in the log in confusing order.
+autoflush STDOUT 1;
+autoflush STDERR 1;
+autoflush TESTLOG 1;
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -73,7 +111,7 @@ sub tempdir_short
sub standard_initdb
{
my $pgdata = shift;
- system_or_bail("initdb -D '$pgdata' -A trust -N >/dev/null");
+ system_or_bail('initdb', '-D', "$pgdata", '-A' , 'trust', '-N');
system_or_bail("$ENV{top_builddir}/src/test/regress/pg_regress",
'--config-auth', $pgdata);
}
@@ -87,14 +125,15 @@ sub start_test_server
my $tempdir_short = tempdir_short;
+ print("### Starting test server in $tempdir\n");
standard_initdb "$tempdir/pgdata";
- $ret = system 'pg_ctl', '-D', "$tempdir/pgdata", '-s', '-w', '-l',
+ $ret = system_log('pg_ctl', '-D', "$tempdir/pgdata", '-w', '-l',
"$tempdir/logfile", '-o',
- "--fsync=off -k $tempdir_short --listen-addresses='' --log-statement=all",
- 'start';
-
+"--fsync=off -k \"$tempdir_short\" --listen-addresses='' --log-statement=all",
+ 'start');
if ($ret != 0)
{
+ print "# pg_ctl failed; logfile:\n";
system('cat', "$tempdir/logfile");
BAIL_OUT("pg_ctl failed");
}
@@ -106,28 +145,45 @@ sub start_test_server
sub restart_test_server
{
- system 'pg_ctl', '-s', '-D', $test_server_datadir, '-w', '-l',
- $test_server_logfile, 'restart';
+ print("### Restarting test server\n");
+ system_log('pg_ctl', '-D', $test_server_datadir, '-w', '-l',
+ $test_server_logfile, 'restart');
}
END
{
if ($test_server_datadir)
{
- system 'pg_ctl', '-D', $test_server_datadir, '-s', '-w', '-m',
- 'immediate', 'stop';
+ system_log('pg_ctl', '-D', $test_server_datadir, '-m',
+ 'immediate', 'stop');
}
}
sub psql
{
my ($dbname, $sql) = @_;
+ print("# Running SQL command: $sql\n");
run [ 'psql', '-X', '-q', '-d', $dbname, '-f', '-' ], '<', \$sql or die;
}
sub system_or_bail
{
- system(@_) == 0 or BAIL_OUT("system @_ failed: $?");
+ if (system_log(@_) != 0)
+ {
+ BAIL_OUT("system $_[0] failed: $?");
+ }
+}
+
+sub system_log
+{
+ print("# Running: " . join(" ", @_) ."\n");
+ return system(@_);
+}
+
+sub run_log
+{
+ print("# Running: " . join(" ", @{$_[0]}) ."\n");
+ return run (@_);
}
@@ -139,24 +195,22 @@ sub system_or_bail
sub command_ok
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok($result, $test_name);
}
sub command_fails
{
my ($cmd, $test_name) = @_;
- my $result = run $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ my $result = run_log($cmd);
ok(!$result, $test_name);
}
sub command_exit_is
{
my ($cmd, $expected, $test_name) = @_;
- my $h = start $cmd, '>', File::Spec->devnull(), '2>',
- File::Spec->devnull();
+ print("# Running: " . join(" ", @{$cmd}) ."\n");
+ my $h = start $cmd;
$h->finish();
is($h->result(0), $expected, $test_name);
}
@@ -165,6 +219,7 @@ sub program_help_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --help\n");
my $result = run [ $cmd, '--help' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --help exit code 0");
isnt($stdout, '', "$cmd --help goes to stdout");
@@ -175,6 +230,7 @@ sub program_version_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
+ print("# Running: $cmd --version\n");
my $result = run [ $cmd, '--version' ], '>', \$stdout, '2>', \$stderr;
ok($result, "$cmd --version exit code 0");
isnt($stdout, '', "$cmd --version goes to stdout");
@@ -185,7 +241,9 @@ sub program_options_handling_ok
{
my ($cmd) = @_;
my ($stdout, $stderr);
- my $result = run [ $cmd, '--not-a-valid-option' ], '>', \$stdout, '2>', \$stderr;
+ print("# Running: $cmd --not-a-valid-option\n");
+ my $result = run [ $cmd, '--not-a-valid-option' ], '>', \$stdout, '2>',
+ \$stderr;
ok(!$result, "$cmd with invalid option nonzero exit code");
isnt($stderr, '', "$cmd with invalid option prints error message");
}
@@ -194,6 +252,7 @@ sub command_like
{
my ($cmd, $expected_stdout, $test_name) = @_;
my ($stdout, $stderr);
+ print("# Running: " . join(" ", @{$cmd}) . "\n");
my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
ok($result, "@$cmd exit code 0");
is($stderr, '', "@$cmd no stderr");
@@ -203,9 +262,8 @@ sub command_like
sub issues_sql_like
{
my ($cmd, $expected_sql, $test_name) = @_;
- my ($stdout, $stderr);
truncate $test_server_logfile, 0;
- my $result = run $cmd, '>', \$stdout, '2>', \$stderr;
+ my $result = run_log($cmd);
ok($result, "@$cmd exit code 0");
my $log = `cat '$test_server_logfile'`;
like($log, $expected_sql, "$test_name: SQL found in server log");
--
2.4.5
On Thu, Jul 9, 2015 at 9:43 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Heikki Linnakangas <hlinnaka@iki.fi> writes:
Pushed, thanks.
Shouldn't we consider back-patching these improvements into 9.5 and 9.4?
ISTM the main point is to help debug buildfarm failures, and we won't be
getting much benefit if only one-third of such reports have decent
logging.
+1.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 07/09/2015 06:29 AM, Heikki Linnakangas wrote:
On 07/09/2015 04:50 AM, Michael Paquier wrote:
Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.
What was the reason for not backpatching this? I have a fix for the
execrable treatment of vpath builds, but it only applies to the tip
branch because it relies on this.
cheers
andrew
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 07/28/2015 05:49 PM, Andrew Dunstan wrote:
On 07/09/2015 06:29 AM, Heikki Linnakangas wrote:
On 07/09/2015 04:50 AM, Michael Paquier wrote:
Except that this patch looks good to me. Thanks for the black magic on
stdout/stderr handling.Thanks, fixed the parenthesis and committed. The missing --debug is a
separate issue.What was the reason for not backpatching this? I have a fix for the
execrable treatment of vpath builds, but it only applies to the tip
branch because it relies on this.
No reason, other than the general only-backpatch-bug-fixes rule. Several
people requested it, and it seems reasonable to me too, but it fell off
my radar. Feel free to backpatch...
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers