Last active
January 23, 2019 23:42
-
-
Save blurayne/c6831adb0305fbd185e459007ef31b09 to your computer and use it in GitHub Desktop.
Prevent stderr written before stdout
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
#!/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 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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 |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment