Skip to content

Instantly share code, notes, and snippets.

@blurayne blurayne/01-logging.sh
Last active Jan 23, 2019

Embed
What would you like to do?
Prevent stderr written before stdout
#!/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
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
You can’t perform that action at this time.