For a while my preferred “bash script prelude” (the stuff you write in every bash script, before the actual content) has been a modest:

#!/bin/bash
set -eux

Those settings break down to:

  • -e: fail when any subcommand fails (the number of scripts that proceed to do completely incorrect things after an earlier command failed is criminal). You can always silence errors by using || or an if statement, but (much like exceptions in a high-level language) silence should not be the default.
  • -u: fail when an unknown variable is referenced - mostly guards against silly typos, but why wouldn’t you? It’s sometimes not what you want with variables that may be optionally set by the user, so sometimes I’ll move the set -u down in the script after I’ve dealt with setting those to their defaults if they are not present.

  • -x: trace all commands, after expansion. E.g with a line like: x=123; echo $x, Your output will be:

    • x=123
    • echo 123 123

This gets very noisy, but frequently I find it’s better to have more output than less - when a script breaks, often you can tell why just by looking at the last command trace (especially when combined with the -e option). And it’s easier to ignore excess output than it is to guess what went wrong.

The new hotness

Today, I discovered / created a much longer (and uglier) prelude, but I think it’s going to be worth it. Here ‘tis:

#!/bin/bash
set -eu
set -o pipefail
export PS4='+ ${FUNCNAME[0]:+${FUNCNAME[0]}():}line ${LINENO}: '
syslogname="$(basename "$0")[$$]"
exec 3<> >(logger -t "$syslogname")
BASH_XTRACEFD=3
echo "Tracing to syslog as $syslogname"
unset syslogname
debug() { echo "$@" >&3; }
set -x

A mouthful, indeed. Lets go though it line-by-line:

#!/bin/bash

Pretty normal stuff.

set -eu

Just like I normally do, but without the -x option. That will come later.

set -o pipefail

Fail the entire pipeline if any part of it fails. e.g you have something like ls -1 nonexistant_dir | cat then this option (combined with -e) will ensure your script fails when it should.

export PS4='+ ${FUNCNAME[0]:+${FUNCNAME[0]}():}line ${LINENO}: '

$PS4 is like the $PS1 prompt variable, but it’s prepended to bash’s trace output (the stuff you get from setting -x). This one adds useful information like the line number and function that the command came from.

syslogname="$(basename "$0")[$$]"

Get a meaningful name, combining the script’s name and the current process’ PID.

exec 3<> >(logger -t "$syslogname")

Create a new read/write file descriptor with number 3, and connect its output to the input of the logger command. If you don’t give logger a filename, it’ll read stdin and pipe the results through to your system’s syslog facility (with the tag specified by -t).

Note that this is similar in principle to:

echo "whatever" | logger -t "$syslogname"

with the difference being:

  • instead of piping stdout into logger, we create a new file descriptor
  • the exec call makes the redirection happen for the rest of the current process, not just for a single sub-process like echo

Together, this means that we have a new file descriptor (unconnected from stdout/stderr) which is connected straight to syslog!

BASH_XTRACEFD=3

This will direct bash to send trace output to file descriptor 3 (instead of stdout or stderr), which is the FD we just set up above.

echo "Tracing to syslog as $syslogname"
unset syslogname
debug() { echo "$@" >&3 }

Tell the operator where the logs are going, unset $syslogname (to be a good citizen), and add a convenience function to log a message directly to syslog.

set -x

Gentlemen, start your loggers!

An example

Here’s an example script using the above prelude:

#!/bin/bash
set -eu
set -o pipefail
export PS4='+ ${FUNCNAME[0]:+${FUNCNAME[0]}():}line ${LINENO}: '
syslogname="$(basename "$0")[$$]"
exec 3<> >(logger -t "$syslogname")
BASH_XTRACEFD=3
echo "Tracing to syslog as $syslogname"
unset syslogname
debug() { echo "$@" >&3 }
set -x

function fun_a
{
	echo "$1"
	debug "calling fun_b!"
	fun_b 1 2 3
}

function fun_b
{
	echo "$@"
}

x=123
fun_a x

It’s not a very interesting script, but here’s the useful output you get in syslog:

test.sh[15152]: + line 25: x=123
test.sh[15152]: + line 26: fun_a x
test.sh[15152]: + fun_a():line 15: echo x
test.sh[15152]: + fun_a():line 16: debug 'calling fun_b!'
test.sh[15152]: + debug():line 10: echo 'calling fun_b!'
test.sh[15152]: calling fun_b!
test.sh[15152]: + fun_a():line 17: fun_b 1 2 3
test.sh[15152]: + fun_b():line 22: echo 1 2 3

And here’s the script output:

Tracing to syslog as test.sh[15152]
x
1 2 3

So everything’s there in syslog if you need it (easily filterable by script name and PID), but if you don’t - there’s nothing to clean up, and no noise on the console.

Problems

There are two potential downsides to this prelude that I’m aware of:

  • you don’t want sensitive information going to syslog

This goes without saying, although you probably don’t want sensitive information going to stdout either. You can always temporarily set +x to suppress logging, and set -x to turn it back on.

  • reading syslog is (usually) restricted to root, or you don’t want to clutter syslog

There’s probably some configuration you could set up to get your syslog messages going to a particular file, but at that point you may want to replace the exec line with:

exec 3<> "/tmp/my-script.log"

..or something. You can include the pid or timestamp in the filename, but then you’ll get lots of them to clean up (but it will allow multiple concurrent instances to be run). Which one you prefer may differ per-script, but the basic format can remain pretty much the same.

Improvements

Undoubtedly there are improvements that could be made. Got any thoughts?

Update (20/06/2102): Added set -o pipefail