Debugging: bash -x, PS4, trap DEBUG and logs

A loop meant to print one city, New Delhi, printed two lines, <New> and <Delhi>, and the script still exited with status 0, so no log said anything was wrong. Reading the code finds a slip like that slowly; a single run under bash -x, which shows each command after Bash has expanded it, shows the loop making one pass per word of the unquoted $name.

You will trace scripts with set -x and a navigable PS4, send the trace to its own log with BASH_XTRACEFD, catch syntax errors with bash -n, read a ShellCheck report, and narrow a bug to one line and one word by shrinking the sample input and the script together.

xtrace prints each command before it runs, already expanded

set -xxtrace: Bash's set -x option (also set -o xtrace): the shell writes each simple command to stderr before running it, with its expansion done, prefixed by PS4 (default '+ '). set +x stops it; BASH_XTRACEFD=N sends the trace to file descriptor N instead. (also set -o xtrace) tells Bash to write each simple command to standard error before running it, with the expansion already done. set +x turns it back off, so a block of a script can be traced without the trace flooding the whole run. The one-shot form is bash -x script, which starts the shell with -x on.

from session import run, write

# set -x and set +x bracket the block the user wants to trace. The default PS4 is "+ ", so every traced line reads
# "+ command". A richer PS4 names the file, the line and the function: PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: '
write("buggy.sh", """#!/bin/bash
greet() {
    local who=${1-world}
    local msg="hello, $who"
    echo "$msg"
}

set -x
x=2
greet "errors-and-debugging"
set +x

echo "set -x block ended"
""")

write("buggy_ps4.sh", """#!/bin/bash
# A richer PS4 that names the file, the line and the function. Single-quote it so it expands at trace time.
PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: '

greet() {
    local who=${1-world}
    local msg="hello, $who"
    echo "$msg"
}

set -x
x=2
greet "errors-and-debugging"
set +x

echo "set -x block ended"
""")

run("""
chmod +x buggy.sh buggy_ps4.sh
# Default PS4 is just "+ ". Every traced command reads "+ command".
bash buggy.sh
echo "---with a richer PS4---"
bash buggy_ps4.sh
# A one-line trace with -c: the loop over the unquoted $name makes one pass per word.
bash -xc 'name="New Delhi"; for w in $name; do echo "<$w>"; done'
""")

$ chmod +x buggy.sh buggy_ps4.sh
# Default PS4 is just "+ ". Every traced command reads "+ command".
$ bash buggy.sh
+ x=2
+ greet errors-and-debugging
+ local who=errors-and-debugging
+ local 'msg=hello, errors-and-debugging'
+ echo 'hello, errors-and-debugging'
hello, errors-and-debugging
+ set +x
set -x block ended
$ echo "---with a richer PS4---"
---with a richer PS4---
$ bash buggy_ps4.sh
+ buggy_ps4.sh:12:main: x=2
+ buggy_ps4.sh:13:main: greet errors-and-debugging
+ buggy_ps4.sh:6:greet: local who=errors-and-debugging
+ buggy_ps4.sh:7:greet: local 'msg=hello, errors-and-debugging'
+ buggy_ps4.sh:8:greet: echo 'hello, errors-and-debugging'
hello, errors-and-debugging
+ buggy_ps4.sh:14:main: set +x
set -x block ended
# A one-line trace with -c: the loop over the unquoted $name makes one pass per word.
$ bash -xc 'name="New Delhi"; for w in $name; do echo "<$w>"; done'
+ name='New Delhi'
+ for w in $name
+ echo '<New>'
<New>
+ for w in $name
+ echo '<Delhi>'
<Delhi>

The first two runs printed every expansion. + x=2 is the assignment to x. + greet errors-and-debugging is the call, with its argument already expanded. The three lines after it are inside the function: + local who=..., + local 'msg=hello, ...' (quoted because the value has a space), and + echo '...'. The trace line comes before the command runs, so a program that fails on a line is named on the previous trace line.

PS4 names the file, line and function at trace time

The default PS4='+ ' is enough for a short block. For a trace that runs over many lines or spans several functions, a richer PS4 names where each line is. The habit is the one buggy_ps4.sh used:

#!/bin/bash
# A navigable PS4 that names the file, the line and the function. Single-quote so the three expansions
# fire at trace time, not at PS4-set time.
PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: '

The three expansions do three jobs. ${BASH_SOURCE##*/} is the current file’s basename: ## is the expansion POSIX calls Remove Largest Prefix Pattern, and here it deletes the longest match of */ from the front. ${LINENO} is the current line number in that file. ${FUNCNAME[0]} is the name of the function currently running, or empty at the top level; the ${…:-main} default replaces the empty value with main. Single-quote the whole PS4 so Bash reads these expansions at trace time, not at PS4-set time; otherwise they freeze to the values they had on the line that set PS4.

The lesson’s second run printed + buggy_ps4.sh:12:main: x=2, + buggy_ps4.sh:13:main: greet errors-and-debugging, then + buggy_ps4.sh:6:greet: local who=..., which is enough to open the file at line 6 and look at the function. For a script with sourced files, the basename makes the file obvious too.

Send the trace to its own file with a dedicated descriptor

set -x writes to standard error by default. For a script that reports its own errors to stderr, the trace and the error lines mingle, and a user who runs the script sees both. BASH_XTRACEFD, new in Bash 4.1, names a file descriptor, and Bash then writes the trace there instead of to standard error. Open a file as that descriptor, set the variable, and the trace lands in the file:

from session import run, write

# BASH_XTRACEFD = N sends the trace output to file descriptor N instead of stderr (fd 2). This keeps the script's
# own stderr for errors and the trace in a separate file, so a tee or grep over stderr is not swamped by trace lines.
write("to_file.sh", """#!/bin/bash
# Open file descriptor 3 for writing to trace.log, then send xtrace output there.
exec 3> trace.log
BASH_XTRACEFD=3
PS4='+ ${LINENO}: '

set -x
greet() {
    local who=${1-world}
    echo "hello, $who"
}
greet "errors-and-debugging"
echo "data on stdout"
set +x

exec 3>&-
""")

run("""
chmod +x to_file.sh
bash to_file.sh
echo "---trace.log content---"
cat trace.log
echo "---script's own stderr was clean, trace went to the file---"
""")

$ chmod +x to_file.sh
$ bash to_file.sh
hello, errors-and-debugging
data on stdout
$ echo "---trace.log content---"
---trace.log content---
$ cat trace.log
+ 12: greet errors-and-debugging
+ 9: local who=errors-and-debugging
+ 10: echo 'hello, errors-and-debugging'
+ 13: echo 'data on stdout'
+ 14: set +x
$ echo "---script's own stderr was clean, trace went to the file---"
---script's own stderr was clean, trace went to the file---

The three key lines of to_file.sh are exec 3> trace.log (open fd 3 for writing to trace.log), BASH_XTRACEFD=3 (point xtrace at fd 3), and set -x (switch on tracing). The function then ran with no visible trace; the terminal only showed hello, errors-and-debugging and data on stdout, and trace.log held every traced line. set +x then exec 3>&- at the end stop the trace and close the descriptor; a script that leaves fd 3 open is fine too, since every descriptor closes when the shell exits.

Three common uses: a long run under CI (the trace is an artefact, not a flood on stderr); a script a user runs by hand (the terminal stays clean); and a debug mode a flag enables ([ -n "${TRACE-}" ] && { exec 3>trace.log; BASH_XTRACEFD=3; set -x; }), which the script turns on with TRACE=1 ./script.sh.

Catch syntax errors first, then lint with ShellCheck

bash -n is the parse-only mode: the shell reads the script, checks the grammar and reports syntax errors, but runs no command. It is the first thing to try on a script that fails before the first line of output. In Bash 5.3 the message names the line where an unterminated construct began, which is often more useful than the line it ends on:

from session import run, write

# bash -n parses the script and reports syntax errors without running any command. Bash 5.3 names the line where
# an unterminated construct began, which turns a cryptic "unexpected end of file" into a navigable hint.
# shellcheck is the lint for the rest: a successful bash -n only says "the parser is happy", not "the script is right".
write("unterminated.sh", """#!/bin/bash
if [ -z "$1" ]; then
    echo "needs an argument"
# missing fi
""")

write("buggy_logic.sh", """#!/bin/bash
# Two slips ShellCheck's rules name on sight: an unquoted expansion that splits on spaces (SC2086), and
# -a used as "and" inside [ ] (SC2166), which is not well defined when an operand looks like an operator.
file=$1
if [ -r $file -a -s $file ]; then
    echo "ok: $file is readable and non-empty"
fi
""")

run("""
chmod +x unterminated.sh buggy_logic.sh
# bash -n parses only; a syntax error names the line of the opening construct.
!bash -n unterminated.sh
# Fixed syntax: shellcheck catches the two slips bash -n does not.
echo "---bash -n is quiet on buggy_logic.sh:---"
bash -n buggy_logic.sh
echo "---shellcheck is not:---"
!shellcheck buggy_logic.sh
""")

$ chmod +x unterminated.sh buggy_logic.sh
# bash -n parses only; a syntax error names the line of the opening construct.
$ bash -n unterminated.sh
unterminated.sh: line 5: syntax error: unexpected end of file from `if' command on line 2
[exit status 2]
# Fixed syntax: shellcheck catches the two slips bash -n does not.
$ echo "---bash -n is quiet on buggy_logic.sh:---"
---bash -n is quiet on buggy_logic.sh:---
$ bash -n buggy_logic.sh
$ echo "---shellcheck is not:---"
---shellcheck is not:---
$ shellcheck buggy_logic.sh

In buggy_logic.sh line 5:
if [ -r $file -a -s $file ]; then
        ^---^ SC2086 (info): Double quote to prevent globbing and word splitting.
              ^-- SC2166 (warning): Prefer [ p ] && [ q ] as [ p -a q ] is not well defined.
                    ^---^ SC2086 (info): Double quote to prevent globbing and word splitting.

Did you mean:
if [ -r "$file" -a -s "$file" ]; then

For more information:
  https://www.shellcheck.net/wiki/SC2166 -- Prefer [ p ] && [ q ] as [ p -a q...
  https://www.shellcheck.net/wiki/SC2086 -- Double quote to prevent globbing ...
[exit status 1]

bash -n unterminated.sh ended with syntax error: unexpected end of file from `if' command on line 2 and status 2. The if on line 2 was missing its fi, and the message named the line where that if began as well as line 5, where the file ended. Bash 5.3 added that starting line to the message; older versions name only the end of the file, which in a long script can be hundreds of lines below the slip.

A clean bash -n only says “the parser is happy”. The next tool is ShellCheck 0.11.0 (shellcheck script.sh), which checks for many slips that a parser cannot see. buggy_logic.sh passed bash -n and failed shellcheck: SC2086 (quote the expansion to prevent word splitting), SC2166 ([ p -a q ] is not well defined; use [ p ] && [ q ]). ShellCheck prints the file, the line, the carets under the span, and a link to the wiki page for every code; most codes name the fix in one line.

The ShellCheck codes that the earlier lessons of this module named are worth keeping on a crib sheet: SC2155 (declare and assign separately, from strict mode), SC2064 (single-quote the trap action, from traps and cleanup), SC2164 and SC2181 (cd … || exit and “check the status directly”, from error-handling patterns), and SC2086 (quote expansions, from this lesson’s example).

Shrink the bug and let a DEBUG trap narrate

A trace of 400 lines is harder to read than a trace of six, and the bug is almost never spread across the whole script. The practice: copy the failing block of the script into a scratch file (bug.sh), the failing input into a scratch file (bug.txt), and run the pair in isolation. The smaller the reproduction, the smaller the trace.

For the few bugs where every line of the smallest trace reads fine, trap … DEBUG is the next tool. A DEBUG trap runs before every simple command (Traps and cleanup describes it, and the next example sets one up); write the current BASH_COMMAND and one named variable to stderr, and the trace becomes a running commentary:

#!/bin/bash
# A DEBUG trap that narrates every simple command and the current count. set -T (functrace) is required
# for the trap to be inherited into functions.
set -T
trap 'printf '\''%s: %s (count=%s)\n'\'' "$LINENO" "$BASH_COMMAND" "${count-unset}" >&2' DEBUG

Three defences worth building into every long-running script:

• A --debug flag or a DEBUG environment variable that turns on set -x, so an on-call engineer can turn tracing on without editing the file.
• A log directory with one file per run (logs/$(date +%Y%m%d-%H%M%S).log), so two runs do not fight for one file.
• A one-line summary at the end of the trace: how many records, how long, which exit code.

The lint reportThe list of findings a linter such as ShellCheck prints for a script: each names the file, the line and a code (SC2086, SC2155 …) with the slip it saw, and points to the code's wiki page. is the fastest first look; the trace is the slowest, so leave it for the bugs lint cannot name. The scene below reads as a workflow, from “I know something is wrong” to “I know which line and why”:

Practise: pick the right tool, read the trace

The questions read trace lines, ask what bash -n and ShellCheck report, and pick a tool for a case: a descriptor left open, a DEBUG trap that has to reach into functions, a run that must not change anything. Decide before you check:

Interview questions

Warm-up (fresher to 2–5 years): what does bash -x script show that a plain bash script does not?

bash -x prints each command to standard error just before Bash runs it, after every expansion is done, with the prefix in PS4 (by default “+ ”). So you see the values a command really received: + x=2 for an assignment, + echo 'hello, world' for an echo whose argument holds a space, and one line per pass for the body of a loop. A plain bash script prints only what the commands themselves write. A richer PS4 adds the file, the line and the function, and BASH_XTRACEFD sends the trace to a file of its own instead of standard error.

Two questions follow, one about a failure that appears only on the production host and one about what a trace can expose in a shared CI log. Work out what you would check first in each, then open its page:

Key takeaways

• set -x prints every simple command before Bash runs it, prefixed with PS4 (default + ). set -x and set +x bracket a block; bash -x script traces the whole run.
• A navigable PS4 names the file, the line and the function: PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: '. Single-quote it so the expansions fire at trace time, not at PS4-set time.
• BASH_XTRACEFD=N sends the trace to the file descriptor the script opens as N; a user running the script sees the normal output while the trace lands in trace.log.
• bash -n parses the script and reports syntax errors without running a command; Bash 5.3 names the line of the opening construct, which turns “unexpected end of file” into a navigable hint. ShellCheck catches the slips the parser misses: SC2086 quoting, SC2155 declarations, SC2064 trap quoting, SC2164 cd … || exit, SC2181 “check status directly”.
• Shrink the bug: copy the failing block and the failing input into scratch files, trace that pair, and let a DEBUG trap narrate every step when the lint and the trace are not enough; a run that still fails on four lines of input tells you where to look much faster than a 400-line log.