pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedSIGPIPE in TAP tests
4+ messages / 2 participants
[nested] [flat]
* SIGPIPE in TAP tests
@ 2017-12-09 21:02 Noah Misch <noah@leadboat.com>
0 siblings, 1 reply; 4+ messages in thread
From: Noah Misch @ 2017-12-09 21:02 UTC (permalink / raw)
To: pgsql-hackers
Two buildfarm runs[1][2] from the last 90 days have failed in
src/test/authentication, like this:
t/001_password.pl ..
Failed 3/8 subtests
t/002_saslprep.pl .. ok 1815 ms ( 0.00 usr 0.00 sys + 0.89 cusr 0.26 csys = 1.15 CPU)
Test Summary Report
-------------------
t/001_password.pl (Wstat: 13 Tests: 5 Failed: 0)
Non-zero wait status: 13
Parse errors: Bad plan. You planned 8 tests but ran 5.
Files=2, Tests=17, 3 wallclock secs ( 0.04 usr 0.00 sys + 1.67 cusr 0.50 csys = 2.21 CPU)
Result: FAIL
Compared to a good run, the other logs just end suddenly after the expected
"FATAL: password authentication failed". "Wstat: 13" means the Perl process
died to signal 13 (SIGPIPE). This test invokes psql in a way that fails
authentication, and it writes "SELECT 1" to psql's stdin. The SIGPIPE happens
if the psql process exits before that write. I can reproduce this
consistently by patching a delay into IPC::Run:
--- IPC/Run.pm~ 2017-05-12 06:46:43.000000000 -0700
+++ IPC/Run.pm 2017-12-09 00:24:06.876132628 -0800
@@ -1449,6 +1449,8 @@
sub run {
local $in_run = 1; ## Allow run()-only optimizations.
my IPC::Run $self = start(@_);
+ use Time::HiRes 'usleep';
+ usleep 100_000;
The two src/test/authentication tests then fail, but nothing else fails.
Let's ignore SIGPIPE in all TAP tests, which leaves some evidence in
regress_log_001_password:
ack Broken pipe: write( 13, 'SELECT 1' ) at /home/nm/sw/cpan/lib/perl5/IPC/Run/IO.pm line 549.
To fix the actual failures, we can cease sending "SELECT 1"; it's enough to
disconnect immediately. Patch attached.
[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=crake&dt=2017-11-23%2008%3A37%3A17
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mandrill&dt=2017-10-30%2000%3A14%3A09
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 2d3f674..9340f2f 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -44,8 +44,7 @@ sub test_role
$status_string = 'success' if ($expected_res eq 0);
- my $res =
- $node->psql('postgres', 'SELECT 1', extra_params => [ '-U', $role ]);
+ my $res = $node->psql('postgres', undef, extra_params => [ '-U', $role ]);
is($res, $expected_res,
"authentication $status_string for method $method, role $role");
}
diff --git a/src/test/authentication/t/002_saslprep.pl b/src/test/authentication/t/002_saslprep.pl
index df9f85d..e09273e 100644
--- a/src/test/authentication/t/002_saslprep.pl
+++ b/src/test/authentication/t/002_saslprep.pl
@@ -41,8 +41,7 @@ sub test_login
$status_string = 'success' if ($expected_res eq 0);
$ENV{"PGPASSWORD"} = $password;
- my $res =
- $node->psql('postgres', 'SELECT 1', extra_params => [ '-U', $role ]);
+ my $res = $node->psql('postgres', undef, extra_params => [ '-U', $role ]);
is($res, $expected_res,
"authentication $status_string for role $role with password $password"
);
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index d1a2eb5..6019040 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -75,6 +75,10 @@ BEGIN
INIT
{
+ # Return EPIPE instead of killing the process with SIGPIPE. An affected
+ # test may still fail, but it's more likely to report useful facts.
+ $SIG{PIPE} = 'IGNORE';
+
# Determine output directories, and create them. The base path is the
# TESTDIR environment variable, which is normally set by the invoking
# Makefile.
Attachments:
[text/plain] sigpipe-tap-v1.patch (1.7K, ../../20171209210203.GC3362632@rfd.leadboat.com/2-sigpipe-tap-v1.patch)
download | inline diff:
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 2d3f674..9340f2f 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -44,8 +44,7 @@ sub test_role
$status_string = 'success' if ($expected_res eq 0);
- my $res =
- $node->psql('postgres', 'SELECT 1', extra_params => [ '-U', $role ]);
+ my $res = $node->psql('postgres', undef, extra_params => [ '-U', $role ]);
is($res, $expected_res,
"authentication $status_string for method $method, role $role");
}
diff --git a/src/test/authentication/t/002_saslprep.pl b/src/test/authentication/t/002_saslprep.pl
index df9f85d..e09273e 100644
--- a/src/test/authentication/t/002_saslprep.pl
+++ b/src/test/authentication/t/002_saslprep.pl
@@ -41,8 +41,7 @@ sub test_login
$status_string = 'success' if ($expected_res eq 0);
$ENV{"PGPASSWORD"} = $password;
- my $res =
- $node->psql('postgres', 'SELECT 1', extra_params => [ '-U', $role ]);
+ my $res = $node->psql('postgres', undef, extra_params => [ '-U', $role ]);
is($res, $expected_res,
"authentication $status_string for role $role with password $password"
);
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm
index d1a2eb5..6019040 100644
--- a/src/test/perl/TestLib.pm
+++ b/src/test/perl/TestLib.pm
@@ -75,6 +75,10 @@ BEGIN
INIT
{
+ # Return EPIPE instead of killing the process with SIGPIPE. An affected
+ # test may still fail, but it's more likely to report useful facts.
+ $SIG{PIPE} = 'IGNORE';
+
# Determine output directories, and create them. The base path is the
# TESTDIR environment variable, which is normally set by the invoking
# Makefile.
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: SIGPIPE in TAP tests
@ 2017-12-11 07:19 Michael Paquier <michael.paquier@gmail.com>
parent: Noah Misch <noah@leadboat.com>
0 siblings, 1 reply; 4+ messages in thread
From: Michael Paquier @ 2017-12-11 07:19 UTC (permalink / raw)
To: Noah Misch <noah@leadboat.com>; +Cc: pgsql-hackers
On Sun, Dec 10, 2017 at 6:02 AM, Noah Misch <noah@leadboat.com> wrote:
> Two buildfarm runs[1][2] from the last 90 days have failed in
> src/test/authentication, like this:
>
> t/001_password.pl ..
> Failed 3/8 subtests
> t/002_saslprep.pl .. ok 1815 ms ( 0.00 usr 0.00 sys + 0.89 cusr 0.26 csys = 1.15 CPU)
>
> Test Summary Report
> -------------------
> t/001_password.pl (Wstat: 13 Tests: 5 Failed: 0)
> Non-zero wait status: 13
> Parse errors: Bad plan. You planned 8 tests but ran 5.
> Files=2, Tests=17, 3 wallclock secs ( 0.04 usr 0.00 sys + 1.67 cusr 0.50 csys = 2.21 CPU)
> Result: FAIL
>
> Compared to a good run, the other logs just end suddenly after the expected
> "FATAL: password authentication failed". "Wstat: 13" means the Perl process
> died to signal 13 (SIGPIPE). This test invokes psql in a way that fails
> authentication, and it writes "SELECT 1" to psql's stdin. The SIGPIPE happens
> if the psql process exits before that write.
Nice investigation. An interesting coincidence is that I have looked
yesterday at an off-list reported some folks have sent me which is
basically what you have here.
+ # Return EPIPE instead of killing the process with SIGPIPE. An affected
+ # test may still fail, but it's more likely to report useful facts.
+ $SIG{PIPE} = 'IGNORE';
With this portion changed I can indeed see something which is more helpful:
psql: FATAL: password authentication failed for user "saslpreptest1_role"
ack Broken pipe: write( 11, 'SELECT 1' ) at
/Library/Perl/5.18/IPC/Run/IO.pm line 558.
If SIGPIPE is ignored then test output just stops after generating the
FATAL message. Oops.
> The two src/test/authentication tests then fail, but nothing else fails.
> Let's ignore SIGPIPE in all TAP tests, which leaves some evidence in
> regress_log_001_password:
>
> ack Broken pipe: write( 13, 'SELECT 1' ) at /home/nm/sw/cpan/lib/perl5/IPC/Run/IO.pm line 549.
>
> To fix the actual failures, we can cease sending "SELECT 1"; it's enough to
> disconnect immediately. Patch attached.
Perhaps you could use an empty string instead? I feel a bit uneasy
about passing an undefined object to IPC::Run::run.
--
Michael
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: SIGPIPE in TAP tests
@ 2017-12-11 07:32 Noah Misch <noah@leadboat.com>
parent: Michael Paquier <michael.paquier@gmail.com>
0 siblings, 1 reply; 4+ messages in thread
From: Noah Misch @ 2017-12-11 07:32 UTC (permalink / raw)
To: Michael Paquier <michael.paquier@gmail.com>; +Cc: pgsql-hackers
On Mon, Dec 11, 2017 at 04:19:52PM +0900, Michael Paquier wrote:
> On Sun, Dec 10, 2017 at 6:02 AM, Noah Misch <noah@leadboat.com> wrote:
> If SIGPIPE is ignored then test output just stops after generating the
> FATAL message. Oops.
You mean "If SIGPIPE is not ignored ...", right?
> > To fix the actual failures, we can cease sending "SELECT 1"; it's enough to
> > disconnect immediately. Patch attached.
>
> Perhaps you could use an empty string instead? I feel a bit uneasy
> about passing an undefined object to IPC::Run::run.
IPC::Run documents the equivalence of undef and '' in this context; search for
"close a child processes stdin" in
http://search.cpan.org/~rbs/IPC-Run-0.78/lib/IPC/Run.pm. Thus, I expect both
spellings to work reliably, and I find "undef" slightly more evocative.
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: SIGPIPE in TAP tests
@ 2017-12-11 08:17 Michael Paquier <michael.paquier@gmail.com>
parent: Noah Misch <noah@leadboat.com>
0 siblings, 0 replies; 4+ messages in thread
From: Michael Paquier @ 2017-12-11 08:17 UTC (permalink / raw)
To: Noah Misch <noah@leadboat.com>; +Cc: pgsql-hackers
On Mon, Dec 11, 2017 at 4:32 PM, Noah Misch <noah@leadboat.com> wrote:
> On Mon, Dec 11, 2017 at 04:19:52PM +0900, Michael Paquier wrote:
>> On Sun, Dec 10, 2017 at 6:02 AM, Noah Misch <noah@leadboat.com> wrote:
>
>> If SIGPIPE is ignored then test output just stops after generating the
>> FATAL message. Oops.
>
> You mean "If SIGPIPE is not ignored ...", right?
Yes, sorry.
>> > To fix the actual failures, we can cease sending "SELECT 1"; it's enough to
>> > disconnect immediately. Patch attached.
>>
>> Perhaps you could use an empty string instead? I feel a bit uneasy
>> about passing an undefined object to IPC::Run::run.
>
> IPC::Run documents the equivalence of undef and '' in this context; search for
> "close a child processes stdin" in
> http://search.cpan.org/~rbs/IPC-Run-0.78/lib/IPC/Run.pm. Thus, I expect both
> spellings to work reliably, and I find "undef" slightly more evocative.
Thanks, I missed this bit. No objections to use undef then.
--
Michael
^ permalink raw reply [nested|flat] 4+ messages in thread
end of thread, other threads:[~2017-12-11 08:17 UTC | newest]
Thread overview: 4+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2017-12-09 21:02 SIGPIPE in TAP tests Noah Misch <noah@leadboat.com>
2017-12-11 07:19 ` Michael Paquier <michael.paquier@gmail.com>
2017-12-11 07:32 ` Noah Misch <noah@leadboat.com>
2017-12-11 08:17 ` Michael Paquier <michael.paquier@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox