On Thu, Jun 18, 2015 at 3:52 PM, Michael Paquier wrote: > I think that it would be useful as well to improve the buildfarm > output. Thoughts?
And after running the tests more or less 6~7 times in a row on a PI, I
have been able to trigger the problem and I think that I have found
its origin. First, the error has been triggered by the tests of
pg_rewind:
t/002_databases.pl ...
1..4
Bailout called. Further testing stopped: run pg_ctl failed: 256
Bail out! run pg_ctl failed: 256
FAILED--Further testing stopped: run pg_ctl failed: 256
Makefile:51: recipe for target 'check' failed
make[1]: *** [check] Error 255
And by looking at the logs obtained thanks to the previous patch I
could see the following (log attached for tests 1 and 2):
$ tail -n5 regress_log/regress_log_002_databases
waiting for server to start........ stopped waiting
pg_ctl: could not start server
Examine the log output.
LOG: received immediate shutdown request
LOG: received immediate shutdown request
pg_ctl should be able to start the server and should not fail here.
This is confirmed by the fact that first test has not stopped the
servers. On a clean run, the immediate shutdown request is received
and done:
waiting for server to shut down....LOG: received immediate shutdown request
LOG: unexpected EOF on standby connection
done
But in the case of the failure this does not happen:
LOG: received immediate shutdown request
LOG: unexpected EOF on standby connection
LOG: received immediate shutdown request
See the "done" is not here.
Now if we look at RewindTest.pm, there is the following code:
if ($test_master_datadir)
{
system
"pg_ctl -D $test_master_datadir -s -m immediate stop
2> /dev/null";
}
if ($test_standby_datadir)
{
system
"pg_ctl -D $test_standby_datadir -s -m immediate
stop 2> /dev/null";
}
And I think that the problem is triggered because we are missing a -w
switch here, meaning that we do not wait until the confirmation that
the server has stopped, and visibly if stop is slow enough the next
server to use cannot start because the port is already taken by the
server currently stopping.
Note as well that the last command of pg_ctl stop in
pg_ctl/t/002_status.pl does not use -w, so we have the same problem
there.
Attached is a patch fixing those problems and improving the log
facility as it really helped me out with those issues. The simplest
fix would be to include the -w switch missing in the tests of
pg_rewind and pg_ctl though.
It would be good to get that fixed, then I would be able to re-enable
the TAP tests of hamster. I have run the tests a dozen of times again
with this patch, and I could not trigger the failure anymore.
Regards,
--
Michael
regress_log_001_basic
Description: Binary data
regress_log_002_databases
Description: Binary data
From 50ea935f3873df7c206e6ff3890a3d2219698098 Mon Sep 17 00:00:00 2001
From: Michael Paquier <michael@otacoo.com>
Date: Fri, 19 Jun 2015 14:12:09 +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.
Some commands of pg_ctl was lacking a -w switch, meaning that in rather
slow environments this could lead to a server not able to start if the
last server stopped did not yet acknowledge the stop request.
---
src/Makefile.global.in | 1 +
src/bin/pg_basebackup/.gitignore | 1 +
src/bin/pg_basebackup/Makefile | 2 +-
src/bin/pg_basebackup/t/010_pg_basebackup.pl | 4 +-
src/bin/pg_controldata/.gitignore | 1 +
src/bin/pg_controldata/Makefile | 2 +-
src/bin/pg_controldata/t/001_pg_controldata.pl | 2 +-
src/bin/pg_ctl/.gitignore | 1 +
src/bin/pg_ctl/Makefile | 2 +-
src/bin/pg_ctl/t/001_start_stop.pl | 2 +-
src/bin/pg_ctl/t/002_status.pl | 6 +--
src/bin/pg_rewind/RewindTest.pm | 68 +++++++++++++-------------
src/bin/scripts/.gitignore | 1 +
src/bin/scripts/Makefile | 2 +-
src/test/perl/TestLib.pm | 48 +++++++++++++-----
src/test/ssl/.gitignore | 1 +
src/test/ssl/Makefile | 3 ++
src/test/ssl/ServerSetup.pm | 6 +--
18 files changed, 90 insertions(+), 63 deletions(-)
diff --git a/src/Makefile.global.in b/src/Makefile.global.in
index c583b44..4b1de8c 100644
--- a/src/Makefile.global.in
+++ b/src/Makefile.global.in
@@ -336,6 +336,7 @@ cd $(srcdir) && TESTDIR='$(CURDIR)' PATH="$(bindir):$$PATH" PGPORT='6$(DEF_PGPOR
endef
define prove_check
+rm -rf $(srcdir)/regress_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/.gitignore b/src/bin/pg_basebackup/.gitignore
index 36a2f12..746908b 100644
--- a/src/bin/pg_basebackup/.gitignore
+++ b/src/bin/pg_basebackup/.gitignore
@@ -2,4 +2,5 @@
/pg_receivexlog
/pg_recvlogical
+/regress_log/
/tmp_check/
diff --git a/src/bin/pg_basebackup/Makefile b/src/bin/pg_basebackup/Makefile
index 0d8421a..66771dc 100644
--- a/src/bin/pg_basebackup/Makefile
+++ b/src/bin/pg_basebackup/Makefile
@@ -48,7 +48,7 @@ clean distclean maintainer-clean:
rm -f pg_basebackup$(X) pg_receivexlog$(X) pg_recvlogical$(X) \
pg_basebackup.o pg_receivexlog.o pg_recvlogical.o \
$(OBJS)
- rm -rf tmp_check
+ rm -rf tmp_check regress_log
check:
$(prove_check)
diff --git a/src/bin/pg_basebackup/t/010_pg_basebackup.pl b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
index 3476ea6..ecff372 100644
--- a/src/bin/pg_basebackup/t/010_pg_basebackup.pl
+++ b/src/bin/pg_basebackup/t/010_pg_basebackup.pl
@@ -22,7 +22,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', '-s', '-D', "$tempdir/pgdata", 'reload']);
command_fails(
[ 'pg_basebackup', '-D', "$tempdir/backup" ],
@@ -51,7 +51,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/.gitignore b/src/bin/pg_controldata/.gitignore
index 051d71d..04d0c68 100644
--- a/src/bin/pg_controldata/.gitignore
+++ b/src/bin/pg_controldata/.gitignore
@@ -1,2 +1,3 @@
/pg_controldata
/tmp_check/
+/regress_log/
diff --git a/src/bin/pg_controldata/Makefile b/src/bin/pg_controldata/Makefile
index fd7399b..3853dd1 100644
--- a/src/bin/pg_controldata/Makefile
+++ b/src/bin/pg_controldata/Makefile
@@ -33,7 +33,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_controldata$(X) $(OBJS)
- rm -rf tmp_check
+ rm -rf tmp_check regress_log
check:
$(prove_check)
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/.gitignore b/src/bin/pg_ctl/.gitignore
index 73ab4ed..3efa15d 100644
--- a/src/bin/pg_ctl/.gitignore
+++ b/src/bin/pg_ctl/.gitignore
@@ -1,2 +1,3 @@
/pg_ctl
/tmp_check/
+/regress_log/
diff --git a/src/bin/pg_ctl/Makefile b/src/bin/pg_ctl/Makefile
index 37eb482..5bce54f 100644
--- a/src/bin/pg_ctl/Makefile
+++ b/src/bin/pg_ctl/Makefile
@@ -36,7 +36,7 @@ uninstall:
clean distclean maintainer-clean:
rm -f pg_ctl$(X) $(OBJS)
- rm -rf tmp_check
+ rm -rf tmp_check regress_log
check:
$(prove_check)
diff --git a/src/bin/pg_ctl/t/001_start_stop.pl b/src/bin/pg_ctl/t/001_start_stop.pl
index 6c9ec5c..132e1a4 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', '-w', '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..e72dba9 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', '-w', 'stop', '-D', "$tempdir/data", '-m', 'fast']);
diff --git a/src/bin/pg_rewind/RewindTest.pm b/src/bin/pg_rewind/RewindTest.pm
index 5219ec9..e8bafc2 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
@@ -175,10 +176,6 @@ 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
@@ -209,8 +206,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 +224,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 +235,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 +256,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 +275,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', '-w', '-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 +295,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', '-w', '-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 +337,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 +350,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', '-w', '-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', '-w', '-D', $test_standby_datadir, '-m', 'immediate',
+ 'stop']);
}
}
diff --git a/src/bin/scripts/.gitignore b/src/bin/scripts/.gitignore
index 1056b28..b1647a7 100644
--- a/src/bin/scripts/.gitignore
+++ b/src/bin/scripts/.gitignore
@@ -16,3 +16,4 @@
/print.c
/tmp_check/
+/regress_log/
\ No newline at end of file
diff --git a/src/bin/scripts/Makefile b/src/bin/scripts/Makefile
index c831716..c699470 100644
--- a/src/bin/scripts/Makefile
+++ b/src/bin/scripts/Makefile
@@ -67,7 +67,7 @@ clean distclean maintainer-clean:
rm -f $(addsuffix $(X), $(PROGRAMS)) $(addsuffix .o, $(PROGRAMS))
rm -f common.o dumputils.o kwlookup.o keywords.o print.o mbprint.o $(WIN32RES)
rm -f dumputils.c print.c mbprint.c kwlookup.c keywords.c
- rm -rf tmp_check
+ rm -rf tmp_check regress_log
check:
$(prove_check)
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index ef42366..a9350f9 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,16 @@ our @EXPORT = qw(
);
use Cwd;
+use File::Basename;
use File::Spec;
use File::Temp ();
use IPC::Run qw(run start);
use Test::More;
+mkdir 'regress_log';
+my $test_logfile = basename($0);
+$test_logfile =~ s/\.[^.]+$//;
+$test_logfile = 'regress_log/regress_log_' . $test_logfile;
# Set to untranslated messages, to be able to compare program output
# with expected strings.
@@ -77,9 +84,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 +99,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 +117,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, '-w', '-m',
+ 'immediate', 'stop']);
}
}
@@ -131,7 +138,22 @@ 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: $?");
+ }
}
diff --git a/src/test/ssl/.gitignore b/src/test/ssl/.gitignore
index a325c2f..d7b2b23 100644
--- a/src/test/ssl/.gitignore
+++ b/src/test/ssl/.gitignore
@@ -1,3 +1,4 @@
# Generated by regression tests
/client-log
/tmp_check/
+/regress_log/
diff --git a/src/test/ssl/Makefile b/src/test/ssl/Makefile
index d9fd29a..785500e 100644
--- a/src/test/ssl/Makefile
+++ b/src/test/ssl/Makefile
@@ -122,5 +122,8 @@ ssl/root+client.crl: ssl/root.crl ssl/client.crl
sslfiles-clean:
rm -f $(SSLFILES) ssl/client_ca.srl ssl/server_ca.srl ssl/client_ca-certindex* ssl/server_ca-certindex* ssl/root_ca-certindex* ssl/root_ca.srl ssl/temp_ca.crt ssl/temp_ca_signed.crt
+clean:
+ rm -rf regress_log
+
check:
$(prove_check)
diff --git a/src/test/ssl/ServerSetup.pm b/src/test/ssl/ServerSetup.pm
index 4ce4a69..6b186a4 100644
--- a/src/test/ssl/ServerSetup.pm
+++ b/src/test/ssl/ServerSetup.pm
@@ -111,8 +111,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', '-s', '-D', "$tempdir/pgdata", '-w']);
+ run_or_bail(['pg_ctl', 'start', '-s', '-D', "$tempdir/pgdata", '-w']);
}
--
2.4.4
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
