Skip Menu |

This queue is for tickets about the Prty CPAN distribution.

Report information
The Basics
Id: 122402
Status: resolved
Priority: 0/
Queue: Prty

People
Owner: Nobody in particular
Requestors: SREZIC [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: (no value)
Broken in: 1.115
Fixed in: (no value)



Subject: Ipc.t fails on some systems without diagnostics
On some of my smoker systems (centos6, debian jessie, freebsd) I see the following failure, without any further diagnostics: ... t/bin/Prty/Ipc.t ................................ Failed 2/4 subtests ...
Subject: Re: [rt.cpan.org #122402] Ipc.t fails on some systems without diagnostics
Date: Sun, 9 Jul 2017 13:19:46 +0200
To: bug-Prty [...] rt.cpan.org
From: Frank Seitz <fs [...] fseitz.de>
Hallo Slaven, kannst du mir von einem dieser Systeme die Ausgabe des folgenden Kommandos senden? $ prove -v -Ilib t/bin/Prty/Ipc.t Grüße Frank On 07/09/2017 10:46 AM, Slaven_Rezic via RT wrote: Show quoted text
> Sun Jul 09 04:46:06 2017: Request 122402 was acted upon. > Transaction: Ticket created by SREZIC > Queue: Prty > Subject: Ipc.t fails on some systems without diagnostics > Broken in: 1.115 > Severity: (no value) > Owner: Nobody > Requestors: SREZIC@cpan.org > Status: new > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402 > > > > On some of my smoker systems (centos6, debian jessie, freebsd) I see the following failure, without any further diagnostics: > > ... > t/bin/Prty/Ipc.t ................................ > Failed 2/4 subtests > ...
-- Dipl.-Inform. Frank Seitz IT Consultant / {Web, Database, Linux} Developer Tel: +49-176-78243503, Hauptstr. 32-34, D-25462 Rellingen Blog: http://fseitz.de/blog
Auf einem CentOS6-System: $ /opt/perl-5.22.3/bin/prove -v -Ilib t/bin/Prty/Ipc.t t/bin/Prty/Ipc.t .. 1..4 ok 1 - use Prty::Ipc; ok 2 Failed 2/4 subtests Test Summary Report ------------------- t/bin/Prty/Ipc.t (Wstat: 13 Tests: 2 Failed: 0) Non-zero wait status: 13 Parse errors: Bad plan. You planned 4 tests but ran 2. Files=1, Tests=2, 0 wallclock secs ( 0.02 usr 0.01 sys + 0.08 cusr 0.04 csys = 0.15 CPU) Result: FAIL Signal 13 ist SIGPIPE. Dummerweise ist es ein Heisenbug: sobald ich versuche, mit strace reinzuschauen, läuft der Test erfolgreich durch. Vermutlich ein Timing-Problem; eventuell läuft das externe Kommando zu langsam oder zu schnell. On 2017-07-09 07:20:01, fs@fseitz.de wrote: Show quoted text
> Hallo Slaven, > > kannst du mir von einem dieser Systeme die Ausgabe > des folgenden Kommandos senden? > > $ prove -v -Ilib t/bin/Prty/Ipc.t > > Grüße > Frank > > On 07/09/2017 10:46 AM, Slaven_Rezic via RT wrote:
> > Sun Jul 09 04:46:06 2017: Request 122402 was acted upon. > > Transaction: Ticket created by SREZIC > > Queue: Prty > > Subject: Ipc.t fails on some systems without diagnostics > > Broken in: 1.115 > > Severity: (no value) > > Owner: Nobody > > Requestors: SREZIC@cpan.org > > Status: new > > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402 > > > > > > > On some of my smoker systems (centos6, debian jessie, freebsd) I see > > the following failure, without any further diagnostics: > > > > ... > > t/bin/Prty/Ipc.t ................................ > > Failed 2/4 subtests > > ...
Mit strace bekommt man einen Fehler nur, wenn man -f weglässt. Damit sieht man leider nicht, was in den Kindprozessen passiert, aber immerhin. Die letzten Zeilen: ... 13:35:18.882051 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000009> 13:35:18.882080 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000022> 13:35:18.882140 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 <0.000009> 13:35:18.882181 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f06386a49d0) = 13563 <0.003322> 13:35:18.885560 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000010> 13:35:18.885632 close(14) = 0 <0.000010> 13:35:18.885720 read(13, "", 8192) = 0 <0.001494> 13:35:18.887310 close(13) = 0 <0.000014> 13:35:18.887393 close(3) = 0 <0.000010> 13:35:18.887445 close(10) = 0 <0.000010> 13:35:18.887499 close(12) = 0 <0.000010> 13:35:18.887627 write(4, "Ein Test", 8) = 8 <0.000025> 13:35:18.887675 close(4) = 0 <0.000010> 13:35:18.887707 fstat(9, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 <0.000010> 13:35:18.887741 read(9, "Ein Test", 8192) = 8 <0.000129> 13:35:18.887892 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=13563, si_status=0, si_utime=0, si_stime=0} --- 13:35:18.887912 read(9, "", 8192) = 0 <0.000010> 13:35:18.887941 close(9) = 0 <0.000011> 13:35:18.887976 fstat(11, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 <0.000010> 13:35:18.888009 read(11, "", 8192) = 0 <0.000010> 13:35:18.888041 close(11) = 0 <0.000010> 13:35:18.888080 wait4(13563, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 13563 <0.000013> 13:35:18.888576 write(5, "ok 2\n", 5) = 5 <0.000014> 13:35:18.888756 pipe([3, 4]) = 0 <0.000013> 13:35:18.888799 ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000010> 13:35:18.888830 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000010> 13:35:18.888859 ioctl(4, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000010> 13:35:18.888888 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000010> 13:35:18.888915 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000010> 13:35:18.888943 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000010> 13:35:18.888977 pipe([9, 10]) = 0 <0.000012> 13:35:18.889009 ioctl(9, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000010> 13:35:18.889038 lseek(9, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000009> 13:35:18.889067 ioctl(10, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000009> 13:35:18.889095 lseek(10, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000010> 13:35:18.889122 fcntl(9, F_SETFD, FD_CLOEXEC) = 0 <0.000009> 13:35:18.889149 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 <0.000009> 13:35:18.889182 pipe([11, 12]) = 0 <0.000011> 13:35:18.889214 ioctl(11, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000009> 13:35:18.889242 lseek(11, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000010> 13:35:18.889270 ioctl(12, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000009> 13:35:18.889298 lseek(12, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000009> 13:35:18.889325 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 <0.000010> 13:35:18.889351 fcntl(12, F_SETFD, FD_CLOEXEC) = 0 <0.000009> 13:35:18.889382 pipe([13, 14]) = 0 <0.000011> 13:35:18.889412 ioctl(13, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000010> 13:35:18.889440 lseek(13, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000009> 13:35:18.889468 ioctl(14, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL (Invalid argument) <0.000009> 13:35:18.889496 lseek(14, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000009> 13:35:18.889523 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000010> 13:35:18.889550 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000009> 13:35:18.889589 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 <0.000010> 13:35:18.889623 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f06386a49d0) = 13564 <0.002480> 13:35:18.892175 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000011> 13:35:18.892247 close(14) = 0 <0.000010> 13:35:18.892358 read(13, "", 8192) = 0 <0.001207> 13:35:18.893591 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=13564, si_status=1, si_utime=0, si_stime=0} --- 13:35:18.893632 close(13) = 0 <0.000012> 13:35:18.893707 close(3) = 0 <0.000011> 13:35:18.893747 close(10) = 0 <0.000010> 13:35:18.893788 close(12) = 0 <0.000011> 13:35:18.893912 write(4, "Ein Test", 8) = -1 EPIPE (Broken pipe) <0.000011> 13:35:18.893959 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=13562, si_uid=1023} --- 13:35:18.895255 +++ killed by SIGPIPE +++ On 2017-07-09 09:33:28, SREZIC wrote: Show quoted text
> Auf einem CentOS6-System: > > $ /opt/perl-5.22.3/bin/prove -v -Ilib t/bin/Prty/Ipc.t > t/bin/Prty/Ipc.t .. > 1..4 > ok 1 - use Prty::Ipc; > ok 2 > Failed 2/4 subtests > > Test Summary Report > ------------------- > t/bin/Prty/Ipc.t (Wstat: 13 Tests: 2 Failed: 0) > Non-zero wait status: 13 > Parse errors: Bad plan. You planned 4 tests but ran 2. > Files=1, Tests=2, 0 wallclock secs ( 0.02 usr 0.01 sys + 0.08 cusr > 0.04 csys = 0.15 CPU) > Result: FAIL > > Signal 13 ist SIGPIPE. > > Dummerweise ist es ein Heisenbug: sobald ich versuche, mit strace > reinzuschauen, läuft der Test erfolgreich durch. > > Vermutlich ein Timing-Problem; eventuell läuft das externe Kommando zu > langsam oder zu schnell. > > On 2017-07-09 07:20:01, fs@fseitz.de wrote:
> > Hallo Slaven, > > > > kannst du mir von einem dieser Systeme die Ausgabe > > des folgenden Kommandos senden? > > > > $ prove -v -Ilib t/bin/Prty/Ipc.t > > > > Grüße > > Frank > > > > On 07/09/2017 10:46 AM, Slaven_Rezic via RT wrote:
> > > Sun Jul 09 04:46:06 2017: Request 122402 was acted upon. > > > Transaction: Ticket created by SREZIC > > > Queue: Prty > > > Subject: Ipc.t fails on some systems without diagnostics > > > Broken in: 1.115 > > > Severity: (no value) > > > Owner: Nobody > > > Requestors: SREZIC@cpan.org > > > Status: new > > > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402 > > > > > > > > > > On some of my smoker systems (centos6, debian jessie, freebsd) I > > > see > > > the following failure, without any further diagnostics: > > > > > > ... > > > t/bin/Prty/Ipc.t ................................ > > > Failed 2/4 subtests > > > ...
Man kann das Problem mit diesem diff nachstellen: diff --git a/lib/Prty/Ipc.pm b/lib/Prty/Ipc.pm index c0501c5..364a29b 100644 --- a/lib/Prty/Ipc.pm +++ b/lib/Prty/Ipc.pm @@ -76,6 +76,8 @@ sub filter { ); } + sleep 1; + if (defined $in) { print W $in; } Damit kann man zusichern, dass sich das externe Kommando schneller beendet als "print W ..." ausgeführt wird. Und in diesem Fall kommt es zum SIGPIPE, weil der print-Befehl "ins Leere" läuft. On 2017-07-09 09:36:47, SREZIC wrote: Show quoted text
> Mit strace bekommt man einen Fehler nur, wenn man -f weglässt. Damit > sieht man leider nicht, was in den Kindprozessen passiert, aber > immerhin. Die letzten Zeilen: > > ... > > 13:35:18.882051 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000009> > 13:35:18.882080 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000022> > 13:35:18.882140 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 > <0.000009> > 13:35:18.882181 clone(child_stack=0, > flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, > child_tidptr=0x7f06386a49d0) = 13563 <0.003322> > 13:35:18.885560 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 > <0.000010> > 13:35:18.885632 close(14) = 0 <0.000010> > 13:35:18.885720 read(13, "", 8192) = 0 <0.001494> > 13:35:18.887310 close(13) = 0 <0.000014> > 13:35:18.887393 close(3) = 0 <0.000010> > 13:35:18.887445 close(10) = 0 <0.000010> > 13:35:18.887499 close(12) = 0 <0.000010> > 13:35:18.887627 write(4, "Ein Test", 8) = 8 <0.000025> > 13:35:18.887675 close(4) = 0 <0.000010> > 13:35:18.887707 fstat(9, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 > <0.000010> > 13:35:18.887741 read(9, "Ein Test", 8192) = 8 <0.000129> > 13:35:18.887892 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, > si_pid=13563, si_status=0, si_utime=0, si_stime=0} --- > 13:35:18.887912 read(9, "", 8192) = 0 <0.000010> > 13:35:18.887941 close(9) = 0 <0.000011> > 13:35:18.887976 fstat(11, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 > <0.000010> > 13:35:18.888009 read(11, "", 8192) = 0 <0.000010> > 13:35:18.888041 close(11) = 0 <0.000010> > 13:35:18.888080 wait4(13563, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], > 0, NULL) = 13563 <0.000013> > 13:35:18.888576 write(5, "ok 2\n", 5) = 5 <0.000014> > 13:35:18.888756 pipe([3, 4]) = 0 <0.000013> > 13:35:18.888799 ioctl(3, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000010> > 13:35:18.888830 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000010> > 13:35:18.888859 ioctl(4, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000010> > 13:35:18.888888 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000010> > 13:35:18.888915 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000010> > 13:35:18.888943 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000010> > 13:35:18.888977 pipe([9, 10]) = 0 <0.000012> > 13:35:18.889009 ioctl(9, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000010> > 13:35:18.889038 lseek(9, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000009> > 13:35:18.889067 ioctl(10, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000009> > 13:35:18.889095 lseek(10, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000010> > 13:35:18.889122 fcntl(9, F_SETFD, FD_CLOEXEC) = 0 <0.000009> > 13:35:18.889149 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 <0.000009> > 13:35:18.889182 pipe([11, 12]) = 0 <0.000011> > 13:35:18.889214 ioctl(11, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000009> > 13:35:18.889242 lseek(11, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000010> > 13:35:18.889270 ioctl(12, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000009> > 13:35:18.889298 lseek(12, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000009> > 13:35:18.889325 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 <0.000010> > 13:35:18.889351 fcntl(12, F_SETFD, FD_CLOEXEC) = 0 <0.000009> > 13:35:18.889382 pipe([13, 14]) = 0 <0.000011> > 13:35:18.889412 ioctl(13, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000010> > 13:35:18.889440 lseek(13, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000009> > 13:35:18.889468 ioctl(14, SNDCTL_TMR_TIMEBASE or > SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL > (Invalid argument) <0.000009> > 13:35:18.889496 lseek(14, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) > <0.000009> > 13:35:18.889523 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000010> > 13:35:18.889550 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000009> > 13:35:18.889589 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 > <0.000010> > 13:35:18.889623 clone(child_stack=0, > flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, > child_tidptr=0x7f06386a49d0) = 13564 <0.002480> > 13:35:18.892175 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 > <0.000011> > 13:35:18.892247 close(14) = 0 <0.000010> > 13:35:18.892358 read(13, "", 8192) = 0 <0.001207> > 13:35:18.893591 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, > si_pid=13564, si_status=1, si_utime=0, si_stime=0} --- > 13:35:18.893632 close(13) = 0 <0.000012> > 13:35:18.893707 close(3) = 0 <0.000011> > 13:35:18.893747 close(10) = 0 <0.000010> > 13:35:18.893788 close(12) = 0 <0.000011> > 13:35:18.893912 write(4, "Ein Test", 8) = -1 EPIPE (Broken pipe) > <0.000011> > 13:35:18.893959 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, > si_pid=13562, si_uid=1023} --- > 13:35:18.895255 +++ killed by SIGPIPE +++ > > > On 2017-07-09 09:33:28, SREZIC wrote:
> > Auf einem CentOS6-System: > > > > $ /opt/perl-5.22.3/bin/prove -v -Ilib t/bin/Prty/Ipc.t > > t/bin/Prty/Ipc.t .. > > 1..4 > > ok 1 - use Prty::Ipc; > > ok 2 > > Failed 2/4 subtests > > > > Test Summary Report > > ------------------- > > t/bin/Prty/Ipc.t (Wstat: 13 Tests: 2 Failed: 0) > > Non-zero wait status: 13 > > Parse errors: Bad plan. You planned 4 tests but ran 2. > > Files=1, Tests=2, 0 wallclock secs ( 0.02 usr 0.01 sys + 0.08 cusr > > 0.04 csys = 0.15 CPU) > > Result: FAIL > > > > Signal 13 ist SIGPIPE. > > > > Dummerweise ist es ein Heisenbug: sobald ich versuche, mit strace > > reinzuschauen, läuft der Test erfolgreich durch. > > > > Vermutlich ein Timing-Problem; eventuell läuft das externe Kommando > > zu > > langsam oder zu schnell. > > > > On 2017-07-09 07:20:01, fs@fseitz.de wrote:
> > > Hallo Slaven, > > > > > > kannst du mir von einem dieser Systeme die Ausgabe > > > des folgenden Kommandos senden? > > > > > > $ prove -v -Ilib t/bin/Prty/Ipc.t > > > > > > Grüße > > > Frank > > > > > > On 07/09/2017 10:46 AM, Slaven_Rezic via RT wrote:
> > > > Sun Jul 09 04:46:06 2017: Request 122402 was acted upon. > > > > Transaction: Ticket created by SREZIC > > > > Queue: Prty > > > > Subject: Ipc.t fails on some systems without diagnostics > > > > Broken in: 1.115 > > > > Severity: (no value) > > > > Owner: Nobody > > > > Requestors: SREZIC@cpan.org > > > > Status: new > > > > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402
> > > > >
> > > > > > > > > > > > On some of my smoker systems (centos6, debian jessie, freebsd) I > > > > see > > > > the following failure, without any further diagnostics: > > > > > > > > ... > > > > t/bin/Prty/Ipc.t ................................ > > > > Failed 2/4 subtests > > > > ...
Subject: Re: [rt.cpan.org #122402] Ipc.t fails on some systems without diagnostics
Date: Sun, 9 Jul 2017 17:41:23 +0200
To: bug-Prty [...] rt.cpan.org
From: Frank Seitz <fs [...] fseitz.de>
Hallo Slaven, verstehe. Das Problem kann ich im Testcode dadurch lösen, dass ich beim zweiten Testfall (Aufruf von false) keine Daten mitgebe. Daten mitzugeben ist an der Stelle eigentlich unsinnig, da false nichts von stdin liest. Bei dem Test geht es ansich nur um den Exitcode. Vielen Dank für die genaue Analyse! Grüße Frank On 07/09/2017 03:48 PM, Slaven_Rezic via RT wrote: Show quoted text
> Queue: Prty > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402 > > > Man kann das Problem mit diesem diff nachstellen: > > diff --git a/lib/Prty/Ipc.pm b/lib/Prty/Ipc.pm > index c0501c5..364a29b 100644 > --- a/lib/Prty/Ipc.pm > +++ b/lib/Prty/Ipc.pm > @@ -76,6 +76,8 @@ sub filter { > ); > } > > + sleep 1; > + > if (defined $in) { > print W $in; > } > > > Damit kann man zusichern, dass sich das externe Kommando schneller beendet als "print W ..." ausgeführt wird. Und in diesem Fall kommt es zum SIGPIPE, weil der print-Befehl "ins Leere" läuft. > > On 2017-07-09 09:36:47, SREZIC wrote:
>> Mit strace bekommt man einen Fehler nur, wenn man -f weglässt. Damit >> sieht man leider nicht, was in den Kindprozessen passiert, aber >> immerhin. Die letzten Zeilen: >> >> ... >> >> 13:35:18.882051 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000009> >> 13:35:18.882080 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000022> >> 13:35:18.882140 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 >> <0.000009> >> 13:35:18.882181 clone(child_stack=0, >> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, >> child_tidptr=0x7f06386a49d0) = 13563 <0.003322> >> 13:35:18.885560 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 >> <0.000010> >> 13:35:18.885632 close(14) = 0 <0.000010> >> 13:35:18.885720 read(13, "", 8192) = 0 <0.001494> >> 13:35:18.887310 close(13) = 0 <0.000014> >> 13:35:18.887393 close(3) = 0 <0.000010> >> 13:35:18.887445 close(10) = 0 <0.000010> >> 13:35:18.887499 close(12) = 0 <0.000010> >> 13:35:18.887627 write(4, "Ein Test", 8) = 8 <0.000025> >> 13:35:18.887675 close(4) = 0 <0.000010> >> 13:35:18.887707 fstat(9, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 >> <0.000010> >> 13:35:18.887741 read(9, "Ein Test", 8192) = 8 <0.000129> >> 13:35:18.887892 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, >> si_pid=13563, si_status=0, si_utime=0, si_stime=0} --- >> 13:35:18.887912 read(9, "", 8192) = 0 <0.000010> >> 13:35:18.887941 close(9) = 0 <0.000011> >> 13:35:18.887976 fstat(11, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 >> <0.000010> >> 13:35:18.888009 read(11, "", 8192) = 0 <0.000010> >> 13:35:18.888041 close(11) = 0 <0.000010> >> 13:35:18.888080 wait4(13563, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], >> 0, NULL) = 13563 <0.000013> >> 13:35:18.888576 write(5, "ok 2\n", 5) = 5 <0.000014> >> 13:35:18.888756 pipe([3, 4]) = 0 <0.000013> >> 13:35:18.888799 ioctl(3, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000010> >> 13:35:18.888830 lseek(3, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000010> >> 13:35:18.888859 ioctl(4, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000010> >> 13:35:18.888888 lseek(4, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000010> >> 13:35:18.888915 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000010> >> 13:35:18.888943 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000010> >> 13:35:18.888977 pipe([9, 10]) = 0 <0.000012> >> 13:35:18.889009 ioctl(9, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000010> >> 13:35:18.889038 lseek(9, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000009> >> 13:35:18.889067 ioctl(10, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000009> >> 13:35:18.889095 lseek(10, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000010> >> 13:35:18.889122 fcntl(9, F_SETFD, FD_CLOEXEC) = 0 <0.000009> >> 13:35:18.889149 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 <0.000009> >> 13:35:18.889182 pipe([11, 12]) = 0 <0.000011> >> 13:35:18.889214 ioctl(11, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000009> >> 13:35:18.889242 lseek(11, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000010> >> 13:35:18.889270 ioctl(12, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000009> >> 13:35:18.889298 lseek(12, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000009> >> 13:35:18.889325 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 <0.000010> >> 13:35:18.889351 fcntl(12, F_SETFD, FD_CLOEXEC) = 0 <0.000009> >> 13:35:18.889382 pipe([13, 14]) = 0 <0.000011> >> 13:35:18.889412 ioctl(13, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000010> >> 13:35:18.889440 lseek(13, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000009> >> 13:35:18.889468 ioctl(14, SNDCTL_TMR_TIMEBASE or >> SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff77036860) = -1 EINVAL >> (Invalid argument) <0.000009> >> 13:35:18.889496 lseek(14, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek) >> <0.000009> >> 13:35:18.889523 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 <0.000010> >> 13:35:18.889550 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000009> >> 13:35:18.889589 rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 >> <0.000010> >> 13:35:18.889623 clone(child_stack=0, >> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, >> child_tidptr=0x7f06386a49d0) = 13564 <0.002480> >> 13:35:18.892175 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 >> <0.000011> >> 13:35:18.892247 close(14) = 0 <0.000010> >> 13:35:18.892358 read(13, "", 8192) = 0 <0.001207> >> 13:35:18.893591 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, >> si_pid=13564, si_status=1, si_utime=0, si_stime=0} --- >> 13:35:18.893632 close(13) = 0 <0.000012> >> 13:35:18.893707 close(3) = 0 <0.000011> >> 13:35:18.893747 close(10) = 0 <0.000010> >> 13:35:18.893788 close(12) = 0 <0.000011> >> 13:35:18.893912 write(4, "Ein Test", 8) = -1 EPIPE (Broken pipe) >> <0.000011> >> 13:35:18.893959 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, >> si_pid=13562, si_uid=1023} --- >> 13:35:18.895255 +++ killed by SIGPIPE +++ >> >> >> On 2017-07-09 09:33:28, SREZIC wrote:
>>> Auf einem CentOS6-System: >>> >>> $ /opt/perl-5.22.3/bin/prove -v -Ilib t/bin/Prty/Ipc.t >>> t/bin/Prty/Ipc.t .. >>> 1..4 >>> ok 1 - use Prty::Ipc; >>> ok 2 >>> Failed 2/4 subtests >>> >>> Test Summary Report >>> ------------------- >>> t/bin/Prty/Ipc.t (Wstat: 13 Tests: 2 Failed: 0) >>> Non-zero wait status: 13 >>> Parse errors: Bad plan. You planned 4 tests but ran 2. >>> Files=1, Tests=2, 0 wallclock secs ( 0.02 usr 0.01 sys + 0.08 cusr >>> 0.04 csys = 0.15 CPU) >>> Result: FAIL >>> >>> Signal 13 ist SIGPIPE. >>> >>> Dummerweise ist es ein Heisenbug: sobald ich versuche, mit strace >>> reinzuschauen, läuft der Test erfolgreich durch. >>> >>> Vermutlich ein Timing-Problem; eventuell läuft das externe Kommando >>> zu >>> langsam oder zu schnell. >>> >>> On 2017-07-09 07:20:01, fs@fseitz.de wrote:
>>>> Hallo Slaven, >>>> >>>> kannst du mir von einem dieser Systeme die Ausgabe >>>> des folgenden Kommandos senden? >>>> >>>> $ prove -v -Ilib t/bin/Prty/Ipc.t >>>> >>>> Grüße >>>> Frank >>>> >>>> On 07/09/2017 10:46 AM, Slaven_Rezic via RT wrote:
>>>>> Sun Jul 09 04:46:06 2017: Request 122402 was acted upon. >>>>> Transaction: Ticket created by SREZIC >>>>> Queue: Prty >>>>> Subject: Ipc.t fails on some systems without diagnostics >>>>> Broken in: 1.115 >>>>> Severity: (no value) >>>>> Owner: Nobody >>>>> Requestors: SREZIC@cpan.org >>>>> Status: new >>>>> Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122402 >>>>> >>>>> On some of my smoker systems (centos6, debian jessie, freebsd) I >>>>> see >>>>> the following failure, without any further diagnostics: >>>>> >>>>> ... >>>>> t/bin/Prty/Ipc.t ................................ >>>>> Failed 2/4 subtests >>>>> ...
-- Dipl.-Inform. Frank Seitz IT Consultant / {Web, Database, Linux} Developer Tel: +49-176-78243503, Hauptstr. 32-34, D-25462 Rellingen Blog: http://fseitz.de/blog