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 Heikki Linnakangas.

This os a backpatch of Heikki's commit
1ea06203b82b98b5098808667f6ba652181ef5b2 modified by me to suit 9.4

diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index aec6187af6da797cbb24bc867c91f4db7d1722d2..d321dc7450697bb6263b4e7a128b2b74508ec222 100644 (file)
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -322,9 +322,8 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
 endef
 
 define prove_check
-$(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
+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
 
 else

diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index 24a828bb0a332b96c2dbd1b686231935c31e1b47..538ca0aba2c2900d43e7e9b2fde12b9f18b7de73 100644 (file)
--- 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 a4180e7ed18a50b6f0467955daf7f8c579448162..e36fa2d45d99ccf404bdd9a896d61c4f0f62e3f8 100644 (file)
--- 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 0f62c1439a70737f6f1ef2bf8f78829b06cb5fc9..dacdd3e6b38c43bd88dd407d6773e32bf3e66dfa 100644 (file)
--- 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 9f84f3849c05e608676d9fb7607f14ccc0003108..86e810176b608578e3690651c2068cfd1a3c9f6e 100644 (file)
--- 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 (file)
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 003cd9a2cca9d56ad2ecdd4cf2a9b192939a6bba..37a1bc16208310fbc44bdb1961fcd4a36d08980e 100644 (file)
--- 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");