From 1ea06203b82b98b5098808667f6ba652181ef5b2 Mon Sep 17 00:00:00 2001 From: Heikki Linnakangas 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 +- .../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/bin/pg_rewind/.gitignore | 1 - src/bin/pg_rewind/Makefile | 2 +- src/bin/pg_rewind/RewindTest.pm | 85 +++++++---------- 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/SimpleTee.pm | 27 ++++++ src/test/perl/TestLib.pm | 93 +++++++++++++++---- src/test/ssl/ServerSetup.pm | 6 +- 14 files changed, 143 insertions(+), 85 deletions(-) create mode 100644 src/test/perl/SimpleTee.pm diff --git a/src/Makefile.global.in b/src/Makefile.global.in index 8eab178ebd..8d1250d364 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 c8c9250b38..e47c3a0bb7 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 a4180e7ed1..e36fa2d45d 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 6c9ec5c717..bcceb57d7b 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 055885495a..ec0a2a786e 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 9ade7efcce..79ddca3eec 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 7d607157e3..92b5d20afa 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 5219ec967a..e57b41734d 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 f60368bd30..be7d887bb7 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 7564fa98a5..b0b007a763 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 9a952685be..0cd0ac4d56 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 0000000000..8d31a4013c --- /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 ef42366888..0193d575ff 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. @@ -77,7 +115,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 +129,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 +149,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 +199,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 +223,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 +234,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 +245,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 +256,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 +266,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 bbff99a3bd..8c1b517575 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'; } -- 2.40.0