Looking for explanation of shell redirection inter

Question

Given the following script (t.sh):

#!/bin/bash

if [ $# -eq 0 ]; then
    log() {
        {
            if [ $# -gt 0 ]; then
                printf -- %s\\n "$*"
            else
                cat
            fi
        } | tee -a logged.out
    }
else
    log() {
        if [ $# -gt 0 ]; then
            printf -- %s\\n "$*"
        else
            cat
        fi
    } > >(tee -a logged.out)
fi

declare -xf log

: > logged.out

./t2.sh 2>&1 | tee verbose.out

where t2.sh is:

#!/bin/bash

echo outone
echo errone >&2

echo logged pipe | log

echo outtwo
echo errtwo >&2

log logged message

echo outthree
echo errthree >&2

I'm failing to understand the difference in the output between the two versions of the log function.

The default (first) function does what I want in that it correctly interleaves stdout, stderr, and the log function output in the verbose.out file while sending the logged output to logged.out.

The second function however, does not correctly interleave the logged output with the stdout and stderr output and instead seems to buffer the logged output and it therefor ends up at the end of the verbose.out file (though this output ordering is not even consistent and the logged messages occasionally occur in the inverse order in the output and the first of the messages can appear earlier in the output somewhere).

Correct operation:

$ ./t.sh; more {logged,verbose}.out | cat
outone
errone
logged pipe
outtwo
errtwo
logged message
outthree
errthree
::::::::::::::
logged.out
::::::::::::::
logged pipe
logged message
::::::::::::::
verbose.out
::::::::::::::
outone
errone
logged pipe
outtwo
errtwo
logged message
outthree
errthree

Incorrect operation:

$ ./t.sh broken; more {logged,verbose}.out | cat
outone
errone
outtwo
errtwo
outthree
errthree
logged message
logged pipe
::::::::::::::
logged.out
::::::::::::::
logged message
logged pipe
::::::::::::::
verbose.out
::::::::::::::
outone
errone
outtwo
errtwo
outthree
errthree
logged message
logged pipe

I'm sure there is a reason for this behaviour I just don't know what it is. Would someone be able to enlighten me?

Answer 1

Here's a simpler test case. Why does

echo foo | cat
echo bar

print foo followed by bar, while

echo foo > >(cat)
echo bar

prints them in reverse order with bar first?

This is because for a pipe, bash waits for all stages in the pipeline to finish. For process substitution, the process is simply forked off and not waited on.

This means that there's a race condition on whether the process substitution command can start, read and process what's being written to it before the next statements execute, and in your case it's losing.

You can see this effect more clearly with a simple experiment:

echo foo  |  sleep 10    # Waits 10 seconds
echo foo > >(sleep 10)   # Finishes immediately