why does exec+tee output display out-of-order?

Question

This is basically an addendum to this question: redirect COPY of stdout to log file from within bash script itself

So using this test script:

#!/bin/bash

echo 'bash version:'
bash --version|grep release
echo '';
echo '----------------'
rm /tmp/logfile 2>/dev/null;

function testCommands() {
    local mode="$1"
    echo "testCommands(): mode == $mode";

    # Link file descriptor #6 with stdout to save stdout, #7 for stderr
    exec 6>&1;
    exec 7>&2;

    if [[ 'both' == "${mode}" ]]; then
        # log to file and stdout
        exec > >(tee -ia /tmp/logfile);

    elif [[ 'file' == "${mode}" ]]; then
        # log to file only
        exec 1>> /tmp/logfile

    elif [[ 'quiet' == "${mode}" ]]; then
        # be quiet
        exec 1> /dev/null

    #else - use normal stdout
    fi
    if [[ 'true' != "${separate_stderr}" ]]; then
        #by default, merge stderr to stdout for simple logging
        exec 2>&1
    #else - keep stderr separate like it normally is
    fi

    echo "fee";
    echo "fye";
    echo "foh";
    echo "fum";

    # Restore stdout/stderr and close file descriptors #6/#7
    exec 1>&6 6>&-;
    exec 2>&7 7>&-;
}

testCommands 'file'
echo '----------------'
echo ''
echo 'check /tmp/logfile'
ls -acl /tmp/logfile
echo ''
echo 'check output'
cat /tmp/logfile
rm /tmp/logfile 2>/dev/null;
echo '----------------'
testCommands 'stdout'
echo '----------------'
echo ''
echo 'check /tmp/logfile'
ls -acl /tmp/logfile
echo ''
echo 'check output'
cat /tmp/logfile
rm /tmp/logfile 2>/dev/null;
echo '----------------'
testCommands 'both'
echo '----------------'
echo ''
echo 'check /tmp/logfile'
ls -acl /tmp/logfile
echo ''
echo 'check output'
cat /tmp/logfile
rm /tmp/logfile 2>/dev/null;
echo '----------------'
testCommands 'quiet'
echo '----------------'
echo ''
echo 'check /tmp/logfile'
ls -acl /tmp/logfile
echo ''
echo 'check output'
cat /tmp/logfile
echo '----------------'

I get the following output:

bash version:
GNU bash, version 4.4.20(1)-release (x86_64-pc-linux-gnu)

----------------
testCommands(): mode == file
----------------

check /tmp/logfile
-rw-rw---- 1 testuser testuser 16 Sep 20 16:10 /tmp/logfile

check output
fee
fye
foh
fum
----------------
testCommands(): mode == stdout
fee
fye
foh
fum
----------------

check /tmp/logfile
ls: cannot access '/tmp/logfile': No such file or directory

check output
cat: /tmp/logfile: No such file or directory
----------------
testCommands(): mode == both
----------------

check /tmp/logfile
fee
fye
foh
fum
-rw-rw---- 1 testuser testuser 16 Sep 20 16:10 /tmp/logfile

check output
fee
fye
foh
fum
----------------
testCommands(): mode == quiet
----------------

check /tmp/logfile
ls: cannot access '/tmp/logfile': No such file or directory

check output
cat: /tmp/logfile: No such file or directory
----------------

There is a fair bit of output here, so if you didn't see it the first time through, then part that looks weird is in the section testCommands(): mode == both.

What I would expect to see here is that all output from function would display first, then output from echo/ls/cat that is defined after the call. Instead function output displays between output from 2 commands that should be running after the function has completed. In other words, here is what I expect should happen (note: the below is not actual output - I made it up):

----------------
testCommands(): mode == both
fee
fye
foh
fum
----------------

check /tmp/logfile
-rw-rw---- 1 testuser testuser 16 Sep 20 16:10 /tmp/logfile

check output
fee
fye
foh
fum

I am running this from Linux Mint v19.2 x64 Cinnamon (based off Ubuntu 18.04) on my home computer. Was looking to adapt the exec answer from the other post to a shared functions.sh script that I plan to call from various other other bash shell scripts, my .bash_aliases, etc. I have some scenarios where I would like to call the same function in various scenarios which have different logging requirements: file + stdout, file only, stdout only, and silent. I prefer to stderr into stdout for all my scenarios.

1) Calling testCommands 'both', I see output from after the function displayed before output from the function itself. Curious if there is any way to confirm this is really due to buffering in tee, due to something else entirely, or some combination.

2) Is there any way to fix this from bash other than using the 'unbuffered version of tee' referenced in the other question? e.g. even if it is buffering, could I disable or even force printing buffered output before function ends via bash/other posix commands? I would prefer to avoid external dependencies but can't see myself switching to any distros that don't use bash as the default shell.

3) Is there a more elegant/flexible/easier-to-maintain way to go about controlling output when using bash? (e.g. managing the various permutations of display/hide the stdout/stderr output for console/logfile)

score 1 · Accepted Answer · answered Sep 20 '19 at 23:15

Here's an easier way to reproduce your issue:

echo "Hello" > >(tee -a file)
echo "World" >> file

The file will contain "World Hello" instead of "Hello World".

This does not happen because tee buffers (it doesn't), but because you have made writes a two stage process, and the shell only waits for the first one.

When you go via a process substitution, you are writing to a pipe, and echo will only wait until the data has been successfully written to the pipe. It won't make it into the file until tee gets a chance to write it later. If the script continues to cause writes to the file before tee can run, output appears out of order.

If you at any time want to "flush" the output, you'll have to close the pipe and wait for the process substitution to exit:

mkfifo tmpfile
exec > >(echo "$BASHPID" > tmpfile; exec tee -a file)
echo "Hello"
exec >&-
wait "$(<tmpfile)"
echo "World" >> file

So really it's easier to just ensure that all data takes the same path, e.g. by ensuring that all writes happen through the same process substitution.

score 0 · Answer 2 · answered Sep 20 '19 at 22:14

Because command is buffering the IO. If you disable IO buffering you will get the results you want. You can the stdbuf or unbuffer command which will disable buffering.

stdbuf -oL command   # This will buffer one line at time
unbuffer command

And if you system don't have one of these commands try script which is an older and should be on most distributions.

script -q /dev/null long_running_command

why does exec+tee output display out-of-order?

2 Answers2