On Wed, Jul 8, 2015 at 6:10 AM, Heikki Linnakangas <hlinn...@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: >> http://www.postgresql.org/message-id/13002.1434307...@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 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
From dccb8d2226ea2ffa40fd9702cbc26196f214471d Mon Sep 17 00:00:00 2001 From: Michael Paquier <mich...@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
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers