2016-01-06
A fun Bash buffering bug (apparently on Linux only)
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
EXIT
trap, 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/echo
and 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\n
and thenfinal\n
from 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/echo
because we're using the Bash builtinecho
instead.) - 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
.