Linux & Bash · Part II · Module 33 · Debugging Failed Jobs and Broken Flows

Tracing What a Flow Did

A flow's output is what it chose to print; its trace is what it actually ran. This chapter makes the trace useful — naming the file and line and the call chain — then measures the two things nobody expects: that tracing a driver traces none of its children, and that switching tracing on reclassified a passing run as vacuous because the trace landed inside the artifact the verdict is read from.

Advanced26 min readLinuxPart IIDebuggingTracingset -x

Part II · Module 33 · Chapter 33.6 · Tracing What a Flow Did

Chapter 33.5 ended on the one piece of direct evidence about what a tool was asked to do. Here it is:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ bash -x ./bin/regress 2>&1 | tee trace.log

A flow's output is a story it tells about itself. Its trace is a record of what it did. The two differ exactly where the bug is.

1. What the Trace Actually Shows

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ bash -x /tmp/t1.sh
+ d=/tmp/trace-demo
+ mkdir -p /tmp/trace-demo
++ ls /tmp/trace-demo
++ grep -c .
+ n=0
+ printf 'count=%s
' 0
count=0

Four properties of that output, and three of them are not obvious.

Every line is post-expansion. mkdir -p /tmp/trace-demo, not mkdir -p "$d". The trace is the argv, after parameter expansion, command substitution, word splitting, globbing and quote removal — which is why Chapter 33.5 called it the only direct evidence.

The depth marker counts nesting. ++ is one level in — a command substitution — and +++ is two. So ++ ls and ++ grep -c . are the two halves of $(ls "$d" | grep -c .), and the + n=0 below them is the assignment that consumed their result.

Assignments are traced. + n=0 is how you learn what a variable became without adding an echo.

And it quotes what needs quoting. From Chapter 33.3's harness:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

+ vvp '/tmp/m33demo/sim builds/sim.vvp' +TESTNAME=smoke +SEED=1

The single quotes are the shell telling you that argument is one argument. Compare the broken version, where the same path appears unquoted and is therefore two:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

+ vvp /tmp/m33demo/sim builds/sim.vvp +TESTNAME=smoke +SEED=

That one character is the entire diagnosis of a whole class of bug, and it is visible nowhere else.

2. Making It Say Where It Is

The default prefix is almost useless on a flow of any size:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ /bin/bash -c 'printf "%q" "$PS4"'
+```

A plus and a space. On three hundred trace lines from four scripts, nothing says which file or which line. `PS4` fixes that, and it is re-evaluated on every traced line, so it can contain expansions:

```bash
$ PS4='+ ${BASH_SOURCE##*/}:${LINENO}: ' bash -x /tmp/t1.sh
+ t1.sh:2: d=/tmp/trace-demo
+ t1.sh:3: mkdir -p /tmp/trace-demo
++ t1.sh:4: ls /tmp/trace-demo
++ t1.sh:4: grep -c .
+ t1.sh:4: n=0
+ t1.sh:5: printf 'count=%s
' 0

Now every line is a coordinate. Add the function and you get the call chain for free:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: ' bash -x /tmp/t2.sh
+ t2.sh:4:main: outer hello
+ t2.sh:3:outer: inner hello
+ t2.sh:2:inner: echo 'in inner with hello'
+ in inner with hello

Three lines, three stack frames, with the argument visible at each hand-off. ${FUNCNAME[0]:-main} because FUNCNAME is empty at the top level, and the :-main is what stops the prefix collapsing there.

The ${BASH_SOURCE##*/} strips the directory — Chapter 8.3's suffix removal — because the full path of every script on every line is what makes a trace unreadable.

What to put in PS4, and what not to

Worth adding:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: '

A timestamp is tempting for a long flow and has a cost: $(date +%T) in PS4 forks a process for every traced line, which on this driver's 381 lines is 381 forks. $SECONDS is a shell variable and free:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

PS4='+ ${SECONDS}s ${BASH_SOURCE##*/}:${LINENO}: '

Not worth adding: $$ (constant within a script, so it is 300 copies of one number) and $? — which looks essential and is actively misleading, because PS4 is expanded before the command runs, so $? is the status of the command before the one on that line. A reader will inevitably attribute it to the line it sits on.

And one hazard: whatever you put in PS4 is expanded as shell code on every line. A command substitution there runs that often, and a malformed expansion produces an error per traced line, which is how a trace becomes 762 lines instead of 381.

3. It Does Not Trace the Children

This is the finding that makes most flow traces useless, and it is invisible unless you look for it.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ bash -x /tmp/parent.sh
+ echo 'parent: about to call the child'
parent: about to call the child
+ /tmp/child.sh
child: doing work

+ /tmp/child.sh and then nothing. The child ran, printed its output, and not one of its commands was traced. set -x is a property of a shell, and a child script is a different shell.

On the real driver that is the difference between a trace and a trace of the wrong thing:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

=== the driver traced WITHOUT propagation ===
  lines=90   vvp invocations visible: 0

Ninety trace lines about setup, expansion and dispatch — and zero simulations, because the simulations happen inside one.sh, which xargs invokes as a separate script. The work the flow exists to do is the one part the trace omits.

The mechanism that does propagate

The documented answer is SHELLOPTS, and it does not work:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ /bin/bash -c 'SHELLOPTS=xtrace; echo "set to: $SHELLOPTS"'
/bin/bash: SHELLOPTS: readonly variable

Read-only. It reports the current options faithfully —

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ /bin/bash -c 'set -x; echo "SHELLOPTS now: $SHELLOPTS"' 2>&1 | grep SHELLOPTS
+ echo 'SHELLOPTS now: braceexpand:hashall:interactive-comments:xtrace'

— and cannot be assigned, so it cannot be exported into a child.

What does work is BASH_ENV, which names a file every non-interactive bash sources at startup:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ printf "set -x\nPS4='+ \${BASH_SOURCE##*/}:\${LINENO}: '\n" > /tmp/xtrace-all.sh
$ BASH_ENV=/tmp/xtrace-all.sh bash -x ./bin/regress

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

=== and WITH BASH_ENV propagation ===
  lines=381   vvp invocations visible: 2

And the children appear:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

+ regress:73: xargs -P 4 '-I{}' <R>/regr/20261009T110752Z/one.sh '{}'
+ one.sh:3: set -u
+ one.sh:3: set -u
+ one.sh:4: spec=prio0:1
+ one.sh:4: spec=smoke:1

Two one.sh:3 lines interleaved, because four slots are running — which is the next problem and the reason Chapter 31.6 isolates runs. A trace of a parallel flow is several traces shuffled together, and the only reliable way to read one is to re-run the failing spec alone.

`BASH_XTRACEFD` is the right answer and does not exist here

The proper fix for a trace tangled up with program output is to send the trace to its own file descriptor:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

exec 9>trace.log
BASH_XTRACEFD=9
set -x

Measured on this machine:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ /bin/bash -c 'exec 9>/tmp/xt.log; BASH_XTRACEFD=9; set -x; echo hello; set +x'
+ echo hello
hello
+ set +x
$ wc -c < /tmp/xt.log
       0

The trace went to standard error and the file got zero bytes. BASH_XTRACEFD arrived in bash 4.1; this is 3.2.57, which is what macOS ships and what a surprising number of build machines still run.

So on bash 3.2 the trace and the program's stderr are the same stream, and every technique in Section 5 is a workaround for that. Chapter 21.6's point exactly: check the version before adopting the idiom, because the failure here is silent — no error, an empty file, and a trace you believe is captured.

4. The Volume, and What To Do About It

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  plain                              12 lines
  bash -x (driver only)              90 lines
  bash -x + BASH_ENV (everything)    381 lines

32× at full propagation, and 78 of the 90 driver-only lines are trace rather than output. On a real nightly that factor applied to a four-hour flow is a file nobody opens.

Three ways to make it usable, in order of how often they are the right one:

Trace one spec, not the regression. Chapter 33.2's replay reduces the problem to one run before tracing enters the picture at all. A trace of one failing simulation is forty lines.

Turn tracing on for a region. set -x and set +x bracket the part you suspect:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

set -x
"$root/bin/runsim" "$t" "$s" "$d" "$limit"
set +x

And grep the trace for the command you care about, which works because every traced line is a complete argv:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ grep -E '^\++ .*: (iverilog|vvp) ' trace.log

The ^\++ anchors on the depth marker so a line of program output that happens to mention vvp is not matched — the kind of over-match Chapter 24.1 measured in a signal search.

5. Tracing Changed the Result

Here is why this chapter is not simply "turn on set -x".

runsim runs the simulator in a redirected subshell, which is the right structure for Chapter 31.6's isolation:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

( cd "$d" && exec vvp "$root/logs/sim.vvp" … ) > "$d/run.log" 2>&1

With tracing on, the subshell's trace is part of the subshell's standard error — and that is redirected into run.log:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

+ runsim:12: cd <R>/regr/20261009T110752Z/runs/smoke_s1
+ runsim:12: exec vvp <R>/logs/sim.vvp +TESTNAME=smoke +SEED=1 +CYCLES=200
TB  test=smoke seed=1 cycles=200 verbosity=LOW
TB  TEST PASSED  test=smoke checks=3 errors=0
tb/tb_arb.v:165: $finish called at 85 (1s)

Two of the five lines in that log were written by the shell, not the simulator. For debugging this is wonderful — the second line is the exact argv, which is precisely what Chapter 33.1 needed. For the flow it is contamination of the artifact that every verdict is computed from.

On this regression the verdicts happened to survive — 1 PASS 1 FAIL traced and untraced. That is luck, and it is measurable luck:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ cat cap/tr/run.log
TB  test=smoke seed=1 cycles=200 verbosity=LOW
TB  TEST PASSED  test=smoke checks=3 errors=0
+ runsim:14: grep -q 'checks=0' run.log
+ runsim:15: echo 'ERROR none'

A log whose trace lines mention checks=0 — because the wrapper greps for it, so the trace quotes it:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  checks extracted by  sed ... | tail -1  : 0
  checks the testbench actually reported  : 3

Chapter 32.3's extraction takes the last checks= in the log, and the last one is now a trace line. Running that chapter's classifier on it:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ verdict cap/tr
VACUOUS
  exit=7

A passing run, reclassified as vacuous, by switching on tracing. Nothing failed; no error appeared; the regression simply reported a different result because it was being observed.

Which rules survived, and the three fixes measured

Not every rule broke, and the difference is instructive. The same log's ERROR check was unaffected:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  ERROR lines seen by  grep -c "[[:space:]]ERROR" : 0

Because the trace renders it as echo 'ERROR none' — the E is preceded by a quote, not whitespace, so Chapter 32.3's deliberately anchored '[[:space:]]ERROR' does not match it. The rule that was written tightly survived; the rule that took the last match of a loose pattern did not. That is an argument for anchoring that neither chapter anticipated.

Three ways to keep the trace out of the artifact, measured:

fix	trace lines left in the log	cost
`( set +x; … ) > log 2>&1`	1	the `set +x` is itself traced before it takes effect
`( … ) > log 2>err`	0	the tool's stderr is now in a different file, so interleaving is lost
`exec 3>&2; ( … ) > log 2>&3`	0	the tool's stderr goes to the terminal rather than the log

The interleaving cost of the middle option is real and easy to underestimate:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  combined order is lost: out=[line1,line2,] err=[oops,]

An error that followed line1 now sits in a separate file with nothing to say what it followed, which is the one thing Chapter 29.1 relies on when reading a tool log.

So there is no free option on bash 3.2, and the honest recommendation is the boring one: trace a reproduction, not a regression. Switch tracing on when you are already down to one run, where the artifact is something you are about to read yourself rather than something a classifier will score. The measurement above is the reason, and it generalises past tracing: any change that adds output to a flow's artifacts is a change to the flow's results, and that includes raising a tool's verbosity.

Practice

Trace a short script and identify a post-expansion argv, a nesting marker and an assignment.
Find a traced line with quotes in it and say what the quotes mean.
Print the default PS4 with printf %q.
Add the source file and line number and re-read a trace.
Add the function name and trace a three-deep call chain.
Explain ${FUNCNAME[0]:-main}.
Put $(date +%T) in PS4 and count the forks it costs on a real flow.
Use $SECONDS instead.
Put $? in PS4 and work out which command's status it reports.
Trace a script that calls another script and count the child's traced lines.
Try to export SHELLOPTS.
Use BASH_ENV and confirm the child is traced.
Trace a parallel flow and find two interleaved children.
Try BASH_XTRACEFD on your machine and check the file size.
Check your bash version against 4.1.
Measure the line-count ratio for plain, traced, and fully propagated.
Grep a trace for one tool's invocations, anchored on the depth marker.
Find a flow that redirects a subshell into an artifact.
Trace it and look inside the artifact.
Construct a trace line that a verdict rule picks up, and run the classifier.
Work out which of your own log rules are loose enough to be fooled.
Try all three fixes and count the leftover trace lines.
Split stdout and stderr and demonstrate the lost interleaving.

Check Your Understanding

What is the difference between a flow's output and its trace?
Name the four properties of a traced line.
What does ++ mean?
What do quotes in a traced line tell you?
What is the default PS4?
Why can PS4 contain expansions?
What does ${FUNCNAME[0]:-main} give at the top level, and why the default?
What does a timestamp in PS4 cost, and what is free instead?
Why is $? in PS4 misleading?
What happens when a traced script calls another script?
How many simulations were visible in the driver-only trace, and why?
What is wrong with SHELLOPTS?
What does BASH_ENV do?
What appears in the trace once propagation is on?
Why is a parallel flow's trace hard to read, and what is the fix?
What does BASH_XTRACEFD do on this machine, and why?
Why is that failure especially dangerous?
Give the three line counts and the ratio.
Give the three ways to reduce trace volume.
Why anchor a trace grep on ^\++?
Why did trace lines end up inside run.log?
What did the trace line containing checks=0 do to the extraction?
What did the classifier then report for a passing run?
Which rule survived, and why?
What does that argue for?
Give the three fixes and their costs.
What is the honest recommendation, and what does it generalise to?

Answers

The output is a story the flow tells about itself; the trace is a record of what it ran. They differ exactly where the bug is.
Every line is post-expansion; the depth marker counts nesting; assignments are traced; and arguments are quoted when they need it.
One level of nesting — a command substitution. +++ is two.
That the quoted text is a single argument. Its absence where you expected it is the whole diagnosis of a word-splitting bug.
+ — a plus and a space, which printf %q shows as +\ .
Because it is re-evaluated on every traced line.
FUNCNAME is empty at the top level, so without the default the prefix collapses there; :-main labels it.
$(date +%T) forks a process per traced line — 381 forks on this driver. $SECONDS is a shell variable and free.
Because PS4 is expanded before the command runs, so $? is the status of the previous command, which a reader will attribute to the line it sits on.
The child is not traced at all. set -x is a property of a shell, and a child script is a different shell.
Zero. The simulations happen inside one.sh, which xargs invokes as a separate script.
It is read-only — SHELLOPTS: readonly variable — so it cannot be assigned and therefore cannot be exported into a child.
Names a file that every non-interactive bash sources at startup, so set -x in that file propagates.
The children — + one.sh:3: set -u, + one.sh:4: spec=prio0:1 — and the line count went from 90 to 381.
It is several traces shuffled together. The fix is to re-run the failing spec alone.
Nothing — the trace still went to standard error and the target file got zero bytes. It arrived in bash 4.1 and this is 3.2.57.
Because it is silent: no error, an empty file, and a trace you believe is captured.
12 plain, 90 driver-only, 381 fully propagated — 32× at full propagation.
Trace one spec rather than the regression; bracket a region with set -x/set +x; and grep the trace for the command you care about.
So a line of program output that happens to mention the tool is not matched.
Because the subshell's trace is part of its standard error, and that is redirected into run.log for isolation.
The extraction takes the last checks= in the log, and the last one was now the trace line — so it read 0 instead of 3.
VACUOUS, exit 7 — a passing run reclassified because it was being observed.
The ERROR check, because the trace renders it as echo 'ERROR none' so the E is preceded by a quote rather than whitespace, and the rule was anchored on [[:space:]]ERROR.
Anchoring patterns tightly, and not taking the last match of a loose one.
set +x inside the subshell leaves 1 line; stderr to its own file leaves 0 but loses interleaving; exec 3>&2 then 2>&3 leaves 0 but sends the tool's stderr to the terminal instead of the log.
Trace a reproduction, not a regression — switch tracing on once you are down to one run whose artifact you will read yourself. It generalises to any change that adds output to a flow's artifacts, including raising a tool's verbosity.

6. Remember

Output is what a flow chose to print; the trace is what it ran.
Every traced line is the argv after all expansion, with quotes marking a single argument — the only direct evidence for a word-splitting bug.
++ is one nesting level. Assignments are traced too.
Set PS4='+ ${BASH_SOURCE##*/}:${LINENO}:${FUNCNAME[0]:-main}: ' — and use $SECONDS, not $(date), which forks per line. Never $?: PS4 expands before the command runs.
bash -x does not trace child scripts. The driver's trace showed zero of its simulations.
SHELLOPTS is read-only. BASH_ENV pointing at a file containing set -x is what propagates.
BASH_XTRACEFD does nothing on bash 3.2 — the file stays empty and there is no error. It arrived in 4.1.
Volume: 12 → 90 → 381 lines. Trace one spec, bracket a region, and grep anchored on ^\++.
Tracing reclassified a passing run as VACUOUS, because the subshell's trace landed in run.log and the last checks= in the file was a trace line.
The tightly anchored rule survived and the loose one did not. Anchor patterns; never take the last match of a loose one.
No fix is free on bash 3.2: 1 leftover line, lost interleaving, or the tool's stderr off the log.
Trace a reproduction, not a regression — and remember that anything which adds output to a flow's artifacts changes the flow's results, verbosity included.

7. What Is Next

Tracing works on one run. Chapter 33.7 goes back to the other end of the scale — two hundred failures at once — and groups them by signature, so that one fix can be matched to the forty tests it actually explains rather than to the one somebody happened to open.

Where this fits

Part of the Linux & Bash curriculum.