Bash redirect stdout and stderr to seperate files with timestamps

Question

Want to log all stdout and stderr to seperate files and add timestamp to each line.

Tried the following, which works but is missing timestamps.

#!/bin/bash

debug_file=./stdout.log
error_file=./stderr.log

exec > >(tee -a "$debug_file") 2> >(tee -a "$error_file")

echo "hello"
echo "hello world"

this-will-fail
and-so-will-this

Adding timestamps. (Only want timestamps prefixed to log output.)

#!/bin/bash

debug_file=./stdout.log
error_file=./stderr.log

log () {
  file=$1; shift 
  while read -r line; do
    printf '%(%s)T %s\n' -1 "$line"
  done >> "$file"
}

exec > >(tee >(log "$debug_file")) 2> >(tee >(log "$error_file"))

echo "hello"
echo "hello world"

this-will-fail
and-so-will-this

The latter adds timestamps to the logs but it also has the chance of messing up my terminal window. Reproducing this behavior was not straight forward, it only happend every now and then. I suspect it has to with the subroutine/buffer still having output flowing through it.

Examples of the script messing up my terminal.

# expected/desired behavior
user@system:~ ./log_test
hello
hello world
./log_test: line x: this-will-fail: command not found
./log_test: line x: and-so-will-this: command not found
user@system:~ # <-- cursor blinks here

# erroneous behavior
user@system:~ ./log_test
hello
hello world
user@system:~ ./log_test: line x: this-will-fail: command not found
./log_test: line x: and-so-will-this: command not found
# <-- cursor blinks here

# erroneous behavior
user@system:~ ./log_test
hello
hello world
./log_test: line x: this-will-fail: command not found
user@system:~
./log_test: line x: and-so-will-this: command not found
# <-- cursor blinks here

# erroneous behavior
user@system:~ ./log_test
hello
hello world
user@system:~
./log_test: line x: this-will-fail: command not found
./log_test: line x: and-so-will-this: command not found
# <-- cursor blinks here

For funs I put a sleep 2 at the end of the script to see what would happen and the problem never occurred again.

Hopefully someone knows the answer or can point me in the right derection.

Thanks

Edit

Judging from another question answered by Charles Duffy, what I'm trying to achieve is not really possible in bash. Separately redirecting and recombining stderr/stdout without losing ordering

Answer 1

The trick is to make sure that tee, and the process substitution running your log function, exits before the script as a whole does -- so that when the shell that started the script prints its prompt, there isn't any backgrounded process that might write more output after it's done.

As a working example (albeit one focused more on being explicit than terseness):

#!/usr/bin/env bash
stdout_log=stdout.log; stderr_log=stderr.log

log () {
  file=$1; shift
  while read -r line; do
    printf '%(%s)T %s\n' -1 "$line"
  done >> "$file"
}

# first, make backups of your original stdout and stderr
exec {stdout_orig_fd}>&1 {stderr_orig_fd}>&2
# for stdout: start your process substitution, record its PID, start tee, record *its* PID
exec {stdout_log_fd}> >(log "$stdout_log"); stdout_log_pid=$!
exec {stdout_tee_fd}> >(tee "/dev/fd/$stdout_log_fd"); stdout_tee_pid=$!
exec {stdout_log_fd}>&- # close stdout_log_fd so the log process can exit when tee does
# for stderr: likewise
exec {stderr_log_fd}> >(log "$stderr_log"); stderr_log_pid=$!
exec {stderr_tee_fd}> >(tee "/dev/fd/$stderr_log_fd" >&2); stderr_tee_pid=$!
exec {stderr_log_fd}>&- # close stderr_log_fd so the log process can exit when tee does
# now actually swap out stdout and stderr for the processes we started
exec 1>&$stdout_tee_fd 2>&$stderr_tee_fd {stdout_tee_fd}>&- {stderr_tee_fd}>&-

# ...do the things you want to log here...
echo "this goes to stdout"; echo "this goes to stderr" >&2

# now, replace the FDs going to tee with the backups...
exec >&"$stdout_orig_fd" 2>&"$stderr_orig_fd"

# ...and wait for the associated processes to exit.
while :; do
  ready_to_exit=1
  for pid_var in stderr_tee_pid stderr_log_pid stdout_tee_pid stdout_log_pid; do
    # kill -0 just checks whether a PID exists; it doesn't actually send a signal
    kill -0 "${!pid_var}" &>/dev/null && ready_to_exit=0
  done
  (( ready_to_exit )) && break
  sleep 0.1 # avoid a busy-loop eating unnecessary CPU by sleeping before next poll
done

---

So What's With The File Descriptor Manipulation?

A few key concepts to make sure we have clear:

• All subshells have their own copies of the file descriptor table as created when they were fork()ed off from their parent. From that point forward, each file descriptor table is effectively independent.
• A process reading from (the read end of) a FIFO (or pipe) won't see an EOF until all programs writing to (the write end of) that FIFO have closed their copies of the descriptor.

...so, if you create a FIFO pair, fork() off a child process, and let the child process write to the write end of the FIFO, whatever's reading from the read end will never see an EOF until not just the child, but also the parent, closes their copies.

Thus, the gymnastics you see here:

• When we run exec {stdout_log_fd}>&-, we're closing the parent shell's copy of the FIFO writing to the log function for stdout, so the only remaining copy is the one used by the tee child process -- so that when tee exits, the subshell running log exits too.
• When we run exec 1>&$stdout_tee_fd {stdout_tee_fd}>&-, we're doing two things: First, we make FD 1 a copy of the file descriptor whose number is stored in the variable stdout_tee_fd; second, we delete the stdout_tee_fd entry from the file descriptor table, so only the copy on FD 1 remains. This ensures that later, when we run exec >&"$stdout_orig_fd", we're deleting the last remaining write handle to the stdout tee function, causing tee to get an EOF on stdin (so it exits, thus closing the handle it holds on the log function's subshell and letting that subshell exit as well).

---

Some Final Notes On Process Management

Unfortunately, how bash handles subshells created for process substitutions has changed substantially between still-actively-deployed releases; so while in theory it's possible to use wait "$pid" to let a process substitution exit and collect its exit status, this isn't always reliable -- hence the use of kill -0.

However, if wait "$pid" worked, it would be strongly preferable, because the wait() syscall is what removes a previously-exited process's entry from the process table: It is guaranteed that a PID will not be reused (and a zombie process-table entry is left as a placeholder) if no wait() or waitpid() invocation has taken place.

Modern operating systems try fairly hard to avoid short-term PID reuse, so wraparound is not an active concern in most scenarios. However, if you're worried about this, consider using the flock-based mechanism discussed in https://stackoverflow.com/a/31552333/14122 for waiting for your process substitutions to exit, instead of kill -0.