Finding the First Real Error

Part II · Module 29 · Chapter 29.2 · Finding the First Real Error

Chapter 29.1 located the regions of a log. This chapter is about one line inside the message region: the first thing that actually went wrong. Everything after it is usually a consequence, and the discipline of reading that line and no other is the single largest difference between a ten-minute debug and an afternoon.

1. One Cause, Forty Messages

Forty instances of a module that does not exist:

$ iverilog -g2012 -o /tmp/t4.vvp /tmp/t4.sv
/tmp/t4.sv:2: error: Unknown module type: missing_mod
/tmp/t4.sv:3: error: Unknown module type: missing_mod
/tmp/t4.sv:4: error: Unknown module type: missing_mod
…
        missing_mod referenced 40 times.
***
$ echo $?
41

Forty-four lines for one mistake. The useful ones are the first — which names a file and a line — and the tool's own summary near the end, which has already done the deduplication for you: missing_mod referenced 40 times.

So the registry's recommended command is right, and worth understanding rather than copying:

$ grep -n -m1 -E 'error|Error|ERROR' /tmp/t4.log
1:/tmp/t4.sv:2: error: Unknown module type: missing_mod

-m1 stops at the first match, -n gives the line number so you can go back for context, and -E lets the alternation cover the spellings different tools use. On a four-thousand-line log the -m1 is also the difference between a line of output and a screenful.

2. The Same Tool, Two Cascade Shapes

Elaboration errors come one per instance. Syntax errors do not:

$ printf 'module m;\n  logic a\nendmodule\n' > /tmp/syn.sv
$ iverilog -g2012 -o /tmp/syn.vvp /tmp/syn.sv
/tmp/syn.sv:3: syntax error
I give up.
$ echo $?
2

Two lines, and the tool stopped. A parser that has lost track of the grammar cannot usefully continue, so it abandons the file — which means for a syntax error the first message is the only message, and there is no cascade to see past.

That difference matters when reading:

The third row is the one to be careful about, and it is why "read the first error and stop" is a rule for compile logs rather than a universal one. At run time, two errors can be genuinely unrelated — a scoreboard mismatch at cycle 13,370 and a protocol violation at cycle 31,000 may be two bugs. Chapter 29.4 is about telling those apart across a whole regression; here the narrow claim is that for compile and elaborate, later messages are consequences; for run time, they may not be.

3. The Measurement That Removes the Exit Status From the Argument

Module 27 established that a tool's exit status answers whether it finished, not whether the work was right. This chapter can make that much sharper, because iverilog's status is not merely uninformative — it is arithmetic on the error count, and the arithmetic wraps.

$ for n in 1 3 10 40 254 255 256; do
>   # n instances of a missing module; compile; report three numbers
>   … ; iverilog -g2012 -o /tmp/rc.vvp /tmp/rc.sv > /tmp/rc.log 2>&1; rc=$?
>   el=$(grep -c 'error:' /tmp/rc.log)
>   own=$(grep -oE '[0-9]+ error\(s\)' /tmp/rc.log | tail -1 | grep -oE '^[0-9]+')
>   printf '  %-6s %-6s %-14s %-16s\n' "$n" "$rc" "$el" "$own"
> done
  n      rc     error: lines   tool's own count
  1      2      1              2
  3      4      3              4
  10     11     10             11
  40     41     40             41
  254    255    254            255
  255    0      255            256
  256    1      256            257

Two separate facts are in that table, and they are both worth having.

There are two error counts in one log and they differ. grep -c 'error:' gives 40 for the forty-instance case; the tool's own line says 41 error(s) during elaboration. The extra one is the missing module type, reported once in addition to each instance that referenced it:

$ tail -5 /tmp/rc40.log
/tmp/rc40.sv:41: error: Unknown module type: missing_mod
41 error(s) during elaboration.
*** These modules were missing:
        missing_mod referenced 40 times.
***

And the exit status is the tool's own count, truncated to one byte. rc == own mod 256 in every row. A process status is a single byte, so at 256 reported errors the status is 0:

The mod 256 behaviour is not a bug in Icarus — a byte is all the operating system provides. It is a bug in the convention of returning a count as a status, and it is worth knowing because several tools do it.

4. "First" Is Not "Near the Top"

For compile logs the first error is usually near the start. For run logs it is wherever the design first misbehaved, and that is a measurement rather than a guess:

$ grep -n -m1 'UVM_ERROR' axi_burst_test.log
1344:UVM_ERROR tb/env/axi_sb.sv(201) @ 13370: uvm_test_top.env.sb [MISMATCH] expected 0xdeadbeef got 0xd…
$ grep -c . axi_burst_test.log
4021

Line 1344 of 4021 — a third of the way in. Neither head nor tail would have found it, which is why grep -n -m1 is the right instrument and why the line number is part of the answer: it tells you where to go for context.

And the simulated time in that line, @ 13370, is more useful than the line number for two purposes. It is what Chapter 27.6 needs to place a waveform window, and it is what lets you look at what the design was doing just before:

# the twenty lines of monitor traffic leading up to the first error
$ grep -n -m1 'UVM_ERROR' axi_burst_test.log | cut -d: -f1 \
>   | xargs -I{} sh -c 'sed -n "$(({} - 20)),{}p" axi_burst_test.log'

That xargs -I{} sh -c with arithmetic is doing real work — turning "the first error" into "the context around the first error" — and it is the shape of almost every log investigation.

5. A First-Error Extractor

#!/bin/bash
# firsterr LOG [CONTEXT] — the originating error, with the lines before it.
set -u
log=${1:?usage: firsterr LOG [CONTEXT]}
ctx=${2:-10}
[ -r "$log" ] || { echo "firsterr: cannot read $log" >&2; exit 2; }

# the spellings used by the tools in this flow, most specific first
hit=$(grep -n -m1 \
        -e '\*\* Error' -e '\*\* Fatal' \
        -e 'UVM_FATAL' -e 'UVM_ERROR' \
        -e 'error:' -e '^ERROR' -e 'Error-\[' \
        "$log" 2>/dev/null)

if [ -z "$hit" ]; then
  printf 'firsterr: no error line found in %s\n' "$log"
  # absence of an error line is NOT absence of a problem -- 29.5
  if ! grep -qE 'TEST (PASSED|FAILED)|Report Summary' "$log"; then
    printf 'firsterr: and no verdict either -- the run may not have finished\n' >&2
    exit 1
  fi
  exit 0
fi

n=${hit%%:*}
printf '== first error at line %s of %s ==\n%s\n' "$n" "$(grep -c . "$log")" "${hit#*:}"

printf '\n-- the %s lines before it --\n' "$ctx"
if [ "$n" -gt 1 ]; then
  from=$(( n - ctx )); [ "$from" -lt 1 ] && from=1
  sed -n "${from},$((n - 1))p" "$log"
else
  printf '(it is the first line of the file)\n'
fi

# the tool's own count, if it keeps one
own=$(grep -oE '[0-9]+ error\(s\)' "$log" | tail -1)
[ -n "$own" ] && printf '\n-- the tool says: %s --\n' "$own"
exit 1

$ firsterr /tmp/t4.log 3
== first error at line 1 of 44 ==
/tmp/t4.sv:2: error: Unknown module type: missing_mod

-- the 3 lines before it --
(it is the first line of the file)

-- the tool says: 41 error(s) --
$ echo $?
1

On the long run log, where the error is not at the top:

$ firsterr axi_burst_test.log 4
== first error at line 1344 of 4021 ==
UVM_ERROR tb/env/axi_sb.sv(201) @ 13370: uvm_test_top.env.sb [MISMATCH] expected 0xdeadbeef got 0xde…

-- the 4 lines before it --
UVM_INFO tb/agents/axi_mon.sv(142) @ 13340: … [AXI_MON] addr=0x00005360…
UVM_INFO tb/agents/axi_mon.sv(142) @ 13350: … [AXI_MON] addr=0x00005370…
UVM_INFO tb/agents/axi_mon.sv(142) @ 13360: … [AXI_MON] addr=0x00005380…
UVM_INFO tb/agents/axi_mon.sv(142) @ 13370: … [AXI_MON] addr=0x00005390…
$ echo $?
1

Those four lines are the point of the before-context: the monitor was mid-burst at exactly the time the scoreboard complained, and the addresses are the ones to look for in a waveform.

And the two no-error cases, which must not be conflated:

$ firsterr logs/fast.log ; echo "exit=$?"
firsterr: no error line found in logs/fast.log
exit=0

$ firsterr logs/stall.log ; echo "exit=$?"
firsterr: no error line found in logs/stall.log
firsterr: and no verdict either -- the run may not have finished
exit=1

Four decisions in that script.

The patterns are ordered most-specific first, and UVM_FATAL precedes UVM_ERROR. With -m1 the order of -e patterns does not select which matches — grep returns the earliest line in the file regardless — so this ordering is documentation rather than logic. Worth knowing, because it is easy to assume otherwise and write a script whose behaviour you have mispredicted.

No error line found is not success. The script checks for a verdict, and if there is neither an error nor a verdict it exits 1 — the NO-VERDICT state from Chapter 27.3, which Chapter 29.5 is entirely about.

It prints the lines before the error, not after. The lines after an originating error are its consequences; the lines before are what the design was doing when it went wrong. This is the opposite of grep -A, and it is the right default for a log.

It exits 1 when it found an error, so the script is usable in a condition. A reporting tool that always exits 0 cannot be composed.

And it guards the sed range. When the error is on line 1 the before-context is sed -n "1,0p", and BSD sed with an end lower than its start printed line 1 — the error line itself, presented as its own context. The explicit [ "$n" -gt 1 ] is there because the degenerate case is the common one for compile logs.

6. Reading the First Error Itself

Once you have the line, three things in it are worth extracting deliberately, because they are the inputs to everything downstream:

# the location: which file and line to open
$ echo "$line" | grep -oE '[A-Za-z0-9_./]+\.(sv|svh|v|vhd)[:(][0-9]+' | head -1
tb/env/axi_sb.sv(201

# the simulated time: where to put a waveform window (27.6)
$ echo "$line" | grep -oE '@ *[0-9]+' | head -1
@ 13370

# the message id: what to count across the regression (29.4)
$ echo "$line" | grep -oE '\[[A-Z_][A-Z_0-9]*\]' | head -1
[MISMATCH]

Note the first one is imperfect — it captures axi_sb.sv(201 without the closing parenthesis, because the delimiter differs between tools (file:line for Icarus and nvc, file(line) for UVM-style output). Making that pattern exactly right for every tool is the kind of work that never finishes, and the pragmatic answer is to accept a slightly ragged capture that is unambiguous to a human and to a $EDITOR, rather than to grow the regex.

That is a judgement worth stating plainly: a log parser is allowed to be approximate about things a human will read and must be exact about things a machine will count. The location is read by a person. The message id in Chapter 29.4 is counted by a script, and that one has to be exact.

Practice

1. Compile a file with forty instances of a missing module and count the log lines. Find the two useful ones.
2. Find the tool's own deduplicating summary in that output.
3. Compile a file with a syntax error and count the messages. Explain why there is no cascade.
4. Build the table for 1, 10, 40, 254, 255 and 256 instances with three columns: the status, your grep -c 'error:', and the tool's own count. Find which two agree.
5. Isolate the 255-instance case. Record the status, both counts, and whether an executable exists.
6. Write the obvious if iverilog …; then wrapper and run it on that input. Watch it print success.
7. Add the artifact check and confirm it catches what the status missed.
8. Add the log check using the tool's own count line, and decide which of the two you would keep if you could only have one.
9. Find the first UVM_ERROR in a long run log with its line number, and work out what fraction of the way through the file it is.
10. Extract the simulated time from that line and use it to place a dump window.
11. Write firsterr with its before-context and confirm it exits 1 on a log with an error and 1 on a log with no verdict.
12. Make firsterr print the lines after the error instead, and compare the usefulness on a real cascade.

Check Your Understanding

1. Forty-four lines came from one mistake. Which two are useful?
2. Why does a syntax error produce one message while an elaboration error produces forty?
3. For which kinds of log is "read the first error and stop" a sound rule, and where does it break down?
4. There are two error counts in one compile log. What are they, why do they differ, and which one does the exit status follow?
5. 255 instances produced what status, and what else was true of that compile?
6. Why does the wrapping happen at all, and whose mistake is it?
7. Which of the two defences is stronger, and why?
8. Where was the first UVM_ERROR in the 4,021-line log?
9. Why would neither head nor tail have found it?
10. Why does firsterr print the lines before the error?
11. Why does the order of the -e patterns not select which error is reported?
12. Why did the before-context need an explicit guard, and which case triggers it?
13. When may a log parser be approximate, and when must it be exact?

7. Remember

• One mistake produced 44 lines. The first names the location; the tool's own summary deduplicates the rest.
• grep -n -m1 -E is the instrument: first match, with its line number, across several tools' spellings.
• A syntax error has no cascade — the parser gives up. An elaboration error reports every instance.
• "First error and stop" is a compile-log rule. Run-time errors may be independent.
• A compile log can hold two different error counts. grep -c 'error:' gave 40; the tool's own line said 41 error(s).
• The exit status is the tool's own count mod 256. 255 instances → 256 reported errors → status 0, with no executable produced.
• Check the artifact, not the status. [ -s "$out" ] is immune to wrapping and to message formats.
• The first error is not near the top. It was at line 1344 of 4021.
• Extract the location, the simulated time and the message id — they feed the editor, the waveform window and the regression count respectively.
• Print the lines before an error, not after.
• No error line is not success. Check for a verdict too.
• A parser may be approximate for humans and must be exact for counting.

8. What Is Next

The originating error is found and the exit status has been removed from the argument. Chapter 29.3 reads the summary region properly — and finds a naive severity count that reports a fatal error on a run that had none.