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.

Author: hlinnaka

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
 

src/bin/pg_basebackup/t/010_pg_basebackup.pl

@@ -30,7 +30,7 @@
 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" ],

src/bin/pg_controldata/t/001_pg_controldata.pl

@@ -11,6 +11,6 @@
 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');

src/bin/pg_ctl/t/001_start_stop.pl

@@ -36,4 +36,4 @@
 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';

src/bin/pg_ctl/t/002_status.pl

@@ -18,9 +18,9 @@
 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';

src/bin/pg_rewind/.gitignore

@@ -4,4 +4,3 @@
 
 # Generated by test suite
 /tmp_check/
-/regress_log/

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)

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';
 	}
 }
 

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.

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.

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;

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;