Debugging Scripts: bash -x

bash -x runs a script and prints every line before it runs, with its variables already filled in, so you can watch what the script really did; set -x and set +x trace one part only, and PS4 adds line numbers to the trace.

Journeyman · Unix · Linux · Updated

After this lesson you can

  • Trace a script line by line with bash -x, and read the + lines it prints
  • Trace one part of a script with set -x and set +x, and add line numbers to the trace with PS4

Key takeaways

  • bash -x script.sh prints each command, starting with +, right before it runs, with every variable replaced by its value.
  • ++ marks a command run inside $( ), one level deeper. The trace goes to standard error, so it doesn't mix into a file you send the output to.
  • set -x inside a script turns tracing on from that line, and set +x turns it off again, so you see only the part you suspect.
  • PS4='+ line ${LINENO}: ' near the top of a script puts each traced command's line number in front of it.

A script did something wrong, and reading it over doesn't show why: every line looks right. That's when you need to see what the script actually did, line by line, with the real values in place of the variables. It's like the dashcam in a delivery van: instead of guessing how the dent happened, you play back the trip. Bash records the trip for you with bash -x, and it's the first thing an administrator reaches for when a script that ran fine for months suddenly misbehaves.

The examples use mover.sh as Cleaning Up: trap and mktemp left it, in the mover practice folder.

A bug that loses a photo

Make a one-word change, the kind of slip anyone makes when tidying a script. In the line that checks for a photo already there, change $name to $file:

  if [[ -e "$dest/$file" ]]; then

Run the practice lines from Errors a User Can Act On for a fresh folder, and move the photos:

./mover.sh inbox photos
echo $?
cat photos/IMG_0412.jpg

Moved IMG_0412.jpg.
Moved IMG_0413.jpg.
Moved IMG_0414.jpg.
0
beach

No warning, exit code 0, and the birthday cake is gone, replaced by the beach. The check is still in the script, so why didn't it fire?

bash -x: watch every line

Run the practice lines again, then run the script with bash -x in front, read "bash, trace":

bash -x ./mover.sh inbox photos

These are the first 23 lines it prints:

+ set -euo pipefail
+ usage='Usage: mover.sh FROM-FOLDER TO-FOLDER'
+ [[ inbox == \-\-help ]]
+ [[ 2 -ne 2 ]]
+ src=inbox
+ dest=photos
+ [[ -d inbox ]]
+ [[ -d photos ]]
+ tmp=
+ trap 'rm -f "$tmp"' EXIT
+ skipped=0
+ for file in "$src"/*
+ [[ -e inbox/IMG_0412.jpg ]]
++ basename inbox/IMG_0412.jpg
+ name=IMG_0412.jpg
+ [[ -e photos/inbox/IMG_0412.jpg ]]
++ mktemp photos/.moving.XXXXXX
+ tmp=photos/.moving.GisPc3
+ cp -p inbox/IMG_0412.jpg photos/.moving.GisPc3
+ mv photos/.moving.GisPc3 photos/IMG_0412.jpg
+ rm inbox/IMG_0412.jpg
+ echo 'Moved IMG_0412.jpg.'
Moved IMG_0412.jpg.

This printed record of what ran is called an execution trace. Each line that starts with + is a command, printed right before it runs, with every variable already replaced by its value. ++ marks a command run inside $( ), one level deeper. Lines without a + are the script's own output. The other two photos follow the same way, and at the very end the trap's rm -f shows up too.

Now read the trace like a dashcam. name=IMG_0412.jpg is right. The next line isn't: the script asked about photos/inbox/IMG_0412.jpg, a path that will never exist, because $file still holds the folder name. The fix is the word you changed: put $name back.

The trace goes to standard error, like the error messages in Errors a User Can Act On, so bash -x ./mover.sh inbox photos > moved.log still keeps a clean log. To read a long trace page by page, send both streams into less: bash -x ./mover.sh inbox photos 2>&1 | less.

set -x around one part

A long script makes a long trace. To watch only the part you suspect, turn tracing on inside the script with set -x and off again with set +x (the + turns an option off). Put them around the check, keeping the $file bug for now:

  set -x
  name=$(basename "$file")
  if [[ -e "$dest/$file" ]]; then
    echo "mover: skipped $name: $dest already has one." >&2
    skipped=$((skipped + 1))
    continue
  fi
  set +x

Run the practice lines and the mover again, and only those lines are traced, once for each photo:

++ basename inbox/IMG_0412.jpg
+ name=IMG_0412.jpg
+ [[ -e photos/inbox/IMG_0412.jpg ]]
+ set +x
Moved IMG_0412.jpg.
++ basename inbox/IMG_0413.jpg
+ name=IMG_0413.jpg
+ [[ -e photos/inbox/IMG_0413.jpg ]]
+ set +x
Moved IMG_0413.jpg.

(The third photo follows the same way.)

PS4: which line is it?

The + at the start of each traced line comes from a variable, PS4, the way your prompt comes from PS1. Set it near the top of the script, under set -euo pipefail, to show each command's line number. ${LINENO} is bash's own variable for the line it's running, and the single quotes keep it from being filled in too early:

PS4='+ line ${LINENO}: '

Run the practice lines and the mover again:

++ line 31: basename inbox/IMG_0412.jpg
+ line 31: name=IMG_0412.jpg
+ line 32: [[ -e photos/inbox/IMG_0412.jpg ]]
+ line 37: set +x
Moved IMG_0412.jpg.

That's the first photo; the other two follow the same way. Line 32 is the one to fix, in a script of 46 lines. Yours may sit on other lines if your file differs a little. Fix $file back to $name, take out set -x and set +x, and run the practice lines and the mover once more: mover: skipped IMG_0412.jpg: photos already has one. is back, and cat photos/IMG_0412.jpg says cake. bash -x and set -x work the same on a Mac.

Check yourself

2 questions to try on the lesson page.

So what

When a script misbehaves, bash -x shows what it really did, with every value filled in, so you find the bug by reading facts instead of guessing.

Key terms

Cheat sheets

Related