Re: strange behavior

[Vincent Lefevre <vincent@vinc17.net>]

On 2011-01-30 14:25:40 -0800, Bart Schaefer wrote:
> Possible epiphany:  zsh prints "zsh: exit 141" like that only if the
> exit status came from a builtin or shell function (Src/exec.c).  For
> all external commands or subshells it appends the jobtext after the
> status number (Src/jobs.c).  Those are the only PRINTEXITVALUE cases.
> 
> Thus the exit value of 141 must be coming from one of these places:
> 
> (1) "read" builtin in the inner loop of "filter"
> (2) "printf" in the ?* branch of the case in "filter"
> (3) "echo" in the { ... } expression

I can reproduce the SIGPIPE problem when resizing the terminal window
while the wrapper is being run. According to strace, it's (3).

> I can't imagine how "read" could return 141.
> 
> For the { echo } statement, I get "zsh: broken pipe" every way I try
> to make it fail, before zsh ever gets around to PRINTEXITVALUE.
> 
> That leaves "printf" ...
> 
> Which at first let me to wonder if what's happening is that the inner
> while loop is failing to consume the entire svnwrapper:term$'\012' in
> a single pass around the outer loop, e.g. that the -t option you're
> adding after reading the first character causes read to time out on
> some calls instead of reading the next character.  But that implies
> that the stderr of "filter" is getting closed somehow, and I can't
> think of a way that would happen.
> 
> So I'm still stuck. What we need is an "strace -ff -o ..." or the
> equivalent to tell which process is printing that, but tracing may
> resolve the race condition and prevent the error.

Here's the end of the strace output:

access("/home/vlefevre/bin/svnwrapper", F_OK) = 0
stat("/home/vlefevre/bin/svnwrapper", {st_mode=S_IFREG|0755, st_size=2027, ...}) = 0
open("/home/vlefevre/bin/svnwrapper", O_RDONLY|O_NOCTTY) = 3
fcntl(3, F_DUPFD, 10)                   = 11
close(3)                                = 0
fcntl(11, F_GETFL)                      = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat(11, {st_mode=S_IFREG|0755, st_size=2027, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffa4ad2c000
lseek(11, 0, SEEK_CUR)                  = 0
read(11, "#!/usr/bin/env zsh\n\n# svn wrappe"..., 4096) = 2027
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
pipe([3, 5])                            = 0
fcntl(3, F_DUPFD, 10)                   = 12
close(3)                                = 0
fcntl(5, F_DUPFD, 10)                   = 13
close(5)                                = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffa4ad399d0) = 19270
close(12)                               = 0
fcntl(2, F_DUPFD, 10)                   = 12
close(2)                                = 0
dup2(13, 2)                             = 2
close(13)                               = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
pipe([3, 5])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ffa4ad399d0) = 19271
close(5)                                = 0
read(3, "", 1)                          = 0
close(3)                                = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigsuspend([INT])                    = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
--- SIGWINCH (Window changed) @ 0 (0) ---
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [INT CHLD WINCH], 8) = 0
rt_sigprocmask(SIG_SETMASK, [INT CHLD WINCH], ~[KILL STOP RTMIN RT_1], 8) = 0
ioctl(10, TIOCGWINSZ, {ws_row=60, ws_col=85, ws_xpixel=523, ws_ypixel=784}) = 0
rt_sigreturn(0x1c)                      = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [INT CHLD], 8) = 0
rt_sigprocmask(SIG_SETMASK, [INT CHLD], ~[KILL STOP RTMIN RT_1], 8) = 0
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 19270
wait4(-1, 0x7ffff6dd97ec, WNOHANG|WSTOPPED|WCONTINUED, 0x7ffff6dd9740) = 0
rt_sigreturn(0xffffffff)                = -1 EINTR (Interrupted system call)
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigsuspend([INT])                    = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [INT CHLD], 8) = 0
rt_sigprocmask(SIG_SETMASK, [INT CHLD], ~[KILL STOP RTMIN RT_1], 8) = 0
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED|WCONTINUED, {ru_utime={0, 196012}, ru_stime={0, 204012}, ...}) = 19271
wait4(-1, 0x7ffff6dd97ec, WNOHANG|WSTOPPED|WCONTINUED, 0x7ffff6dd9740) = -1 ECHILD (No child processes)
rt_sigreturn(0xffffffff)                = -1 EINTR (Interrupted system call)
rt_sigprocmask(SIG_BLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [CHLD], [CHLD], 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
dup(2)                                  = 3
fcntl(1, F_DUPFD, 10)                   = 13
close(1)                                = 0
dup2(3, 1)                              = 1
close(3)                                = 0
write(1, "svnwrapper:term\n", 16)       = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
+++ killed by SIGPIPE +++

-- 
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / Arénaire project (LIP, ENS-Lyon)