I'll present this in the traditional illustrated form:
$ cat repro
#!/bin/bash
function cleanup() {
r1=$(/bin/echo one)
r2=$(echo two)
#echo $r1 '!' $r2 >>/tmp/logfile
echo $r1 '!' $r2 1>&2
}
trap cleanup EXIT
sleep 1
echo final
$ ./repro | false
final
one final ! final two
$
Wait, what? This should print merely '
one ! two
'. The '
echo
final
' should be written to stdout, which is a pipe to
false
(and anyways, it's closed by the time the
echo
runs, since
false
will already have exited by the time '
sleep 1
' finishes). Then the
cleanup
function should run on termination, with
$r1
winding up being
"one"
and
$r2
winding up being
"two"
from the command substitutions, and they should then get echoed out to standard error as '
one ! two
'.
(Indeed you can get exactly this output with a command line like '
./repro >/dev/null
'.)
What is actually happening here (or at least appears to be happening) is an interaction between IO buffering, our old friend
SIGPIPE
, and forking children while you have unclean state. Based on
strace
, the sequence of events is:
- Bash gets to '
echo final' and attempts to write it to the now-closed standard output pipe by calling 'write(1, "final\n", 6)'. This gets an immediateSIGPIPE. - Since we've set a general
EXITtrap, bash immediately runs our cleanup function (since the script is now exiting due to theSIGPIPE). - Bash forks to run the
$(/bin/echo one)command substitution. In the child, it runs/bin/echoand then, just before the child exits, does a 'write(1, "final\n", 6)'. This succeeds, since the child's stdout is connected to the parent's pipe. In the main bash process, it reads backone\nand thenfinal\nfrom the child process, and turns this into"one final"as the value assigned to$r1. - For '
$(echo two)', the child process just winds up callingwrite(1, "final\ntwo\n", 10). This becomes"final two"for$r2's value.(This child doesn't fork to run
/bin/echobecause we're using the Bash builtinechoinstead.) - At last, the main process temporarily duplicates standard error to standard output and calls '
write(1, ....)' to produce all of the output we see here.
What appears to be going on is that when the initial '
echo final
' in the main Bash process was interrupted by a
SIGPIPE
, it left
"final\n"
in stdout's IO buffer as unflushed output. When Bash forked for each $(...) command substitution, the child inherited this unflushed buffer. In the
$r1
case, the child noticed this unflushed buffer as it was exiting and wrote it out at that point; in the
$r2
case, the child appended the output of its builtin
echo
command to the unflushed stdout buffer and then wrote the whole thing out. Then, finally, when the parent ran the
echo
at the end of
cleanup()
, it too appended its
echo
output to the stdout buffer and wrote everything out.
There are two Bash bugs here. First, the output from the initial failed '
echo final
' should have been discarded from stdout's IO buffer, not retained to show up later on. Second, the children forked for each $(...) should not have inherited this unflushed IO buffer, because allowing unflushed buffers to make it into children is a well known recipe for having exactly this sort of multiple-flush happen.
(Well, allowing any unflushed or un-cleaned-up resource into children will do this, at least if your children are allowed to then notice it and attempt to clean it up.)
I don't know why this bug seems to be Linux specific. Perhaps Bash is using stdio, and Linux's stdio is the only version that behaves this way (either on the initial write that gets
SIGPIPE
, or in allowing the unflushed buffer state to propagate into forked children). If this is Linux stdio at work, I don't know if the semantics are legal according to POSIX/SUS and in a way it doesn't matter, as stdio libraries with this behavior are on a lot of deployed machines so your code had better be prepared for it.
(Regardless of what POSIX and SUS say, in practice 'standard' Unix is mostly defined this way. Code that you want to be portable has to cope with existing realities, however non-compliant they may be.)
By the way, finding this Bash issue from the initial, rather drastic symptoms that manifested in a complex environment was what they call a lot of fun (and it was Didier Spezia who did the vital work of identifying where the failure was; I just ground away from there).
PS: If you want to see some extra fun, switch which version of the final
echo
is run in
cleanup()
and then watch the main Bash process with
strace
.