Logging Bash Scripts

1. Overview

In this tutorial, we’ll learn how to log Bash scripts. We’ll understand why we need to log Bash scripts and look at various ways of doing it. Each way of logging helps differently. 

2. The Need for Logging

A script is a program by and large. Each command in a script has a certain behavior. Sometimes they may have errors and exceptions. It makes our lives easy if errors are readable. We’ll know how we can improve the script when we look at the errors.

In the case of Bash scripts, we generally use a series of Linux commands. Logging helps us understand each move a script takes. We can know when we executed a command successfully but it had other repercussions also. For instance, we’ll never know if an SSH command has run successfully if we don’t check its exit status.

The logs can store any type of information but typically answer why, who, when, what, and how something happened. Let’s dive into ways of logging now.

3. How to Log Bash Scripts

Basically, a Bash script is a set of commands. Some sets of commands have visible outcomes, but not all of them do.

The echo command prints the words or letters on the console. It’s a way to log the progress of the script, which prints a message after each command has been executed successfully. But printing messages isn’t enough. We may want to find out what the exit status of a command is, and whether it runs successfully or returns some type of error.

In order to do this, we’ve different ways of logging. 

3.1. Using File Descriptors and Data Streams

We can use the Linux data streams stderr and stdout to get information about a command’s execution status from the script.

While stdout stores standard output, the stderr stores the diagnostic output. In Linux, the file descriptor 0 is stdin, 1 is stdout and 2 is stderr. We can make use of these file descriptors:

#!/bin/bash
exec 3>&1 4>&2
trap 'exec 2>&4 1>&3' 0 1 2 3
exec 1>log.out 2>&1

The above set of commands uses exec and trap Linux commands. The first line saves the file descriptors 3 and 4 to stdout and stderr respectively, to get them restored later. The second line stores back stderr and stdout to file descriptors 3 and 4 when a few signals are caught. Finally, the third line redirects stdout to log.out file and stderr to stdout at the end. 

When the above snippet is given at the start of any Bash script, all the following lines’ output goes to file log.out. The log.out file has both stdout and stderr outputs together.

3.2. Logging With X-Trace

We can invoke a Bash script with the option -x to get the output of each line. We can collect these logs in a file so that we can visit the logs later:

# bash foo.sh
Hi there !
Hello my friend..

# bash -x foo.sh
+ echo 'Hi there !'
Hi there !
+ var_1=Hello
+ echo 'Hello my friend..'
Hello my friend..

# bash -x foo.sh >> bash_log
+ echo 'Hi there !'
+ var_1=Hello
+ echo 'Hello my friend..'

# cat bash_log
Hi there !
Hello my friend..
#

As shown in the above snippet, the option -x prints commands as they execute. It prints the substitute and expanded variables as well. Furthermore, we can redirect all the output to a file to store logs.

This brings us to the set built-in command, which has various useful options for logging.

3.3. The Built-in set Command 

The built-in command set allows us to display the names and values of shell variables. set allows us to set the positional parameters. Below are some of the most commonly used options with set commands.

The option set -x starts printing each command, while set +x stops this behavior. This enables us to use the option -x only for a set of commands in the script. Let’s see an example script:

#!/bin/bash
set -x
echo "Hi there !"
var_1="Hello"
echo "$var_1 my friend.."
set +x
var_2="Wait"
echo "$var_2... stopping here"

The above script logs the commands till it reaches set +x. The following lines won’t get printed.

Let’s see how the output displays:

# bash foo.sh
+ echo 'Hi there !'
Hi there !
+ var_1=Hello
+ echo 'Hello my friend..'
Hello my friend..
+ set +x
Wait... stopping here

The option set -v prints the commands from the script as they are read. This is useful when we want to see commands as they are before they substitute or expand a variable. Let’s see an example of how we can use the option set -xv:

# bash foo.sh

echo "Hi there !"
+ echo 'Hi there !'
Hi there !

var_1="Hello"
+ var_1=Hello

echo "$var_1 my friend.."
+ echo 'Hello my friend..'
Hello my friend..

set +x
+ set +x

var_2="Wait"

echo "$var_2... stopping here"
Wait... stopping here
#

The option set -e exits the script when any command returns an exit status other than zero. That simply means if there’s an error in the script, the script exits with the error shown on the command line. Let’s see an example:

#!/bin/bash
set -e
echo "Hi there !"
var_1="Hello"
echo "$var_1 my friend.."
ls here/file
var_2="Wait"
echo "$var_2... stopping here"

The ls command in the above script tries to list a file that doesn’t exist, hence the script stops and returns an error:

# bash foo.sh
Hi there !
Hello my friend..
ls: here/file: No such file or directory
# 

Thus we can use the built-in set utility to log the script and debug it. In the next section, we’ll learn about an alternate but default way of logging with Linux operating systems.

4. Syslog

The Syslog is a Linux operating system standard to log all actions as messages. The system logger captures, processes, and stores each action taking place in the OS. Utilizing this mechanism, we can log our Bash scripts.

We can find the logs at location /var/log/messages for some Linux distributions, while others use location /var/log/syslog.

Let’s see how it works.

4.1. Facilities

Facilities indicate what type of program or part of the system has originated the message. There are different facilities available like user, kern, mail, daemon, auth, and local0 to local7.

Any user can generate log messages using the user facility. The kern facility is used by the system to log kernel actions. We can use the local0 to local7 facilities for custom message logging.

4.2. Severities

On the other hand, we have severities like emerg, crit, alert, err, warning, notice, info, debug, etc. These severities label the message with the nature of the log.

crit is the most critical log while info is just the information log. In this way, severities describe the type of log. Severities are also known as priorities.

4.3. The Logger Utility

The logger utility uses some combination of facilities and severities to store the logs. The logger daemon can be syslogd, syslog-ng, or rsyslog on our system. There are also many other system loggers available.

Let’s look at some examples of how we can use the logger command and generate logs:

# logger "dear cj"
# tail -f /var/log/syslog
Jul  6 06:33:44 user1 ubuntu: dear cj

The above shows how the message passed by the logger gets logged into the syslog file:

# logger -si -p local0.warning "dear cj"
<132>Jul  6 06:43:06 ubuntu[1046]: dear cj

This example logs the message into the syslog file while displaying the output on the command line. It uses facility and severity to categorize the message. Here, the number <132> at the start of the second line denotes the facility as local0 and severity as a warning. Another benefit is we get the timestamp of each log here.

5. Conclusion

In this article, firstly we learned why we need logging with Bash scripts. Secondly, we looked at various methods of logging.

Lastly, we went through default system logging mechanisms. Using any single method or a combination of all these methods depends on users and varied use cases. Bearing in mind good scripting practices, we should use these logging methods and improve our Bash scripts.