UVM_ERROR, UVM_FATAL and the First Failure

Part II · Module 20 · Chapter 20.7 · UVM_ERROR, UVM_FATAL and the First Failure

1. The Shape of a Message

Here is a complete log, with the report summary the simulator writes at the end:

xcelium> run
Loading snapshot worklib.tb_top:sv ....................... Done
Simulation random seed = 1839274
UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO tb_top.sv(142) @ 0: uvm_test_top [CFG] clk period 2000 ps, reset 10 cycles
UVM_INFO env.sv(61) @ 0: uvm_test_top.env [BLD] built 1 agent, 1 scoreboard
UVM_WARNING mon.sv(51) @ 99300: uvm_test_top.env.agt.mon [SMP] late sample ignored
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 returned 0xdeadbeef
UVM_INFO scb.sv(120) @ 160000: uvm_test_top.env.scb [CHK] 160 transactions compared
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] response timeout after 2000 ns
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] axi_wr_rd_seq done
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :    5
UVM_WARNING :    1
UVM_ERROR :    2
UVM_FATAL :    0
TEST DONE

Put a real message next to a summary line and the difference is obvious to a person:

UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 ...
UVM_ERROR :    2

Both begin with UVM_ERROR, which is why Chapter 20.2 Section 8's startswith fix did nothing. What the first one has and the second does not is a simulation time — @ 141900:. Every message the UVM report server emits carries the time it was emitted at. A tally of messages is not emitted at a time, so it has none.

That is the fact to build the pattern on, and it is worth naming as a fact rather than a trick: a message happened at a moment; a count of messages did not.

2. The Pattern

UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 returned 0xdeadbeef
^^^^^^^^^ ^^^^^^ ^^    ^^^^^^  ^^^^^^^^^^^^^^^^^^^^^^^^ ^^   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
severity  file  line   time    hierarchy path            id   message

Six fields, and one of them is optional:

UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 returned 0xdeadbeef
UVM_ERROR :    2

import re

UVM = re.compile(
    r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
    r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
    r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
    r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)

with open("sim.log", encoding="utf-8") as handle:
    for line in handle:
        m = UVM.match(line)
        if m is None:
            print("no match  :", line.rstrip()[:40])
        else:
            f = m.groupdict()
            print(f"{f['sev']:<8} file={str(f['file']):<9} t={f['time']:<7} id={f['id']}")

INFO     file=None      t=0       id=RNTST
ERROR    file=drv.sv    t=141900  id=WR
no match  : UVM_ERROR :    2

Three lines, two matches, and the summary line rejected — which is the whole point. Taking the pattern a piece at a time, in Chapter 19.12's manner:

^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL) — anchored at the start of the line, with the four severities as a named alternation. No severity is a prefix of another, so Chapter 19.10 Section 4's ordering rule does not bite.

(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))? — the source location, optional. That matters more than it looks: the UVM reporter's own messages, like the RNTST line that announces the test, carry no file. A pattern that required one would drop them, and the INFO count would then disagree with the simulator's. Chapter 19.10 Section 7 argued that an optional group must be specific enough that its absence is unambiguous; \S+\.sv followed by a parenthesised number is specific.

\s+@\s+(?P<time>\d+): — the simulation time, required. This is the clause that rejects the summary lines. Nothing else in the pattern does that job.

(?P<scope>\S+) — the hierarchy path, or reporter for messages from the report server itself.

(?:\s+\[(?P<id>[^\]]+)\])? — the message id in brackets, optional because not every message has one. [^\]]+ is Chapter 19.13 Section 5's negated class rather than a lazy .+?, so it cannot run past the closing bracket.

\s*(?P<msg>.*)$ — everything left. Greedy .* is right here for Chapter 19.13 Section 6's reason: a message body contains anything, including brackets and colons, and no class describes it.

3. Counting, Correctly

xcelium> run
Loading snapshot worklib.tb_top:sv ....................... Done
Simulation random seed = 1839274
UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO tb_top.sv(142) @ 0: uvm_test_top [CFG] clk period 2000 ps, reset 10 cycles
UVM_INFO env.sv(61) @ 0: uvm_test_top.env [BLD] built 1 agent, 1 scoreboard
UVM_WARNING mon.sv(51) @ 99300: uvm_test_top.env.agt.mon [SMP] late sample ignored
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 returned 0xdeadbeef
UVM_INFO scb.sv(120) @ 160000: uvm_test_top.env.scb [CHK] 160 transactions compared
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] response timeout after 2000 ns
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] axi_wr_rd_seq done
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :    5
UVM_WARNING :    1
UVM_ERROR :    2
UVM_FATAL :    0
TEST DONE

import re

UVM = re.compile(
    r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
    r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
    r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
    r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)

SEVERITIES = ["INFO", "WARNING", "ERROR", "FATAL"]

with open("sim.log", encoding="utf-8") as handle:
    lines = handle.read().splitlines()

pattern_counts = dict.fromkeys(SEVERITIES, 0)
naive_counts = dict.fromkeys(SEVERITIES, 0)

for line in lines:
    m = UVM.match(line)
    if m is not None:
        pattern_counts[m["sev"]] += 1
    for sev in SEVERITIES:
        if "UVM_" + sev in line:
            naive_counts[sev] += 1

print(f"{'severity':<10} {'naive':>6} {'pattern':>8}")
for sev in SEVERITIES:
    print(f"{sev:<10} {naive_counts[sev]:>6} {pattern_counts[sev]:>8}")

severity    naive  pattern
INFO            6        5
WARNING         2        1
ERROR           3        2
FATAL           1        0

Every severity over-counted by exactly one, because the summary block contains exactly one line per severity. That uniformity is what makes the bug so easy to live with: it looks like an off-by-one, which feels like a small arithmetic slip, when it is actually a category mistake — counting descriptions of messages as messages.

And FATAL is the row that matters. Naive: 1. Real: 0. A triage script keyed on fatals > 0 escalates every run it ever sees.

dict.fromkeys(SEVERITIES, 0) is Chapter 20.6's always-present rule in one line: all four keys exist before the loop, so FATAL reads 0 rather than being absent.

4. The First Failure

The canonical annotation does both jobs in one pass:

m = UVM.search(line)
if m:
    counts[m.group(1)] += 1
    if first is None:
        first = line.strip()

Keeping the whole line is the minimum. Keeping the parsed fields is better, because a report wants the time and the hierarchy path as values:

UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_WARNING mon.sv(51) @ 99300: uvm_test_top.env.agt.mon [SMP] late sample ignored
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write to 0x40001000 returned 0xdeadbeef
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] response timeout after 2000 ns
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] axi_wr_rd_seq done

import re

UVM = re.compile(
    r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
    r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
    r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
    r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)

FAILING = ("ERROR", "FATAL")

counts = dict.fromkeys(["INFO", "WARNING", "ERROR", "FATAL"], 0)
first = None

with open("sim.log", encoding="utf-8") as handle:
    for line in handle:
        m = UVM.match(line)
        if m is None:
            continue
        counts[m["sev"]] += 1
        if m["sev"] in FAILING and first is None:
            first = m.groupdict()
            first["raw"] = line.rstrip()

print("counts:", counts)
print()
print("first failure")
print("  severity:", first["sev"])
print("  at time :", int(first["time"]))
print("  source  :", f"{first['file']}:{first['line']}")
print("  scope   :", first["scope"])
print("  id      :", first["id"])
print("  message :", first["msg"])

counts: {'INFO': 2, 'WARNING': 1, 'ERROR': 2, 'FATAL': 0}

first failure
  severity: ERROR
  at time : 141900
  source  : drv.sv:88
  scope   : uvm_test_top.env.agt.drv
  id      : WR
  message : write to 0x40001000 returned 0xdeadbeef

Six fields, one pass, no second read of the file. That block is what a debug session starts from: it says what failed, when, which line of which file reported it, which component in the hierarchy, and what the component said.

int(first["time"]) is there deliberately. Every group is a string — Chapter 19.8 Section 3 — and a time that stays text sorts as text, so "99300" would come after "141900". Convert at the boundary.

5. First, Not Worst

first is first by position in the log, which is not the same as most severe. A run with two errors and a later fatal keeps the error:

LINES = [
    "UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] bad handshake",
    "UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] timeout",
    "UVM_FATAL env.sv(12) @ 180500: uvm_test_top.env [BLD] too many errors, aborting",
]

first = None
worst = None
RANK = {"ERROR": 1, "FATAL": 2}

for line in LINES:
    sev = line.split()[0].replace("UVM_", "")
    if first is None:
        first = (sev, line.split("@ ")[1].split(":")[0])
    if worst is None or RANK[sev] > RANK[worst[0]]:
        worst = (sev, line.split("@ ")[1].split(":")[0])

print("first:", first)
print("worst:", worst)

first: ('ERROR', '141900')
worst: ('FATAL', '180500')

Both are computable and they are different lines. Keep the first. The reason is a judgment about simulation rather than a property of Python: in a testbench, later failures are usually consequences of earlier ones. The fatal above says "too many errors, aborting", which is caused by the two errors and tells a debugger nothing. The bad handshake at 141900 is where the run actually went wrong.

A report can carry both if it wants, and most do not need to — the counts already say a fatal occurred.

6. The Parser That Checks Itself

The log contains the simulator's own tallies. A parser can compare its answer with them and say so when they disagree:

UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO tb_top.sv(142) @ 0: uvm_test_top [CFG] clk period 2000 ps
UVM_INFO env.sv(61) @ 0: uvm_test_top.env [BLD] built 1 agent, 1 scoreboard
UVM_WARNING mon.sv(51) @ 99300: uvm_test_top.env.agt.mon [SMP] late sample ignored
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write returned 0xdeadbeef
UVM_INFO scb.sv(120) @ 160000: uvm_test_top.env.scb [CHK] 160 transactions compared
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] response timeout
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] axi_wr_rd_seq done
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :    5
UVM_WARNING :    1
UVM_ERROR :    2
UVM_FATAL :    0
TEST DONE

import re

UVM = re.compile(
    r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
    r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
    r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
    r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)
TALLY = re.compile(r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)\s*:\s*(?P<n>\d+)\s*$")

SEVERITIES = ["INFO", "WARNING", "ERROR", "FATAL"]

counted = dict.fromkeys(SEVERITIES, 0)
reported = {}

with open("sim.log", encoding="utf-8") as handle:
    for line in handle:
        m = UVM.match(line)
        if m is not None:
            counted[m["sev"]] += 1
            continue
        t = TALLY.match(line)
        if t is not None:
            reported[t["sev"]] = int(t["n"])

print(f"{'severity':<10} {'counted':>8} {'reported':>9}  agree")
for sev in SEVERITIES:
    mine = counted[sev]
    theirs = reported.get(sev)
    print(f"{sev:<10} {mine:>8} {str(theirs):>9}  {mine == theirs}")

print()
print("parser agrees with the simulator:", counted == reported)

severity    counted  reported  agree
INFO              5         5  True
WARNING           1         1  True
ERROR             2         2  True
FATAL             0         0  True

parser agrees with the simulator: True

That last line is a test the parser runs on itself, on every real log, for free. Nobody wrote a sample list; the expected values were in the file.

What it would catch is exactly the failure Chapter 20.6 Section 4 described: a tool release changes the message format, the pattern stops matching, counted goes to zero and reported does not. The parser would then know its own answer is wrong — which is strictly better than an unparsed ratio, because it is a direct comparison rather than a heuristic.

Two limits worth being honest about. The summary block is absent from a truncated or timed-out log, so reported is {} and the comparison cannot be made — which is itself information, and Chapter 20.12 uses it. And a log with +UVM_VERBOSITY set low may have INFO messages filtered out of the body but still tallied, so the INFO row can legitimately disagree; the rows that matter for a verdict are ERROR and FATAL.

7. Predict, Run, Observe

import re

UVM = re.compile(
    r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
    r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
    r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
    r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)

A = "UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] bad handshake"
B = "UVM_ERROR :    2"
C = "UVM_INFO @ 0: reporter [RNTST] starting"
D = "UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv bad handshake"

# A
print("A:", UVM.match(A)["sev"], UVM.match(A)["time"], UVM.match(A)["id"])

# B
print("B:", UVM.match(B))

# C
print("C:", UVM.match(C)["file"], UVM.match(C)["scope"])

# D
print("D:", UVM.match(D)["id"], repr(UVM.match(D)["msg"]))

# E
print("E:", type(UVM.match(A)["time"]).__name__)

# F
print("F:", "99300" > "141900", int("99300") > int("141900"))

The verified output:

A: ERROR 141900 WR
B: None
C: None reporter
D: None 'bad handshake'
E: str
F: True False

A — three fields from one match, all strings.

B — the summary line is rejected, because it has no @ <time>:. The whole chapter in one None.

C — no file field, and the optional group leaves it None while the match still succeeds. A required file group would have dropped this line and broken the INFO count.

D — no bracketed id, and the message is still captured correctly. Two optional groups, independently absent.

E — every group is a string, including the time.

F — and that is why: as text, 99300 sorts after 141900. A report ordering failures by an unconverted time gets them backwards.

8. Exercises

Exercise 1 — the distinguishing fact. Put a real UVM message next to a summary tally line and list every difference. Say which one you would build a pattern on and why.

Exercise 2 — build it in stages. Assemble the message pattern using Chapter 19.12's method, one construct at a time, and write the symbol table for the finished version.

Exercise 3 — the optional file. Run your pattern against the UVM reporter line that has no file(line) field. Make the group required and record which count changes.

Exercise 4 — naive versus pattern. Build Section 3's four-row table for a log of your own. Confirm the over-count is exactly one per severity and explain why.

Exercise 5 — the fatal row. Say what a triage script keyed on fatals > 0 does with the naive count, for every log it will ever see.

Exercise 6 — always-present keys. Use dict.fromkeys to seed your counts. Show that a clean log reports FATAL: 0 rather than omitting the key.

Exercise 7 — the first failure. Keep the first failing match as a dict of fields and print all six. Convert the time to an integer and say where the conversion belongs.

Exercise 8 — first versus last. Remove the is None guard and record which failure you now keep. Say which a debugger wants.

Exercise 9 — first versus worst. On a log whose fatal comes after two errors, compute both. Say which you would store and give the simulation-level reason.

Exercise 10 — the self-check. Parse the summary block and compare it with your counts. Then deliberately break your pattern and confirm the comparison reports disagreement.

Exercise 11 — the honest limits. Name two situations in which counted != reported without your parser being wrong, and say what your code should do in each.

9. Summary

• A UVM message and a summary tally both start with the severity, which is why startswith fixes nothing.
• A message carries a simulation time and a tally does not. \s+@\s+(?P<time>\d+): is the clause that separates them.
• The source location is optional — the reporter's own messages have none, and a required file group silently drops them.
• Every severity is over-counted by exactly one by a substring test, because the summary block has one line per severity. It looks like an off-by-one and is a category mistake.
• Naive FATAL is 1 on a log with none, so a triage script keyed on fatals escalates every run.
• dict.fromkeys(SEVERITIES, 0) gives Chapter 20.6's always-present keys in one line.
• Keep the parsed fields, not just the line — severity, time, file, line, scope, id and message are what a report needs.
• if first is None is what makes it first; a plain assignment keeps the last.
• First is not worst. A later fatal is usually a consequence of the first error, so the first failure is the one a debugger wants.
• Convert the time at the boundary. As text, 99300 sorts after 141900.
• The log contains the simulator's own tallies, so the parser can compare its counts with them and report disagreement — a test with no sample list, run on every real log.
• Disagreement is a parser bug until proved otherwise, and Chapter 19.17's routine finds it.
• The comparison is unavailable on a truncated log and may legitimately differ on INFO when verbosity filtering is on; ERROR and FATAL are the rows a verdict depends on.

The next chapter recovers the two facts that let a failure be reproduced at all: which test ran, and with which seed.