Debugging
Debugging is a term for a process of finding errors or fixing unexpected behaviors in scripts.
There are multiple different classes of errors, based on the programming language and style.
But to keep things simple, lets categorize them only on the two types: Syntax errors and logical errors. Syntax errors are usually typos and incorrect syntaxes made by a programmer. Logical errors are those that produce an undisered outcome even the code "is correct" (type of runtime error).
Debugging logical errors can be a pain as you have probably seen, shell scripts doesn't like to tell anything about those. Gladly Bash shell provides multiple options that can help you for debugging.
set command offers a multiple options that can be used when needed or placed on the shebang line to modify the whole script. In the following chapters, three the most common ones are introduced.
- -x = print commands and their arguments as they are executed
- -e = exit immediately if a command exits with a non-zero status
- -v = print shell input lines as they are read
The most common one is the -x option.
The -x option prints commands and their arguments as they are executed. So instead of variables being displayed, the actual values are displayed. Same priciple applies on expansions as well: wildcard chars are not displayed, what they expland are displayed.
This kind of debugging is often called as "tracing" or "print debugging".
When you want to start displaying the commands, call a command set -x. To end display functionality, use set +x command.
#!/bin/bash
set +x
VARIABLE="test"
echo ${VARIABLE}
#Output:
#+ VARIABLE=test
#+ echo test
#test
In the example above, two lines were printed with a plus sign in front of them before the actual echo command's output. That plus sign tells that those were the executed commands, not the outputs from the commands.
The next example shows how to use the set command to debug only a desired portion of the script. set -x turn debugging on and set +x ends it. Notice that only portion between set commands is diplayed: actual output from the echo command and also a the debug ending command set +x.
#!/bin/bash
VARIABLE="test"
set -x
echo ${VARIABLE}
set +x
whoami
#Output:
#+ echo test
#test
#+ set +x
#user
Another useful options is -e option. It causes script to exit immediately if a command exits with a non-zero exit code. This can help to point where the problem is.
Just like in any other Linux commands, you can chain multiple options!
Following example demonstrates -e option. The second line ls ${PATH} will return a non-zero exit code because path is not available. Because -e option is used, the execution of the script will be stopped and echo command is never executed.
#!/bin/bash
set -e
PATH="/not/exist"
ls ${PATH}
echo ${PATH}
#Output:
#ls: cannot access /not/exist: No such file or directory
# ------------------------------
#x and -e combined
#!/bin/bash
set -xe
PATH="/not/exist"
ls ${PATH}
echo ${PATH}
#Output:
#+ PATH="/not/exist"
#+ ls /not/exist
#ls: cannot access /not/exist: No such file or directory
-v option works like a -x option, but it displays the commands just like they are read from the script.
In other words: -v option displayes every line before they are executed.
Combine -v option with a option -x to see what the lines look before and after substitutions and explansions.
#!/bin/bash
set -v
VARIABLE="test"
echo ${VARIABLE}
#Output:
#VARIABLE="test"
#echo ${VARIABLE}
#test
# -------------------------
# With a -x option
#!/bin/bash
set -xv
VARIABLE="test"
echo ${VARIABLE}
#Output:
#VARIABLE="test"
#+ VARIABLE=test
#echo ${VARIABLE}
#+ echo test
#test
Logging
In general logging means to store informations about past actions. Logs can store multiple types of information but they typically answer who, what, when, where and why something occured.
In earlier chapter, you looked debugging. It is usefull if you are manually running the script, but what if script is run by cron or systemd timer or some other means? You need a way to look back the previous runs to see exactly what happened and when.
The Linux operating system uses syslog standart for message logging.
This eliminates the need for every program and service to implement their own logging mechanism, instead programs generate messages that can be captured, processed and stored by the system logger.
The syslog standart uses facilities and severeties to categorize messages.
Each message is labeled with a facility code and a severity level.
Facilities are used to indicate what type of program or what part of the system the message was from. For example, messages that are labeled with a kern facility come from the Linux kernel.
Each facility has a number and a keyword associated with it.
The following table lists the syslog facilities: RFC5424
If it's not clear what facility to use, you can use the user or local facilities.
Severities are what the name describes, the severity of the event in question.
Severity levels are emergency, alert, critical, error, warning, notice, info and debug. Where the emergency is the most severe and the debug is the least severe.
Severities are listed in the official RFC document: RFC5424
The combination of facilities and severeties are used by the system logger to handle messages. Most messages are written to a file. Different Linux distributions use slightly different set of default log locations on different type of messages, but usually you find most of messages stored at /var/log/messages or in /var/log/syslog files.
Logger utility
Now you know the basic principle how log messages are formated, it's time to implement them in your scripts using a logger command (Manual ).
The logger command generates syslog messages and by default, it creates messages using the user facility and the notice severity (user.notice).
The Basic syntax is: logger "message"
There are multiple options to change the basic functionality of the logger. Take a look at the Manual You can use multiple options in one command. Three the most common ones are listed below:
-p= priority-t= tag-i= PID-s= output message to stderr as well
If you need to specify other priority, you'll need to use option -p followed by the facility.severity pair.
For example, -p local3.info logs the message as informational in the local3 facility. An actual command for this would be: logger -p local3.info "message"
If you want to tag messages, so you can search them on the log file, use -t option. Typically, the name of the script would be a goof tag.
Syntax: logger -t "script_name" "Message"
If you want to include the PID (process ID) in teh message, use the -i option.
Syntax: logger -i "Message"
The following examples demonstrate different use cases. Take a look at your system's log file after execution (/var/log/syslog or /var/log/messages) and remember that different priorities might use the different files!
Note that priorities (facility + severity) are not shown on normal syslogd files! Use the following command to show latest 5 entries on journalctl: journalctl -n 5 -o verbose
#!/bin/bash
logger "Is this working"
#MONTH DAY TIME <hostname> <user>: Is this working
logger -p local0.info "message with a custom priority"
#MONTH DAY TIME <hostname> <user>: message with a custom priority
logger -s -p local0.info "message with a custom priority"
#MONTH DAY TIME <hostname> <user>: message with a custom priority
#On terminal: <134>MONTH DAY TIME <user>: message with a custom priority <-- DISPLAYED ON THE SCREEN
logger -t "my_script" "message with a custom tag"
#MONTH DAY TIME <hostname> my_script: message with a custom tag
logger -i -t "my_script" -p local0.info "message with a custom tag, PID and custom priority"
#MONTH DAY TIME <hostname> my_script[<PID>]: message with a custom tag, PID and custom priority
Do you want to type the logger command on every possible case? Probably not. You can create your own function and use it when needed!
For example:
#!/bin/bash
my_logger() {
local PRIORITY=$1
shift
local MESSAGE=$@
logger -i -t ${0} -p ${PRIORITY} ${MESSAGE}
}
ping -c 1 notavailablegoogle.com || my_logger "local0.err" "cannot connect to google.com"
#MONTH DAY TIME <hostname> <script_name>[<PID>]: cannot connect to google.com