Re: Strange behaviour on 'read' from a pipe

[Lluís Batlle i Rossell]

On Sun, Apr 01, 2012 at 06:27:46PM -0400, Chet Ramey wrote:
> On 4/1/12 1:02 PM, Lluís Batlle i Rossell wrote:
> > On Sun, Apr 01, 2012 at 11:06:22AM -0400, Chet Ramey wrote:
> >> On 4/1/12 5:53 AM, Andreas Schwab wrote:
> >>
> >>>> It looks like a simple race condition.  I suspect that the scheduler
> >>>> arranges things so that the child process ends up exiting between the
> >>>> open and the read, but I don't have any real evidence to back it up.
> >>>
> >>> Note that the opening of the pipe as part of the redirection in the
> >>> parent blocks until there is a writer, ie. until the child opens the
> >>> pipe.  Can this open call return EINTR?
> >>
> >> open() is supposed to return EINTR only if interrupted by a signal.  The
> >> only signal I can see occurring is SIGCHLD, and bash installs the SIGCHLD
> >> handler with SA_RESTART.
> > 
> > Then, any idea of what can be happening?
> 
> It looks like a race condition, like I said.  I can't reproduce it on my
> system, so I don't have anything to troubleshoot.

Running "strace ./script" says these next. Notice it hangs at open(). If I use
"strace -f" to follow the child, all works.

OTH, I tried in another computer with the same bash+libc (hashes compared), and
it worked there. But in the problematic computer (linux 3.2.11 x86_64) also
other bash/libc versions hanged.

...
read(255, "\nfunction spawn {\n    \"$@\"\n    e"..., 281) = 201
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
lseek(255, -113, SEEK_CUR)              = 168
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7fd40fbbc9d0) = 29446
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
read(255, "\nwhile true; do\n    echo reading"..., 281) = 113
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
brk(0x21b2000)                          = 0x21b2000
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(1, "reading\n", 8reading
)                = 8
open("/tmp/pipe", O_RDONLYdebug:done
)             = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=29446, si_status=0,
si_utime=0, si_stime=0} (Child exited) ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 29446
wait4(-1, 0x7fff2c3c0798, WNOHANG, NULL) = -1 ECHILD (No child processes)
rt_sigreturn(0xffffffffffffffff)        = 2
open("/tmp/pipe", O_RDONLY