Tratif

A visual indication of steps performed by a shell script not only improves the experience of the user of the script, but a well detailed log helps to debug any problems that could occur and to confirm that the script performed the operations correctly. Introducing a proper logging to shell scripts can help with that.

It’s all obvious, but often neglected, as it requires extra effort when writing a script. I would like to share with you a few tricks I use when it comes to logging operations performed by my scripts.

Goals

Here is what I would like to achieve:

1. When running a script a user is presented with concise descriptions of steps performed. It is important to avoid visual clutter and provide the user with the bare minimum of information.
2. All commands run, and their outputs (stdout and stderr) logged in detail to a file, which can later be looked at for debugging or confirmation.
3. Logs should contain at least some timestamps – we want to know when the script was executed.
4. We don’t want the above defined functionalities to impact our process of writing shell scripts.

Let’s start with a script that does very little, but is sufficiently complex to serve as an example:

#!/bin/bash
 
echo "creating a temporary directory and some files"
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

Running the script ./script-1.sh produces the following output:

creating a temporary directory and some files
touch: cannot touch '/not-existing-directory/testfile': No such file or directory

This however does not meet any of our requirements:

1. User is presented not only with necessary information (echo creating …), but with all outputs of the commands that are printed on the console
2. There is no log file and commands being executed are not logged. We do not even know where the files were created.
3. No timestamps

Let’s try to solve these problems.

Splitting commands output and messages for user

We start by splitting the messages intended to be seen by the end user and ‘debug’ messages printed by commands run – those should end up in a logfile. We can achieve this by using exec command and redirections:

LOGFILE="./log.log"
exec 3>&1 1>"$LOGFILE" 2>&1

To explain what the exec command does, we have to recap what file descriptors (FD) are. Whenever a process opens a file (or pipe, socket etc.) a file descriptor is created, the process then uses the file descriptor to perform IO operations on the file, file path is only used to create the descriptor. File descriptors are process-specific and numbered starting with 0 incrementally. Every process starts with 3 standard file descriptors 0 – Standard input (stdin) 1 – standard output (stdout) 2 – standard error (stderr). Bytes written by processes to FDs 1 and 2 end up displayed on the console. We can now proceed to explaining what arguments passed to the exec call do:

1. 3>&1 Creates a file descriptor number 3 that is a copy of file descriptor number 1 (stdout). Whatever our process writes to FD3 will be displayed on the console
2. 1>log.log Replaces file descriptor number 1 (stdout) with file descriptor created by creating a file log.log. From now on whatever our process writes to FD1 will end up in the log.log file.
3. 2>&1 Replaces file descriptor number 2 with a copy of file descriptor number 1 which is now a file descriptor pointing to the log.log file. From now on whatever our process writes to FD2 will end up in the log.log file.

This enables us to write messages intended to be seen by the end user to FD3, everything else that gets written to both stderr (FD2) and stdout (FD1) ends up in the logfile:

#!/bin/bash
exec 3>&1 1>"log.log" 2>&1
 
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

Running the script ./script-1-1.sh produces the following output:

creating a temporary directory and some files

and a file log.log file with the following content:

touch: cannot touch '/not-existing-directory/testfile': No such file or directory

Logging executed commands

It is still far from perfect. Our logfile lacks detailed information about all commands run. We can improve this by setting x bash option that prints commands and their arguments prefixed with a character of our choice, as they are executed:

#!/bin/bash
exec 3>&1 1>"log.log" 2>&1
set -x # Prints commands, prefixing them with a character stored in an environmental variable ($PS4)
 
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

Running our script ./script-1-2.sh prints:

creating a temporary directory and some files

and creates a file log.log:

+ echo 'creating a temporary directory and some files'
++ mktemp -d
+ TEMPDIR=/tmp/tmp.x0MbGYqxli
+ touch /tmp/tmp.x0MbGYqxli/testfile00 /tmp/tmp.x0MbGYqxli/testfile01 /tmp/tmp.x0MbGYqxli/testfile02 /tmp/tmp.x0MbGYqxli/testfile03 /tmp/tmp.x0MbGYqxli/testfile04 /tmp/tmp.x0MbGYqxli/testfile05 /tmp/tmp.x0MbGYqxli/testfile06 /tmp/tmp.x0MbGYqxli/testfile07 /tmp/tmp.x0MbGYqxli/testfile08 /tmp/tmp.x0MbGYqxli/testfile09
+ touch /not-existing-directory/testfile
touch: cannot touch '/not-existing-directory/testfile': No such file or directory

It is much better now, the log contains all the information needed, and the user is not bothered with it on the console. All that achieved with 2 lines of code:

exec 3>&1 1>"log.log" 2>&1
set -x

There are two more things to fix:

1. There are no timestamps
2. User is not aware of the script failure

Adding timestamps

Regarding timestamps, I do not have a strong opinion on that, so I will present a few different approaches, which, in my opinion, are valid:

• We can just add a simple date call here and there, it should be enough most of the time.

#!/bin/bash
exec 3>&1 1>"log.log" 2>&1
set -x
 
date -Is
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

• We can introduce a wrapper function `log` that will prefix our log messages with a timestamp:

#!/bin/bash
log() {
    echo "[$(date -Is)]" "$@"
}
 
exec 3>&1 1>"log.log" 2>&1
set -x
 
# We replaced echo call with a call to our 'log' function
log "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

• We can utilize a trap bash builtin command, that supports a special DEBUG signal that occurs before any command is executed:

#!/bin/bash
exec 3>&1 1>"log.log" 2>&1
set -x
trap "date -Is" DEBUG
 
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

This would result in date call before every command, which would look like this in the log.log:

+ trap 'date -Is' DEBUG
++ date -Is
2023-01-02T11:11:41+01:00
+ echo 'creating a temporary directory and some files'
++ date -Is
2023-01-02T11:11:41+01:00
++ mktemp -d
+ TEMPDIR=/tmp/tmp.vP5AlJpxfs
++ date -Is
2023-01-02T11:11:41+01:00
+ touch /tmp/tmp.vP5AlJpxfs/testfile00 /tmp/tmp.vP5AlJpxfs/testfile01 /tmp/tmp.vP5AlJpxfs/testfile02 /tmp/tmp.vP5AlJpxfs/testfile03 /tmp/tmp.vP5AlJpxfs/testfile04 /tmp/tmp.vP5AlJpxfs/testfile05 /tmp/tmp.vP5AlJpxfs/testfile06 /tmp/tmp.vP5AlJpxfs/testfile07 /tmp/tmp.vP5AlJpxfs/testfile08 /tmp/tmp.vP5AlJpxfs/testfile09
++ date -Is
2023-01-02T11:11:41+01:00
+ touch /not-existing-directory/testfile
touch: cannot touch '/not-existing-directory/testfile': No such file or directory

I lean towards the first approach. Just because of its simplicity.

Informing user about errors

Error handling in bash scripts will be discussed in more detail in a dedicated article. Here I am going to go with the simplest possible solution that is printing a generic error message pointing to the logfile, whenever any error occurs. This can be achieved by setting up a trap for ERR signal that prints the said message when a command exits with a non-zero status code:

#!/bin/bash
LOGFILE="log.log"
exec 3>&1 1>"$LOGFILE" 2>&1
set -x
trap "echo 'ERROR: An error occurred during execution, check log $LOGFILE for details.' >&3" ERR
 
date -Is
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

When run, the script produces the following output:

creating a temporary directory and some files
ERROR: An error occurred during execution, check log log.log for details.

and the following logfile:

+ trap 'echo '\''ERROR: An error occurred during execution, check log log.log for details.'\'' >&3' ERR
+ date -Is
2023-01-02T11:39:29+01:00
+ echo 'creating a temporary directory and some files'
++ mktemp -d
+ TEMPDIR=/tmp/tmp.Gl3AXiVHJZ
+ touch /tmp/tmp.Gl3AXiVHJZ/testfile00 /tmp/tmp.Gl3AXiVHJZ/testfile01 /tmp/tmp.Gl3AXiVHJZ/testfile02 /tmp/tmp.Gl3AXiVHJZ/testfile03 /tmp/tmp.Gl3AXiVHJZ/testfile04 /tmp/tmp.Gl3AXiVHJZ/testfile05 /tmp/tmp.Gl3AXiVHJZ/testfile06 /tmp/tmp.Gl3AXiVHJZ/testfile07 /tmp/tmp.Gl3AXiVHJZ/testfile08 /tmp/tmp.Gl3AXiVHJZ/testfile09
+ touch /not-existing-directory/testfile
touch: cannot touch '/not-existing-directory/testfile': No such file or directory
++ echo 'ERROR: An error occurred during execution, check log log.log for details.

In my opinion this is good enough. All requirements are met. The logfile is not super readable, but contains all required information, and excessive lines can be easily filtered out with grep. 4 lines in total solved all the problems:

LOGFILE="log.log"
exec 3>&1 1>"$LOGFILE" 2>&1
set -x
trap "echo 'ERROR: An error occurred during execution, check log $LOGFILE for details.' >&3" ERR

Going one step further

With a cost of added complexity we can improve the readability of the logfile with dates logged using DEBUG trap:

#!/bin/bash
LOGFILE="log.log"
exec 3>&1 1>"$LOGFILE" 2>&1
trap "echo 'ERROR: An error occurred during execution, check log $LOGFILE for details.' >&3" ERR
trap '{ set +x; } 2>/dev/null; echo -n "[$(date -Is)]  "; set -x' DEBUG
 
 
echo "creating a temporary directory and some files" >&3
TEMPDIR=$(mktemp -d)
touch $TEMPDIR/testfile{00..09}
touch /not-existing-directory/testfile

Let’s break down the changes:

We want to disable the x mode for the duration of printing the timestamp, however the set +x operation would be logged as well. To avoid that we can use command grouping (curly braces) which allows us to apply redirection to /dev/null to avoid logging execution of this command. This trick can be used to explicitly avoid logging a command execution that occurs due to x option.

Now the logfile looks like this:

[2023-01-02T11:57:24+01:00]  + echo 'creating a temporary directory and some files'
[2023-01-02T11:57:24+01:00]  ++ mktemp -d
+ TEMPDIR=/tmp/tmp.gcT6kYAs61
[2023-01-02T11:57:24+01:00]  + touch /tmp/tmp.gcT6kYAs61/testfile00 /tmp/tmp.gcT6kYAs61/testfile01 /tmp/tmp.gcT6kYAs61/testfile02 /tmp/tmp.gcT6kYAs61/testfile03 /tmp/tmp.gcT6kYAs61/testfile04 /tmp/tmp.gcT6kYAs61/testfile05 /tmp/tmp.gcT6kYAs61/testfile06 /tmp/tmp.gcT6kYAs61/testfile07 /tmp/tmp.gcT6kYAs61/testfile08 /tmp/tmp.gcT6kYAs61/testfile09
[2023-01-02T11:57:24+01:00]  + touch /not-existing-directory/testfile
touch: cannot touch '/not-existing-directory/testfile': No such file or directory
[2023-01-02T11:57:24+01:00]  ++ echo 'ERROR: An error occurred during execution, check log log.log for details.'

Summary 

The following four lines allow our script to meet the requirements I defined above:

LOGFILE="log.log"
exec 3>&1 1>"$LOGFILE" 2>&1
trap "echo 'ERROR: An error occurred during execution, check log $LOGFILE for details.' >&3" ERR
trap '{ set +x; } 2>/dev/null; echo -n "[$(date -Is)]  "; set -x' DEBUG

Users are no longer bothered with unnecessary information, we have a detailed log with timestamps and no extra effort is required when writing scripts. My goal was to present you with a simple solution that can be copy-pasted to an existing script, along with an explanation of what every line does. I believe that it can serve as a good starting point for further improvements.