Logging shell scripts' executions: a better way

Source

Some 11 years ago I wrote:

wanna debug it by at least tracing its execution? Well,
simply surround it by:

    (
    set -x
    ...
    ) > /tmp/$0-$(date +%F.%T).log

Well, a couple of years back at my $OLD_JOB we needed to do exactly that, even with the option turn it on and off at will. For the latter, we decided to use an envvar. Here's how we did it, it's much more robust:

if [ -n "$DEBUG" ]; then
    export PS4='> $(date +"%Y-%m_dT%H:%M:%S") > $(basename "${BASH_SOURCE}") > ${FUNCNAME[0]:=__main__}():${LINENO} > '
    exec 5>> /var/log/foo.log
    BASH_TRACEFD=5
    set -x
fi

There's a lot there, so let's try to unpack it.

  • The last line, set -x, makes bash print every line executed
  • PS4 defines the "prompt" for such lines. We're doing a lot here, so:
  • We start printing a date. Maybe the Y-m-s is too much, but it looks familiar from other log files. This is command substitution that is executed every time a line is printed, the same way you can do fun stuff with your shell prompt.
  • We print the filename of the source file.
  • The the function from the top of the stack, or __main__ in the case of the main body of the script. Guess who wrote this and what's their favorite language :)
  • Then the line number
  • Then bash prints the executed line
  • bash has grown organically, which is a nice way to say 'hacky'. This incantation is how you open a file for appending and copy the file descriptor to the file descriptor 5. Remember 0 is stdin, 1 is stdout and 2 is stderr. We're playing safe with 5.
  • We tell bash to use fd 5 for printing all this, sending it to the file. By default stderr is used, which you probably want to keep for your own script.
  • All this only if DEBUG has any contents. We usually do export DEBUG=1.

Enjoy.

Update

Forgot to mention: this will slow down your execution time noticeably, specially if it's a 65k LoC beast. Ask me how I know, but only after buying me a beer :)