Debugging Bash Scripts with $PS4
Debugging Bash scripts can be a pain, let's be honest. There aren't a lot of built-in debugging features nor are there many tools around to aid in the task. There is, however, $PS4.
For those unfamiliar, $PS4 is a variable that can be set so that when you run your scripts using set -x, a shell option that allows you to print each line of your script as it's run, you can add some custom text to the beginning of each line. The set -x option works like this:
If I have the following shell script named test.sh:
#!/bin/bash
set -x
TEST_VERBIAGE="You should see this printed to your terminal"
printf %s "$TEST_VERBIAGE"When I run it in the terminal it will look like this:
❯ ./test.sh
+ TEST_VERBIAGE='You should see this printed to your terminal'
+ printf %s 'You should see this printed to your terminal'
You should see this printed to your terminal%Back to $PS4. The power of $PS4 is not to be understated, but there isn't much in the bash man page that would lead you to believe there's much going on with it. Below is what you'll find in the man page about it:
The value of this parameter is expanded as with PS1 and the value is printed before each command bash displays during an execution trace. The first character of the expanded value of PS4 is replicated multiple times, as necessary, to indicate multiple levels of indirection. The default is ``+ ''.That isn't very helpful, but it does explain that the default is +. If you look above at the example when I ran test.sh in the terminal you'll notice a + at the beginning of each line that was an executed command (the other line is the output that you would normally see in your terminal, so it's not included). This is where the output of $PS4 is placed.
Crafting a PS4 Variable
You can include anything you want in your $PS4 but it generally makes sense to include things that explain the context of what's being executed so that when a line fails, you can have some extra information to help you figure out why. You could include the value of certain variables in your script, the time, or anything you want.
A simple example would be to use $PS4 to print out the time in nanoseconds before each line so you can tell how long each command takes to execute when looking back over the trace. This would be done by putting the following line at the top of your script:
PS4='$(date +%N)'One thing that should be noted when crafting your $PS4 is that you need to put the contents in single quotes: PS4='$(date +%N)'. That's because the value of $PS4 is executed at the beginning of each line, over and over, ad nauseam. If you put the contents in double quotes, like PS4="$(date +%N)", then anything that's going to be executed will only be executed once at the beginning of your script when you define the variable and each line will be prefixed by the same content, which isn't helpful.
For example, if we used the PS4="$(date)" example above we would get this:
❯ ./test.sh
++ date +%N
+ PS4='152563673 '
152563673 TEST_VERBIAGE='You should see this printed to your terminal'
152563673 printf %s 'You should see this printed to your terminal'
You should see this printed to your terminal% When what we really wanted was this, which shows the difference in time in nanoseconds:
❯ ./test.sh
+ PS4='$(date +%N) '
885045572 TEST_VERBIAGE='You should see this printed to your terminal'
890522778 printf %s 'You should see this printed to your terminal'
You should see this printed to your terminal% So to get that output our script is going to look like this:
#!/bin/bash
set -x
PS4='$(date +%N) '
TEST_VERBIAGE="You should see this printed to your terminal"
printf %s "$TEST_VERBIAGE"A Solid Default $PS4
Now you may be using $PS4 to examine different things in your shell script but in general, I'm going to walk you through the default $PS4 that I use for my scripts. Without further ado here it is:
PS4='$(tput setaf 4)$(printf "%-12s\\t%.3fs\\t@line\\t%-10s" $(date +%T) $(echo $(date "+%s.%3N")-'$(date "+%s.%3N")' | bc ) $LINENO)$(tput sgr 0)'
The output looks like this:
The first column is the time in the format hours:minutes:seconds. The second column is the number of seconds since the script started running, e.g. how far into the script timewise. The third and fourth columns indicate the line in the script you're on when executing the command on that line in the trace.
This last one is massively useful. When your script hits a snag and you get an error, usually the first thing you want to know in a bash script was what line in my script executed the last command.
You're more than welcome to copy and paste this and use it as is. With what you know about $PS4 and how it's used you should be good to go. It may look funny when you copy it into your editor because there is actually a part of this $PS4 definition that is not in single quotes as I advised at the beginning of this article. That's actually on purpose. What it does is it captures the time in nanoseconds at the time the variable is defined to use as a reference when calculating the seconds since the script started! A neat little trick.
Note that the tput commands at the beginning and the end are what create the colored aspect of the script. This is super useful when you've got thousands of lines of this mixed without output from the commands as well in order to orient yourself while navigating the trace. However, to use tput you'll need ncurses installed.
This is a non-issue in 99% of situations but if you're in a Docker container using a barebones image you may not have it, so just take those parts out or install ncurses if you hit a snag.
Enjoy!