Debugging, Tracing & Making Scripts Observable

A script that fails in CI at 2am cannot be debugged by adding echo and re-running. The tools below make a script explain itself the first time it fails.

Topic 1: The Trace Flags

bash -n script.sh      # syntax check ONLY -- executes nothing
bash -v script.sh      # echo each line as READ (before expansion)
bash -x script.sh      # echo each command as EXECUTED (after expansion)
bash -xv script.sh     # both -- see the source and the result

bash -n is the free one: run it in CI on every script and it catches unbalanced quotes, missing fi, and unterminated here-docs without executing anything.

The distinction between -v and -x is the useful part:

name="world"
echo "Hello $name"

# -v shows:  echo "Hello $name"      ← what you wrote
# -x shows:  + echo 'Hello world'    ← what actually ran

-x is where bugs are visible, because it shows the result of every expansion — which is exactly where quoting mistakes reveal themselves.

Enabling from inside:

set -x           # trace from here
risky_section
set +x           # stop tracing

Wrapping one function is far more usable than tracing a 300-line script. You can also gate it on an environment variable so production runs stay quiet:

[[ -n "${DEBUG:-}" ]] && set -x

DEBUG=1 ./deploy.sh        # trace on demand, no code change

Topic 2: PS4 — Making the Trace Readable

Default -x output prefixes every line with +, which tells you nothing about where you are. PS4 controls that prefix, and it is expanded at every traced line.

export PS4='+ ${BASH_SOURCE##*/}:${LINENO}: ${FUNCNAME[0]:-main}(): '
set -x

+ deploy.sh:42: main(): readonly TARGET=web-01
+ deploy.sh:57: upload(): rsync -az ./dist/ web-01:/srv/app/
+ deploy.sh:61: upload(): return 0

Now the trace is a timeline naming the file, line, and function for every step.

A timing-focused variant:

PS4='+ [${SECONDS}s] ${LINENO}: '

Watching the seconds counter jump identifies the slow command without any instrumentation.

The indentation trick:

Nested subshells increase BASH_SUBSHELL, and repeating a PS4 character shows depth:

PS4='${LINENO}:${FUNCNAME[0]:-main}> '

Bash repeats the first character of PS4 once per nesting level automatically, so a leading + visually indents nested calls.

Topic 3: Logging That Outlives the Terminal

For anything run by cron, systemd, or CI, the terminal does not exist. Build the log into the script.

#!/usr/bin/env bash
set -Eeuo pipefail

readonly LOG_FILE="/var/log/myapp/deploy-$(date +%Y%m%d-%H%M%S).log"
mkdir -p "$(dirname "$LOG_FILE")"

# Everything from here on goes to BOTH the terminal and the log
exec > >(tee -a "$LOG_FILE") 2>&1

echo "starting deploy"

exec without a command redirects the current shell’s own descriptors for the remainder of the script. Combined with process substitution and tee, every subsequent command is captured without touching a single one of them.

Variants:

exec >> "$LOG_FILE" 2>&1          # log only, no terminal output
exec 2> >(tee -a "$ERR_LOG" >&2)  # duplicate stderr only
exec 3>&1                          # save the original stdout as fd 3

That last one is the pattern for a script that logs everything but still needs to emit machine-readable output: log to the file, and write the real result to fd 3.

Levelled logging in nine lines:

readonly LOG_LEVEL="${LOG_LEVEL:-INFO}"

_log() {
    local level=$1; shift
    local -A rank=([DEBUG]=0 [INFO]=1 [WARN]=2 [ERROR]=3)
    (( rank[$level] < rank[$LOG_LEVEL] )) && return 0
    printf '%s [%-5s] %s\n' "$(date -Iseconds)" "$level" "$*" >&2
}
debug() { _log DEBUG "$@"; }
info()  { _log INFO  "$@"; }
warn()  { _log WARN  "$@"; }
error() { _log ERROR "$@"; }

LOG_LEVEL=DEBUG ./script.sh        # verbose when you need it

Two conventions that matter: timestamps in ISO-8601 (date -Iseconds) so the log sorts and parses, and diagnostics to stderr so stdout stays clean for data. A script whose logs go to stdout cannot be used in a pipeline.

Topic 4: Finding the Slow Part

time ./script.sh                    # real / user / sys for the whole run

# Per-section, without external tools
start=$SECONDS
do_the_slow_thing
info "took $(( SECONDS - start ))s"

For a line-by-line profile, PS4 with a high-resolution clock and a redirect to a separate descriptor:

PS4='+ $EPOCHREALTIME ${LINENO}: '     # bash 5+, microsecond resolution
exec 5> trace.log
BASH_XTRACEFD=5
set -x

BASH_XTRACEFD sends the trace to its own file descriptor instead of stderr — so the trace does not pollute the script’s real output, and you can analyse it afterwards:

awk '{print $2, $0}' trace.log | sort -n | tail -20     # slowest lines

Topic 5: Common Failure Signatures

Reproducing a cron environment:

The most common “works for me” failure. Cron runs with almost no environment:

env -i /bin/bash --noprofile --norc ./script.sh

That strips your environment entirely, which is much closer to what cron gives you. Anything that breaks here will break at 3am.

# Or capture cron's real environment once and diff it
* * * * * env > /tmp/cron-env.txt
diff <(env | sort) <(sort /tmp/cron-env.txt)

Topic 6: Interactive Debugging

Bash has no full debugger, but trap DEBUG gets close — it fires before every command:

trap 'read -rp "line $LINENO: $BASH_COMMAND  [enter]" </dev/tty' DEBUG

That single-steps the script, printing each command and waiting for a keypress. Crude, and genuinely useful for a loop that misbehaves on the fourth iteration.

Conditional breakpoints:

trap '[[ $LINENO -eq 42 ]] && { echo "state: count=$count file=$file"; }' DEBUG

For anything heavier there is bashdb, a real stepping debugger with breakpoints and watch expressions — worth knowing exists, rarely worth installing.

Try it yourself: Add PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}(): ' to your shell profile. Every bash -x you ever run afterwards is annotated.

Common mistake: Leaving set -x enabled in a script that handles secrets. The trace prints every expanded command — including tokens, passwords, and connection strings — into whatever log CI keeps. Gate tracing behind DEBUG, and disable it around anything sensitive with set +x.