bug#33946: tail -f stops abruptly in AIX when piped.

[Bernhard Voelker]

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?

Have a nice day,
Berny