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

Reproducing a Single Failure From a Regression

Debugging starts when a failure happens on demand, and the usual way of getting there — retyping the command from the log — is how real failures get labelled intermittent. This chapter measures one omitted plusarg turning a genuine failure into a clean pass, builds a replay that re-executes the recorded argv verbatim, and shows why that argv must be stored one token per line.

Advanced26 min readLinuxPart IIDebuggingReproducibilityQuoting

Part II · Module 33 · Chapter 33.2 · Reproducing a Single Failure

Chapter 33.1's triage ends, for the design layer, with the sentence the failure is reproducible from source. This chapter is about the gap between that being true and you having done it.

A failure you cannot make happen on demand is not a failure you can debug. Every technique in the rest of this module assumes a run that fails every time you ask it to.

1. The Failure That Stops Reproducing

The fixture has a test called latefail, which fails at cycle 150 and not before. The regression runs it with +CYCLES=200:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

TB  test=latefail seed=1 cycles=200 verbosity=LOW
TB  ERROR t=1535 late check failed at cycle 150
TB  TEST FAILED  test=latefail checks=1 errors=1
tb/tb_arb.v:165: $finish called at 2025 (1s)

So you reproduce it the way everybody does — by reading the log's first line and typing the command:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ cd /tmp/scratch
$ vvp /proj/logs/sim.vvp +TESTNAME=latefail +SEED=1
TB  test=latefail seed=1 cycles=40 verbosity=LOW
TB  TEST PASSED  test=latefail checks=1 errors=0

It passes. Same test, same seed, same image. The reason is in the first line of each log and is easy to read past:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  the regression used: cycles=200
  this run used      : cycles=40

+CYCLES was not in the command you typed, so the testbench applied its default. And the default is 40, which never reaches cycle 150:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  CYCLES=40   -> TEST PASSED
  CYCLES=100  -> TEST PASSED
  CYCLES=160  -> TEST FAILED  ERROR t=1535 late check failed at cycle 150
  CYCLES=200  -> TEST FAILED  ERROR t=1535 late check failed at cycle 150
  no +CYCLES  -> TEST PASSED   (the TB defaults to 40)

What happens next is the actual damage

The run passed. A reasonable engineer now believes one of three things, and all three are wrong:

"It is intermittent." The commonest conclusion, and the most expensive, because an intermittent failure gets a different and much worse process applied to it — run it fifty times, collect statistics, suspect a race. None of that will find anything, because the failure is perfectly deterministic.

"Somebody already fixed it." Plausible if a commit landed in between, and it leads to closing the ticket.

"The regression environment is broken." Which is at least pointed at the right area and still sends the investigation to the wrong team.

The failure is none of those. It is a completely reproducible bug that reproduces only under the conditions it was found in — and the one line that would have revealed it was printed in both logs. cycles=200 against cycles=40, two characters apart in a line nobody reads twice.

The general shape is worth stating, because it is the whole reason this chapter is Critical: a reproduction attempt that does not reproduce is evidence about your reproduction, not about the bug. Until the attempt is known to be faithful, a negative result means nothing at all.

2. Replay the Record, Not Your Memory of It

The fix is not to be more careful. It is to stop retyping.

Chapter 33.1's runone already records the resolved argv, one token per line:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ cat cap/lf200/cmd.args
vvp
/…/m33/logs/sim.vvp
+TESTNAME=latefail
+SEED=1
+CYCLES=200

And that file can be executed:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

#!/bin/bash
# repro RUNDIR [OUTDIR] -- re-execute one recorded run, verbatim, and say
# whether it produced the same result.
#
# Reads cmd.args, which holds ONE ARGV TOKEN PER LINE. A single quoted string
# cannot be replayed safely: re-splitting it guesses where the boundaries were,
# and guesses wrongly for any token containing a space.
set -u
src=${1:-}
[ -n "$src" ] || { echo "repro: need a run directory" >&2; exit 2; }
[ -r "$src/cmd.args" ] || { echo "repro: '$src' has no cmd.args -- nothing to replay" >&2; exit 2; }
[ -r "$src/run.log" ]  || { echo "repro: '$src' has no run.log -- nothing to compare against" >&2; exit 2; }
out=${2:-$src/repro}
rm -rf "$out"; mkdir -p "$out" || exit 2

# bash 3.2 has no mapfile, so build the array a line at a time. The final line
# may lack a newline, hence the `|| [ -n "$line" ]`.
argv=()
while IFS= read -r line || [ -n "$line" ]; do argv+=("$line"); done < "$src/cmd.args"
[ ${#argv[@]} -gt 0 ] || { echo "repro: cmd.args is empty" >&2; exit 2; }

printf 'repro: replaying %d argv token(s) from %s\n' "${#argv[@]}" "$src" >&2
printf '   %s\n' "${argv[@]}" >&2

( cd "$out" && exec "${argv[@]}" ) > "$out/run.log" 2>&1
printf '%s\n' "$?" > "$out/tool.rc"

a=$(/usr/bin/grep -o 'TEST PASSED\|TEST FAILED' "$src/run.log"  | head -1)
b=$(/usr/bin/grep -o 'TEST PASSED\|TEST FAILED' "$out/run.log"  | head -1)
printf '  recorded verdict : %s\n' "${a:-none}"
printf '  replayed verdict : %s\n' "${b:-none}"
if [ "$a" = "$b" ]; then
  # the same verdict is necessary, not sufficient -- compare the whole log too
  if diff -q <(sed 's/[0-9]\{4,\}/N/g' "$src/run.log") \
             <(sed 's/[0-9]\{4,\}/N/g' "$out/run.log") >/dev/null 2>&1; then
    echo "  => REPRODUCED (same verdict, and the logs match once long numbers are normalised)"
    exit 0
  fi
  echo "  => same verdict, but the logs differ:"
  diff "$src/run.log" "$out/run.log" | sed 's/^/     /' | head -8
  exit 1
fi
echo "  => DID NOT REPRODUCE"
diff "$src/run.log" "$out/run.log" | sed 's/^/     /' | head -8
exit 1

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ repro cap/lf200
repro: replaying 5 argv token(s) from cap/lf200
   vvp
   /…/m33/logs/sim.vvp
   +TESTNAME=latefail
   +SEED=1
   +CYCLES=200
  recorded verdict : TEST FAILED
  replayed verdict : TEST FAILED
  => REPRODUCED (same verdict, and the logs match once long numbers are normalised)
$ echo $?
0

And it reports a non-reproduction rather than only a reproduction — here against a record whose argv is missing +CYCLES:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ repro cap/mismatch
  recorded verdict : TEST FAILED
  replayed verdict : TEST PASSED
  => DID NOT REPRODUCE
     1,4c1,3
     < TB  test=latefail seed=1 cycles=200 verbosity=LOW
     < TB  ERROR t=1535 late check failed at cycle 150
     < TB  TEST FAILED  test=latefail checks=1 errors=1
     < tb/tb_arb.v:165: $finish called at 2025 (1s)
     ---
     > TB  test=latefail seed=1 cycles=40 verbosity=LOW
     > TB  TEST PASSED  test=latefail checks=1 errors=0
$ echo $?
1

The diff is the output that matters, because it puts cycles=200 directly above cycles=40. A tool that said only "did not reproduce" would have left the engineer exactly where Section 1 left them.

I read that exit status wrongly first

The first time I checked repro's status I ran it through a formatter:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ repro cap/mismatch 2>/dev/null | sed 's/^/  /'
  ...
  => DID NOT REPRODUCE
$ echo $?
0

Zero, for a run that plainly did not reproduce. $? after a pipeline is the last command's status, and the last command was sed. Measured without the pipe:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ repro cap/mismatch >/dev/null 2>&1; echo $?
1
$ repro cap/lf200    >/dev/null 2>&1; echo $?
0

Chapter 12.8 establishes the rule and Chapter 32.7 measured it destroying a regression's whole contract. It is in this chapter because of where it happened: in the throwaway command I used to check whether my own tool worked. The hazard is not confined to scripts that get committed; it is in every verification you do at a prompt, and it answers "yes" far more often than it should.

Read a status with nothing between the command and the $?, or capture it into a variable on the very next line.

3. Why One Token Per Line

The obvious way to record a command is as a line you could paste:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

vvp "/proj/a dir with spaces/sim.vvp" +TESTNAME=smoke

Replaying that means splitting it again, and the shell's splitting is not the inverse of the quoting:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ ( cd cap/q && exec $(cat /tmp/quoted.args) )
     rc=255  "/private/tmp/…/a dir with spaces/sim.vvp: No such file or directory

Exit 255, and look at the message: the path begins with a literal ". Command substitution produced the characters, word splitting cut them at spaces, and no quote removal happened — because quote removal is a parsing step that already ran. So vvp received four arguments where one was intended, the first of them starting with a quote character.

The same argv, one token per line:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ argv=(); while IFS= read -r l || [ -n "$l" ]; do argv+=("$l"); done < /tmp/perline.args
$ ( cd cap/p && exec "${argv[@]}" )
     rc=0  TB  test=smoke seed=1 cycles=40 verbosity=LOW

A newline is the one character that cannot appear in a path on this system, which makes it the only safe separator — the same argument Chapter 14.7 makes for find -print0 and xargs -0, one step weaker because a newline can appear in a filename on Linux while a NUL cannot.

Three details in those two lines of bash, all of which matter here:

IFS= read -r — IFS= so leading and trailing spaces in a token survive, -r so a backslash in a path is not an escape. Chapter 31.2 measured both.

|| [ -n "$line" ] — read returns false on a final line with no terminating newline, having already set the variable. Without this the last argv token is silently dropped, which for a command is usually the most important one.

argv+=("$line") rather than mapfile — mapfile -t argv < file is the modern one-liner and does not exist in bash 3.2:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ /bin/bash -c 'mapfile -t a < /etc/hosts; echo ${#a[@]}'
/bin/bash: line 0: mapfile: command not found

This machine's bash is 3.2.57, and so is every stock macOS. Chapter 21.6 is the general case; the practical consequence is that argv round-tripping has to be written the long way.

4. The Working Directory Changes the Evidence, Not the Verdict

repro runs the replay from inside a fresh directory, and it is worth being precise about what that buys, because the obvious claim is wrong.

Same argv, run from the project root instead:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  run from inside its own dir: verdict=TEST PASSED  dump landed in dump.vcd (1470 bytes)
  run from the project root  : verdict=TEST PASSED  dump landed in THE PROJECT ROOT (1470 bytes)

The verdict is identical. The working directory does not change what the simulation computes — it changes where everything the simulation writes ends up. Here that is a 1,470-byte waveform deposited in the project root, where it will be committed by somebody's git add . or deleted by somebody's clean-up.

And it changes what two runs do to each other:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  one dump.vcd, two runs: hashes 1990351d vs aa0bfa94 -> the second overwrote the first

Two debugging runs from the same directory, and the first one's waveform is gone. That is Chapter 31.6's collision arriving in an interactive session rather than a parallel one — and it is more annoying here, because the thing it destroys is the artifact you were about to open.

So the rule is narrower than "always cd" and worth getting right: the working directory is part of the run's identity when the run writes relative paths, and $dumpfile("dump.vcd") is a relative path. Chapter 27.6 measured which artifacts a simulation names for itself; those are precisely the ones the cwd controls.

Three more pieces of the identity, and how each one hides

cmd.args captures the argv. A faithful reproduction needs three things it does not capture.

The environment. A tool's behaviour can depend on variables the argv never mentions — LD_LIBRARY_PATH, a licence server, a project root. Chapter 25.8 builds the capture; the reason it belongs in a reproduction is that the regression ran under a scheduler's minimal environment and you are sitting in your own. Chapter 32.8 measured that gap at five PATH entries against fifteen, and a simulator that was not on the minimal one at all.

The image. Chapter 33.1 is entirely about this: an argv naming logs/sim.vvp says nothing about which build that was. repro replays the recorded absolute path, which is right, and triage is what checks that the file at that path is still the same file.

And the limits. A run killed by a ulimit or a scheduler cap behaves differently from the same run without one, and neither the argv nor the log mentions it. Chapter 30.6 measured an eviction arriving as 128 + SIGXFSZ; reproducing that failure interactively, with no cap, reproduces nothing.

The pattern across all three is the same as the +CYCLES case: the parts of a run's identity that are defaulted rather than stated are exactly the parts a reproduction loses, because a default is invisible in the record of what was asked for. Which is the argument for a wrapper that states everything explicitly — Chapter 27.4 passes the seed even when it is 1, and this is why.

5. What To Do When It Genuinely Does Not Reproduce

Suppose the replay is faithful — same argv, same image verified by its manifest, same environment — and the run passes anyway. Now the non-reproduction is information.

In order of how often they turn out to be the answer:

Something in the run is not a function of its inputs. Time, a process id, a hostname, a directory listing order, an uninitialised value. The test is to run the faithful replay several times and see whether the replay is stable:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$ for i in 1 2 3 4 5; do repro cap/X "/tmp/rx$i" >/dev/null 2>&1; echo -n "$? "; done
0 0 0 0 0

Five identical results means the replay is deterministic and the difference is between the regression and your replay, not inside either. Five mixed results means the run itself is nondeterministic, and that is the bug to chase first — Chapter 31.3 distinguishes a seed-dependent failure, which is reproducible, from a genuinely nondeterministic one, which is not.

The original run was affected by its neighbours. Eight parallel runs share memory bandwidth, disk and a page cache. A failure that needs a loaded machine is real and will not reproduce on an idle one, and the way to find out is to reproduce it under load rather than alone.

Or the record is incomplete. Which loops back to Section 4: something that mattered was defaulted, and the fix is to the recording rather than to the investigation.

The thing not to do is run it fifty times and call the pass rate a measurement. A reproduction rate across an unfaithful replay measures nothing, and it is the step that converts a two-hour debug into a two-day one.

Practice

Find a failing run in your flow and reproduce it by retyping the command from the log.
Compare the first line of both logs field by field and find the difference.
Build a test that fails only after N cycles and run it at four different limits.
Run it with the limit omitted and record what the testbench defaults to.
List the three wrong conclusions a passing reproduction invites, and the cost of each.
Record an argv one token per line and write the replay that executes it.
Make the replay report a non-reproduction with a diff, not just a verdict.
Read its exit status through a pipe, then without one.
Record the same argv as one quoted line and replay it by re-splitting.
Put a space in the image's path and compare the two formats.
Explain why quote removal does not happen on the re-split version.
Drop the || [ -n "$line" ] and replay a file with no final newline.
Try mapfile on this machine.
Run the same argv from two different directories and compare the verdicts.
Find where the waveform went in each case.
Run twice from the same directory and check whether the first waveform survived.
State the narrow rule about when the working directory is part of the identity.
Name the three parts of the identity that cmd.args does not capture.
Reproduce a scheduler eviction interactively and explain the result.
Replay a faithful reproduction five times and interpret both possible outcomes.
Reproduce a failure under load that will not reproduce idle.

Check Your Understanding

Why is a failure you cannot reproduce on demand not debuggable?
What made the retyped reproduction pass?
What were the four measured cycle counts and their verdicts?
What does the testbench do when +CYCLES is absent?
Name the three wrong conclusions, and which is most expensive and why.
State the general rule about a reproduction attempt that does not reproduce.
Which line would have revealed the problem, and why was it missed?
Why replay the record rather than retype it?
Why is the diff the important part of a non-reproduction report?
What did reading the status through sed give, and why?
Why does that matter in an interactive check rather than only in a script?
What happened to the quoted single line when it was re-split?
Why is there a literal quote character in the error message?
Why is a newline the right separator here, and how does it compare to -print0?
What do IFS= and -r each protect?
What does || [ -n "$line" ] protect, and which token is lost without it?
Why not mapfile?
Does the working directory change the verdict? What does it change?
What did two runs from the same directory do to each other?
State the narrow rule about the working directory and identity.
Name the three parts of a run's identity that cmd.args does not capture.
What do all three have in common with the +CYCLES case?
What is the first thing to check when a faithful replay does not reproduce?
What do five identical replay results tell you, and five mixed ones?
Why might a real failure need a loaded machine?
Why is a reproduction rate across an unfaithful replay worthless?

Answers

Because every later technique — tracing, bisecting, instrumenting — assumes a run that fails every time you ask it to.
+CYCLES was omitted, so the testbench used its default of 40, and the failure happens at cycle 150.
40 → PASSED, 100 → PASSED, 160 → FAILED, 200 → FAILED.
Defaults to 40 silently, and reports it in the log's first line.
"It is intermittent", "somebody already fixed it", and "the regression environment is broken". The first is most expensive, because it triggers a statistical investigation that cannot find a deterministic bug.
A reproduction attempt that does not reproduce is evidence about the reproduction, not about the bug. Until the attempt is known faithful, a negative result means nothing.
The first line of each log — cycles=200 against cycles=40. It was missed because it is a line nobody reads twice, and the difference is two characters.
Because the record is complete and memory is not; the parts you forget are the defaulted ones, which are invisible in the log you are reading from.
Because it puts cycles=200 directly above cycles=40. "Did not reproduce" alone leaves the engineer where they started.
Zero — the status of sed, which succeeded. $? after a pipeline is the last command's status.
Because the hazard is in every verification done at a prompt, not just in committed scripts, and it answers "yes" far more often than it should.
vvp exited 255, having received four arguments where one was intended, the first beginning with a literal ".
Because quote removal is a parsing step that already happened; command substitution produces characters and word splitting cuts them, but nothing removes the quotes.
Because a newline cannot appear in a path on this system. It is one step weaker than -print0, since a newline can appear in a filename on Linux while a NUL cannot.
IFS= preserves leading and trailing spaces in a token; -r stops a backslash being treated as an escape.
A final line with no terminating newline — read returns false having already set the variable, so the last argv token is silently dropped. For a command that is usually the most important one.
It does not exist in bash 3.2.57, which is what this machine and every stock macOS ships.
No. It changes where everything the run writes ends up — here a 1,470-byte waveform deposited in the project root.
The second overwrote the first's dump.vcd — hashes 1990351d against aa0bfa94.
The working directory is part of the run's identity when the run writes relative paths, and $dumpfile("dump.vcd") is one.
The environment, the identity of the image behind the path, and the resource limits in force.
All are defaulted rather than stated, and a default is invisible in the record of what was asked for — so a reproduction loses exactly those parts.
Whether the replay itself is stable: run the faithful replay several times.
Identical means the replay is deterministic, so the difference lies between the regression and the replay. Mixed means the run is nondeterministic, and that is the bug to chase first.
Because parallel runs share memory bandwidth, disk and the page cache, so a failure that needs contention will not appear on an idle machine.
Because it measures the replay rather than the bug — and it converts a two-hour debug into a two-day one.

6. Remember

A failure that does not happen on demand cannot be debugged. Everything later in this module assumes one that does.
Retyping the command from the log is how deterministic bugs get called intermittent. One omitted +CYCLES turned a real failure into a clean pass.
The testbench's default was 40 and the regression used 200 — printed in both logs, two characters apart, in the line nobody reads twice.
A reproduction that does not reproduce is evidence about your reproduction. A negative result means nothing until the replay is known faithful.
Replay the recorded argv, and report a diff rather than only a verdict.
Read an exit status with nothing between the command and $? — including in the one-off command you use to check your own tool.
Store the argv one token per line. Re-splitting a quoted line gave exit 255 and a literal quote inside an argument, because quote removal has already happened.
IFS= read -r, || [ -n "$line" ], and argv+=(…) — there is no mapfile in bash 3.2.
The working directory changes the evidence, not the verdict. Two runs from one directory overwrote each other's waveform.
The argv does not capture the environment, the image's identity, or the resource limits — and all three, like +CYCLES, are lost precisely because they were defaulted.
Check whether the replay is stable before calling the run nondeterministic, and never treat a pass rate over an unfaithful replay as a measurement.

7. What Is Next

The replay works because it executes a recorded argv in a controlled directory. Chapter 33.3 takes on the next form of the same problem — a command that works perfectly when you type it and fails inside the script that runs it — and measures the four differences that account for almost every case.

Where this fits

Part of the Linux & Bash curriculum.