]> granicus.if.org Git - postgresql/commitdiff
Improve logging of TAP tests.
authorHeikki Linnakangas <heikki.linnakangas@iki.fi>
Thu, 9 Jul 2015 10:19:10 +0000 (13:19 +0300)
committerHeikki Linnakangas <heikki.linnakangas@iki.fi>
Thu, 9 Jul 2015 10:19:10 +0000 (13:19 +0300)
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.

14 files changed:
src/Makefile.global.in
src/bin/pg_basebackup/t/010_pg_basebackup.pl
src/bin/pg_controldata/t/001_pg_controldata.pl
src/bin/pg_ctl/t/001_start_stop.pl
src/bin/pg_ctl/t/002_status.pl
src/bin/pg_rewind/.gitignore
src/bin/pg_rewind/Makefile
src/bin/pg_rewind/RewindTest.pm
src/bin/pg_rewind/t/001_basic.pl
src/bin/pg_rewind/t/002_databases.pl
src/bin/pg_rewind/t/003_extrafiles.pl
src/test/perl/SimpleTee.pm [new file with mode: 0644]
src/test/perl/TestLib.pm
src/test/ssl/ServerSetup.pm

index 8eab178ebd3822deb015f7dd1f5f4037a315045b..8d1250d36485ff257ceaa580fb3fbe5c5f1a35e8 100644 (file)
@@ -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
 
index c8c9250b3845f93840e05d3550059deb880ec3c2..e47c3a0bb7cdd097217edce69d894de70176d4ac 100644 (file)
@@ -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" ],
index a4180e7ed18a50b6f0467955daf7f8c579448162..e36fa2d45d99ccf404bdd9a896d61c4f0f62e3f8 100644 (file)
@@ -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');
index 6c9ec5c717af668b5653a585c8758aba267053ad..bcceb57d7bcdf877a0d0ccf500bcca6720b9a6d0 100644 (file)
@@ -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';
index 055885495ab14f2f3f961172a01c6987efd29b46..ec0a2a786e09cff120bad15e07eaa64b6789bab8 100644 (file)
@@ -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';
index 9ade7efcce4e033c266a452a43047d310a2719f4..79ddca3eec901a19d36f777250a8611b40ed5e5d 100644 (file)
@@ -4,4 +4,3 @@
 
 # Generated by test suite
 /tmp_check/
-/regress_log/
index 7d607157e38831a7c7f6f1fb4525aa9c57ad9968..92b5d20afa707bc2dfe1137ac0cb8aee536b427b 100644 (file)
@@ -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)
index 5219ec967ae94cde92154f78e25aa38140f4dd06..e57b41734df2368b34064bed274960b76346a790 100644 (file)
@@ -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';
        }
 }
 
index f60368bd307e735ca8cc3c75895bf7c5095d846c..be7d887bb7c9723ca56b32fadc7522c7a62ee0e9 100644 (file)
@@ -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.
index 7564fa98a5377c3411e75827d4e12f007d893800..b0b007a763ad20448aa1c28d7f22e0e8c367c4da 100644 (file)
@@ -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.
index 9a952685be91af6b82416f7a7920225ceaa59b4f..0cd0ac4d5677bcde1c3384bfc15dbbd83ae81fe2 100644 (file)
@@ -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 (file)
index 0000000..8d31a40
--- /dev/null
@@ -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;
index ef42366888e5c73e7145fc4635297848edf9679e..0193d575ff78b0428166caadd47408c1636f648e 100644 (file)
@@ -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");
index bbff99a3bdb8cd913a2334270cef2da8e1880a7a..8c1b517575500f08476f049d021414dc8d4c40a0 100644 (file)
@@ -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';
 }