Friday afternoon. You are handed a ticket for dbglab's periph_power test, which fails in both simulators. The previous owner has moved to another project. The ticket says: "Looked at this for a day. Tried lots of things, think it might be the sink or the isolation. Not reproducible in a consistent way?"
Which things? Which of them were ruled out, and by what? Was the failure really inconsistent, or were two simulators giving two symptoms? You will now spend a day finding out what a few lines of notes would have told you. What should those lines have been?
Most engineers keep no log, or keep the wrong one. Shell history has commands but not the reasons for them, not the results, and not what they ruled out. A waveform session leaves nothing at all. A summary written at the end ("it was the isolation") keeps the answer and loses the path, including every dead end the next bug of this kind will lead into again.
The cost is not only to the next person. Without a log you rerun experiments you already did, you forget which prediction you made before a result arrived, and after three hours you cannot say whether H2 was killed or just dropped. Each of those undoes the discipline of the earlier lessons in this part.
Write before you run. The hypothesis and its prediction go in first. Written afterwards, the prediction bends to fit the result.
One line per event, with the time and a kind: N note, H hypothesis, P prediction, RUN command, X ruled out. Short enough that writing it costs seconds.
Log the exact command and its result line. Copy-pastable: anyone with the commit should be able to rerun it. Keep full outputs in files and point to them.
Write what each result rules out, explicitly. "X: H1 and H2, because..." is the line that saves the next person a day.
Log changes to the tree. Every edit, as the diff line itself, and every checkout. A result is meaningless without the state it ran on.
Close each session with where you are: open hypotheses, the next experiment, what is applied locally. That is the hand-off.
Automate the boring part. This helper stamps the time, runs the command, shows its output and copies the command and result lines into the log:
#!/bin/sh
# dlog: append one entry to the debug log ($DLOG, default ./debug-log.txt), stamped with the time.
# dlog H "hypothesis" dlog P "prediction" dlog X "ruled out" dlog N "note"
# dlog run <command...> runs the command, shows its output, and logs the command,
# its PASS/FAIL and probe lines (dbglab's banner left out) and its exit status
LOG=${DLOG:-debug-log.txt}
t=$(date '+%H:%M')
if [ "$1" = run ]; then
shift
out=$("$@" 2>&1); st=$?
echo "$out"
{ echo "$t RUN $*"
echo "$out" | grep -v '^dbglab: test=' | head -8 | sed 's/^/ | /'
echo " exit $st"; } >> "$LOG"
exit $st
fi
tag=$1; shift
echo "$t $tag $*" >> "$LOG"You cannot draw this from shell history. From a log it falls out: which questions were open at any moment, and which result closed each one.
Here is the log of a hunt for the periph_power failure, written with dlog from the first run to the proven fix. It is complete apart from two trimmed outputs (marked ...):
$ cat debug-log.txt
22:31 N periph_power fails in the nightly at HEAD 49c5f04. Start: reproduce in both simulators.
22:31 RUN tb/run.sh periph_power 1
| FAIL test=periph_power seed=1 cycle=431: STREAM: pstream_valid is unknown
exit 1
22:31 RUN tb/run.sh periph_power 1 verilator
| FAIL test=periph_power seed=1 cycle=2421: WATCHDOG: no bus or stream progress for 2000 cycles; cpu_valid=0 cpu_ready=0 cpu_addr=00003008
exit 1
22:31 N Two symptoms: Icarus sees an unknown stream valid at 431, Verilator hangs (watchdog at 2421). Same bug or two? Keep both open.
22:31 RUN tb/run.sh periph_power 2
| FAIL test=periph_power seed=2 cycle=431: STREAM: pstream_valid is unknown
exit 1
22:31 RUN tb/run.sh periph_power 2 verilator
| FAIL test=periph_power seed=2 cycle=2421: WATCHDOG: no bus or stream progress for 2000 cycles; cpu_valid=0 cpu_ready=0 cpu_addr=00003008
exit 1
22:31 X seed: seed 2 fails at the same cycles in both simulators, so the stimulus that matters is fixed (the power sequence), not random.
22:31 N Test sequence (tb/tests.svh): 4 words drained; sink off; isolate; power off; 6 words pushed while off; power on (isolated); release isolation; sink on; drain.
22:31 H H1 isolation is released while the sink's outputs are still unknown. Predicts: valid_s X just before iso_en falls; FIFO pointers clean.
22:31 H H2 the sink does not come out of power-up cleanly. Predicts: valid_s goes X only after pwr_on rises; FIFO pointers clean.
22:31 H H3 a signal from the off domain corrupts the FIFO while power is off. Predicts: rinc or rbin X while pwr_on=0, before any output is X.
22:31 P One probe splits all three: the first X on rinc, rbin, valid_s and pstream_valid, with pwr_on and iso_en at that moment.
22:31 RUN sh ../../probes/run-probe.sh ../../probes/first_x.sv periph_power 1
| cycle 76: u_pd.rinc (into the FIFO) is X (pwr_on=0 iso_en=1 sink_en=0)
| cycle 87: u_fifo.rbin (read pointer) is X (pwr_on=0 iso_en=1 sink_en=0)
| cycle 427: u_pd.valid_s (sink output) is X (pwr_on=1 iso_en=0 sink_en=1)
| cycle 427: pstream_valid (domain output) is X (pwr_on=1 iso_en=0 sink_en=1)
| FAIL test=periph_power seed=1 cycle=431: STREAM: pstream_valid is unknown
exit 0
22:31 N exit 0 above is the probe script's final grep, not the test: the FAIL line is what counts.
22:31 X H1 and H2: the FIFO read pointer is X at cycle 87, 340 cycles before any output is X. Outputs go bad because the FIFO already is.
22:31 N H3 holds: rinc is X at 76 with pwr_on=0 and iso_en=1. Isolation is on, so why is rinc unknown? Read periph_pd.
22:31 RUN sed -n 33,36p rtl/periph_pd.sv
| // Isolation: every output of the domain is clamped to 0 while iso_en is high.
| assign rinc = rinc_p; // internal: only feeds our own async FIFO
| assign out_valid = iso_en ? 1'b0 : valid_p;
| assign out_data = iso_en ? 32'h0 : data_p;
exit 0
22:31 H H3a rinc leaves the switched domain without a clamp, so the off domain drives the FIFO's read increment.
22:31 P If H3a: clamping rinc makes Icarus pass, and the same change ends Verilator's hang (its supply model drives noise, which pops words instead of making X).
22:31 P Also, if H3a: git bisect over v0.1..HEAD with periph_power names commit 15 (122e88a), the isolation change.
22:31 RUN git bisect start HEAD v0.1
...
22:31 RUN git bisect run tb/run.sh periph_power 1
...
22:32 N bisect (4 runs): first bad commit 122e88a 'periph_pd: isolate only the outputs that leave the peripheral'. Log cut at 8 lines; full output in the terminal. bisect reset done.
22:32 X Every commit before 15 (v0.1..b357bd8): periph_power passes there.
22:32 RUN git diff --stat
| rtl/periph_pd.sv | 2 +-
| 1 file changed, 1 insertion(+), 1 deletion(-)
exit 0
22:32 RUN tb/run.sh periph_power 1
| PASS test=periph_power seed=1 cycles=469 time=4686 ns
exit 0
22:32 RUN tb/run.sh periph_power 1 verilator
| PASS test=periph_power seed=1 cycles=469 time=4686 ns
exit 0
22:32 RUN tb/regress.sh icarus 1 2 3
| smoke seed 1 PASS
...
exit 6
22:32 N Fix confirmed in both simulators; the Verilator hang was the same bug. Left failing in the regression: irq_w1c and dma_burst_backpressure (known, other bugs). Next: hand to the power-intent owner for review; add an X check on rinc while iso_en is high.The times show it all happened in two minutes: every run here takes under a second and the hunt was done in one sitting. In a real hunt the same entries spread over hours or days, which is exactly when the times start to matter.
Entries | What they give the next person |
|---|---|
Reproduce (the first eight) | two exact repro commands, two symptoms kept apart, and seed-dependence ruled out with evidence |
H1, H2, H3 with predictions | the candidate mechanisms, and what each one said would happen before the probe ran |
The probe run and the X line | why H1 and H2 are dead: the FIFO pointer was X 340 cycles before any output |
H3a, two P lines, bisect | a sharp mechanism, two predictions, and the commit that introduced it |
The last RUN lines and N | proof in both simulators, what is still failing and why that is someone else's bug, and the next step |
Compare that with the ticket in the scene. Every question the ticket left open ("the sink or the isolation?", "not reproducible?") has an answer here, with the command that gave it. Note also the line one bug or two? Keep both open: it carried the question of the two symptoms through the whole hunt, and the last Verilator run answered it. That is keeping several hypotheses alive, on paper.
A real log is never perfect. Three faults in this one, each worth a rule:
`exit 0` on a failing run. The probe script ends in grep, so its exit status is grep's. The next line caught it. Rule: log the result line, never only the status.
The fix is not in the log. git diff --stat says one line of periph_pd.sv changed, not what it became. Someone reading this tomorrow cannot see the fix. Rule: log the changed line itself (here assign rinc = iso_en ? 1'b0 : rinc_p;).
The regression summary was cut off. The helper keeps eight lines, so 6 failing run(s) was lost and recovered only by the closing note. Rule: for long outputs, log the summary and a path to the full output.
Kind | Write | Example from this hunt |
|---|---|---|
N note | context, state of the tree, what you are about to do | "Start: reproduce in both simulators" |
H hypothesis | a mechanism, numbered so later lines can name it | "H3 a signal from the off domain corrupts the FIFO" |
P prediction | what you expect, written before the run | "rinc or rbin X while pwr_on=0" |
RUN | the exact command, its result line, a path to the full output | the probe line with its four X lines |
X ruled out | what is now excluded, and by which result | "H1 and H2: rbin is X at 87, 340 cycles before any output" |
End of session | open hypotheses, next experiment, local edits, where logs are | the final N line |
The log turned a hunt into something that can be handed over at any line. Stop it after entry 15 and the next person knows the repro, the two symptoms and the three hypotheses. Stop it after entry 20 and they know H1 and H2 are dead and why. The ticket in the scene, after a day of work, carried less information than the first five lines.
Handing a hunt between people and teams (RTL to DV, DV to the lab) has its own practices, from what goes in the ticket to how a triage meeting uses these logs: see ownership and hand-offs.
The next open hypothesis is H3, with its prediction already written: rinc or rbin X while pwr_on is 0. The probe run in the log already shows that, so they would read the RTL that drives rinc (entry 17 onwards). They would not rerun the reproduce steps or retest H1 and H2: the log says those are done and why.
The hypotheses, the predictions and the rule-outs. Without them you cannot tell which runs were tests of an idea and which were tries, which results were surprising, or what is still open. The runs can be repeated; the reasoning cannot be recovered from them.
dbglab at HEAD 49c5f04 (rebuilt with dbglab/build-history.sh), Icarus Verilog 13.0, Verilator 5.048, git 2.54.0, 2026-10-17. The log is debug-log.txt written by the dlog script shown, in one sitting (times are real; every run takes under a second here). Commands as logged, from a copy of dbglab: tb/run.sh periph_power 1|2 [verilator], sh ../../probes/run-probe.sh ../../probes/first_x.sv periph_power 1, git bisect start HEAD v0.1, git bisect run tb/run.sh periph_power 1, then the clamp assign rinc = iso_en ? 1'b0 : rinc_p; and tb/regress.sh icarus 1 2 3.
Results: FAIL at 431 (Icarus) and WATCHDOG at 2421 (Verilator) for seeds 1 and 2; first X on rinc at cycle 76 and on rbin at 87 with pwr_on=0 iso_en=1; bisect names 122e88a in 4 runs; with the clamp both simulators PASS in 469 cycles and the regression has 6 failing runs, all irq_w1c and dma_burst_backpressure.
Limits: one short hunt by one person. The hypotheses were written by someone who knew dbglab well; in a real hunt more of them fail. Hand-off practice across teams is in Part 11.