Prevent stderr written before stdout

01-logging.sh

#!/bin/bash

##
# Logging of bash output and preventing stderr written before stdout 
# 
# If STDERR is not relvant to yout consider using `exec 1&>>(logger) 2>&1`  
#
# Culprit is Unix stdio buffering, as implemented on Linux by glibc which is a system library 
# that most programs implemented in C use to handle basic stuff (e.g., IO).
#
# The idea behind Unix buffering is to improve IO performance by batching together IO calls
# at the application level (AKA userland) and thus minimizing relatively expensive kernel 
# level read/write operations.
# 
# By default writes to stdout pass through a 4096 byte buffer, unless stdout happens to be
# a terminal/tty in which case it is line buffered.
# 
# The buffering can be switched of by `stdbuf -o 0 -e 0` or `unbuffer` from the expect-package.
#
# Additionaly when redirecting each stdout or stderr we have asynchronous processes.
# 
# Hence the inconsistency between the immediate output when your program is writing
# to the terminal and the delayed output when it is writing to a pipe or file.
#
# Test by `watch -n 1 bash logging.sh`
#
# This is now final solution bust mostly improves the handling of the problem
# SEE: https://www.turnkeylinux.org/blog/unix-buffering
#

pipe_logger() {
	while IFS= read -t 1 -r line; do
	    # try to be fast here (no subprocess spawning!) 
    	if [[ "${1:-ERR}" == "ERR" ]]; then
			builtin echo "[ERR] ${line}"; 
    	else
    		if ! [[ "${line}" =~ ^\[ERR ]]; then
				printf '[%(%F %T)T] '; 
    			builtin echo -n "[OUT] "
    			sync
    		else
    			printf '[%(%F %T)T] ';
    		fi
    		builtin echo "${line}";
    	fi
	done
}

pipe_init() {
    # Backup pipes
	exec 3>&1
	exec 4>&2

	# Register Shutdown (if needed)
	trap pipe_unregister EXIT INT TERM
	
	# 
	exec 1> >(pipe_logger OUT) 2> >(pipe_logger ERR)
	
	# Output to system logger 
	# - -p user.error` does not work here
	# exec 1> >(logger -s -i  -t "$USER notice $(basename $0)" )
	# exec 2> >(logger -s -i  -t "$USER error $(basename $0)")

	# How it almost should look (without ERR)
	# exec 1> >(pipe_logger OUT) 2>&1

	
	sync
}

pipe_unregister() {
	sync
	sleep 0.2

	exec 1>&3
	exec 2>&4
	# wait for fifo to finish

	sync
}

##
# Testing

echotest() {
	sleep 1
	for i in {1..10}; do echo $i; done;
	sleep 1
	for i in {1..10}; do echo $i; done;
}

echo "STDOUT" >&1
echo "ERROR"  >&2
echo "---"

pipe_init

echo "STDOUT" >&1
echo "ERROR"  >&2
# Ooutput with subprocesses
ls -1 /
# echotest
# without sync it could happen that output from previous command
# stills happens and STDERR from next command will be thrown in-between
# sync 
ls /pr0n

echo "---"

#pipe_unregister

echo "STDOUT" >&1
echo -e "ERROR\nERROR"  >&2
echo "---"
echo "a"
echo "b"
echo "c"
echo "---"
echo "Or do stuff like this" >&2

#set +x
# strap date DEBUG

02-example-output.txt

STDOUT
ERROR
---
[2019-01-24 00:40:03] [OUT] STDOUT <--- output not jumping anymore
[2019-01-24 00:40:03] [ERR] ERROR  <--- "
[2019-01-24 00:40:03] [OUT] bin
[2019-01-24 00:40:03] [OUT] boot
[2019-01-24 00:40:03] [OUT] cdrom
[2019-01-24 00:40:03] [OUT] cgroup
[2019-01-24 00:40:03] [OUT] data
[2019-01-24 00:40:03] [OUT] dev
[2019-01-24 00:40:03] [OUT] etc
[2019-01-24 00:40:03] [OUT] home
[2019-01-24 00:40:03] [OUT] host
[2019-01-24 00:40:03] [OUT] initrd.img
[2019-01-24 00:40:03] [OUT] initrd.img.old
[2019-01-24 00:40:03] [OUT] lib
[2019-01-24 00:40:03] [OUT] lib32
[2019-01-24 00:40:03] [OUT] lib64
[2019-01-24 00:40:03] [OUT] lost+found
[2019-01-24 00:40:03] [OUT] media
[2019-01-24 00:40:03] [OUT] mnt
[2019-01-24 00:40:03] [OUT] opt
[2019-01-24 00:40:03] [OUT] proc
[2019-01-24 00:40:03] [OUT] root
[2019-01-24 00:40:03] [OUT] run
[2019-01-24 00:40:03] [OUT] sbin
[2019-01-24 00:40:03] [OUT] snap
[2019-01-24 00:40:03] [OUT] srv
[2019-01-24 00:40:03] [OUT] sys
[2019-01-24 00:40:03] [OUT] tmp
[2019-01-24 00:40:03] [OUT] usr
[2019-01-24 00:40:03] [OUT] var
[2019-01-24 00:40:03] [OUT] vmlinuz
[2019-01-24 00:40:03] [OUT] vmlinuz.old
[2019-01-24 00:40:03] [ERR] ls: cannot access '/pr0n': No such file or directory <--- stays here and does not interfere with output of `ls /`
[2019-01-24 00:40:03] [OUT] ---
[2019-01-24 00:40:03] [OUT] STDOUT
[2019-01-24 00:40:03] [OUT] ---
[2019-01-24 00:40:03] [OUT] a
[2019-01-24 00:40:03] [OUT] b
[2019-01-24 00:40:03] [OUT] c
[2019-01-24 00:40:03] [OUT] ---
[2019-01-24 00:40:03] [ERR] ERROR <--- should come right after last STDOUT but at least is always after STDOUT
[2019-01-24 00:40:03] [ERR] ERROR <--- "
[2019-01-24 00:40:03] [ERR] Or do stuff like this