GNU bug report logs - #33946
tail -f stops abruptly in AIX when piped.

Previous Next

Full log

Message #52 received at 33946 <at> debbugs.gnu.org (full text, mbox):

From: Pádraig Brady <P <at> draigBrady.com>
To: Bernhard Voelker <mail <at> bernhard-voelker.de>, 33946 <at> debbugs.gnu.org
Subject: Re: bug#33946: tail -f stops abruptly in AIX when piped.
Date: Sun, 20 Jan 2019 01:00:27 -0800

[Message part 1 (text/plain, inline)]

On 17/01/19 06:25, Bernhard Voelker wrote:
> On 1/16/19 4:09 AM, Pádraig Brady wrote:
>> On 14/01/19 23:54, Bernhard Voelker wrote:
>>> On 1/13/19 4:31 AM, Pádraig Brady wrote:
>>>> Thanks for testing. Pushed at:
>>>> https://git.sv.gnu.org/gitweb/?p=coreutils.git;a=commitdiff;h=d5ab4cb
>>>
>>>> -timeout 10 tail -f $mode $fastpoll out | sleep .1 || fail=1
>>>> +(returns_ 124 timeout 10 tail -n2 -f $mode $fastpoll out && touch timed_out) |
>>>> + sed 2q > out2
>>>> +test -e timed_out && fail=1
>>>> +compare exp out2 || fail=1
>>>
>>> I see the 'timed_out' file when running the test on openSUSE's build service
>>> for Linux x86_64, and can reproduce when running that in the local 'osc' build
>>> environment (chroot-based).
>>>
>>> I'm not sure what's the problem though, but could this be related to
>>> how we fixed 'tests/misc/seq-epipe.sh' a while ago in v8.25-42-g383e4b2ce?
>>
>> I can't see the problem offhand.
> 
> I also still don't see the problem.  In the log, it's just:
> 
> + returns_ 124 timeout 10 tail -n2 -f ---disable-inotify -s.1 --max-unchanged-stats=1 out
> + sed 2q
> + touch timed_out
> + test -e timed_out
> + fail=1
> 
> Well, under strace:
> 
> In the good case, i.e., without chroot, the process terminates upon the first
> SIGPIPE received:
> 
>   ...
>   inotify_init()                          = 4
>   write(1, "==> standard input <==\nar\n", 26) = 26
>   inotify_add_watch(4, "out", IN_MODIFY)  = 1
>   stat("out", {st_dev=makedev(0x8, 0x20), st_ino=298091, st_mode=S_IFREG|0644, st_nlink=1, st_uid=717, st_gid=1000, ...}) = 0
>   fstat(3, {st_dev=makedev(0x8, 0x20), st_ino=298091, st_mode=S_IFREG|0644, st_nlink=1, st_uid=717, st_gid=1000, ...}) = 0
>   select(5, [1 4], NULL, NULL, NULL)      = 1 (in [1])
>   rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
>   getpid()                                = 29422
>   gettid()                                = 29422
>   tgkill(29422, 29422, SIGPIPE)           = 0
>   rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
>   --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=29422, si_uid=717} ---
>   +++ killed by SIGPIPE +++
> 
> In the bad case, i.e., in the chroot'ed "osc build" environment or on 'build.opensuse.org',
> I see:
> 
>   ...
>   inotify_init()                          = 4
>   write(1, "==> standard input <==\nar\n", 26) = 26
>   inotify_add_watch(4, "out", IN_MODIFY)  = 1
>   stat("out", {st_dev=makedev(0x8, 0x1), st_ino=192286, st_mode=S_IFREG|0644, st_nlink=1, st_uid=399, st_gid=399, ...}) = 0
>   fstat(3, {st_dev=makedev(0x8, 0x1), st_ino=192286, st_mode=S_IFREG|0644, st_nlink=1, st_uid=399, st_gid=399, ...}) = 0
>   select(5, [1 4], NULL, NULL, NULL)      = 1 (in [1])
>   rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
>   getpid()                                = 29191
>   gettid()                                = 29191
>   tgkill(29191, 29191, SIGPIPE)           = 0
>   rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
>   --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=29191, si_uid=399} ---
>   select(5, [1 4], NULL, NULL, NULL)      = 1 (in [1])
>   rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
>   getpid()                                = 29191
>   gettid()                                = 29191
>   tgkill(29191, 29191, SIGPIPE)           = 0
>   rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
>   --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=29191, si_uid=399} ---
>   select(5, [1 4], NULL, NULL, NULL)      = 1 (in [1])
>   rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
>   getpid()                                = 29191
>   gettid()                                = 29191
>   tgkill(29191, 29191, SIGPIPE)           = 0
>   rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
>   --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=29191, si_uid=399} ---
>   [... a.s.o ...]
> 
> and finally gets killed by 'timeout 10':
> 
>   ...
>   --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_TKILL, si_pid=29191, si_uid=399} ---
>   --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=29187, si_uid=399} ---
>   +++ killed by SIGTERM +++
> 
> Any idea?

Right. So the broken pipe is detected fine which is the main thing.
It's just that the osc system has SIGPIPE ignored
(python2 based systems do this by default, which may be related).

I was looking are setting normal handling with `trap - SIGPIPE` in the test,
but that's only effective if ignored in the same shell.
If the parent/login shell has ignored SIGPIPE,
then resetting it is ineffective.
However...

tail should be exiting irrespective of the handling of SIGPIPE.
In fact it goes into an infinite loop in the edge case of:
inotify + ignored sigpipe + early exit filters.

The attached ensures the tail process exits,
which handles the infinite loop and the test failure.

cheers,
Pádraig.

[tail-pipe-hang.patch (text/x-patch, attachment)]

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.