== A fun Bash buffering bug (apparently on Linux only)

I'll present this in the traditional illustrated form:

.pn prewrap on

 $ 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_
../linux/BashPipes]], 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 immediate _SIGPIPE_.
# Since we've set a general _EXIT_ trap, bash immediately runs
  our cleanup function (since the script is now exiting due to
  the _SIGPIPE_).

# 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 back _one\n_ and then _final\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 calling
  _write(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 builtin _echo_ 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 https://github.com/golang/go/issues/13789]]
(and it was [[Didier Spezia https://github.com/dspezia]] 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_.