The First Failure and Its Context

Part II · Module 20 · Chapter 20.10 · The First Failure and Its Context

1. What the Failing Line Does Not Say

Here is the first failure from Chapter 20.7, on its own:

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

It says what, when, where and who. It does not say what the driver had just issued, what the monitor sampled a hundred picoseconds earlier, or what the testbench did next — and those are the first three things anybody looks at.

In practice the engineer opens the log and scrolls to the error, which is a manual version of something a parser can do once and put in a report:

UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [SMP] sampled resp=0xdeadbeef
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write returned 0xdeadbeef
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying once

Four lines instead of one, and the story is now visible: the driver issued a write, the monitor sampled the response, the response was wrong, and the driver retried. A triage report containing that block is one an engineer can act on without opening anything.

2. The Problem With One Pass

Chapter 20.6 decided the parser makes a single pass, and that decision has a consequence here. At the moment the failing line arrives:

• the lines before it have already been read and discarded;
• the lines after it have not been read yet.

Those are two different problems needing two different mechanisms, and the canonical annotation addresses only the first:

if first is None and UVM.search(line):
    first = line.strip()
    context = recent[-5:] + [line]

recent[-5:] works because something has been keeping the recent lines. Section 3 is that. Section 5 is the other half, which is the one people leave out — and leaving it out is easy to miss, because a context block with five lines before and nothing after still looks like context.

3. Keeping the Lines Before

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 seq.sv(88) @ 20000: uvm_test_top.env.agt.seqr [SEQ] starting axi_wr_rd_seq
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [SMP] sampled resp=0xdeadbeef
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write returned 0xdeadbeef
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying once
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] done

BEFORE = 3

recent = []
first = None
context_before = []

with open("ctx.log", encoding="utf-8") as handle:
    for line in handle:
        stripped = line.rstrip()
        if first is None and stripped.startswith("UVM_ERROR"):
            first = stripped
            context_before = recent[-BEFORE:]
        recent.append(stripped)
        if len(recent) > BEFORE:
            recent.pop(0)

print("lines held at the end:", len(recent))
print()
for line in context_before:
    print("     ", line[:58])
print("  >>>", first[:58])

lines held at the end: 3

      UVM_INFO seq.sv(88) @ 20000: uvm_test_top.env.agt.seqr [SE
      UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR
      UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [SM
  >>> UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [W

Three lines kept, and — the line that matters — three lines held at the end, on a log of any length.

The mechanism is four lines and the last two are the whole point:

recent.append(stripped)
if len(recent) > BEFORE:
    recent.pop(0)

append adds the new line; pop(0) removes the oldest once the list is longer than needed. The list is a ring buffer: it holds exactly BEFORE lines forever. That is Chapter 15.7 Section 5's "carry a bounded summary, not a growing list", in its most tempting form — because the version without the prune is shorter:

LINES = ["line %d" % n for n in range(1, 9)]
BEFORE = 3

unbounded = []
bounded = []

for line in LINES:
    unbounded.append(line)
    bounded.append(line)
    if len(bounded) > BEFORE:
        bounded.pop(0)

print("unbounded holds:", len(unbounded), unbounded[-3:])
print("bounded holds  :", len(bounded), bounded)

unbounded holds: 8 ['line 6', 'line 7', 'line 8']
bounded holds  : 3 ['line 6', 'line 7', 'line 8']

Both give the right answer for recent[-3:]. One of them holds eight lines and the other holds three, and on an eight-line log that difference is invisible — which is exactly why the unpruned version gets written and survives. On a twenty-million-line log it holds twenty million lines, and the parser that was carefully built to stream is now loading the file.

4. Keeping the Lines After

The other half. When the failure is found, the following lines have not been read — so the parser has to remember that it owes them:

UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO seq.sv(88) @ 20000: uvm_test_top.env.agt.seqr [SEQ] starting axi_wr_rd_seq
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [SMP] sampled resp=0xdeadbeef
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write returned 0xdeadbeef
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying once
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] done

BEFORE = 3
AFTER = 2

recent = []
first = None
context_before = []
context_after = []
pending = 0

with open("ctx.log", encoding="utf-8") as handle:
    for line in handle:
        stripped = line.rstrip()

        if pending:
            context_after.append(stripped)
            pending -= 1

        if first is None and stripped.startswith("UVM_ERROR"):
            first = stripped
            context_before = recent[-BEFORE:]
            pending = AFTER

        recent.append(stripped)
        if len(recent) > BEFORE:
            recent.pop(0)

for line in context_before:
    print("     ", line[:56])
print("  >>>", first[:56])
for line in context_after:
    print("     ", line[:56])

      UVM_INFO seq.sv(88) @ 20000: uvm_test_top.env.agt.seqr [
      UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [
      UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [
  >>> UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv 
      UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [
      UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv

A six-line block from one pass over the file, holding at most five lines at a time.

pending is the whole mechanism: it is set to AFTER when the failure is found and counted down on each subsequent line. A plain if collecting_after: boolean would collect to the end of the log; the counter is what bounds it.

The order of the two if blocks matters and is not arbitrary. The pending check comes first, so the failing line itself is not added to context_after — at the moment the failure arrives, pending is still 0. Swap them and the failing line appears twice, once as first and once as the first line of the after-context. That is the kind of mistake that produces a report which looks almost right.

5. The After-Window Can Contain Another Failure

Look at the last line of that block: the second UVM_ERROR, at 180400. It is in the context because it is within two lines of the first failure, and keeping it is correct.

This is worth stating because context_after is easy to misread as "the normal lines following the failure". It is not. It is the next few lines, whatever they are, and when a failure is immediately followed by related failures that is precisely the most informative thing the block can contain — a driver error followed by a timeout is a different story from a driver error followed by the sequence completing normally.

The one thing to be careful of is counting. context_after is for a human to read; the errors tally from Chapter 20.7 is what a verdict uses. A report that counted the lines in the context block would double-count that second error.

6. How Much Context

BEFORE = 3, AFTER = 2 is a choice, and the trade is concrete:

Memory is not the deciding factor — a twenty-line buffer is still bounded and still trivial. The deciding factor is the report: a regression summary over five hundred logs with twenty-line context blocks is ten thousand lines nobody opens, and the tool stops being read for the same reason Chapter 20.2's checker would have been switched off.

The usual compromise is a small window in the summary and the log path next to it, so the block gives the shape of the failure and the path gives everything else. Chapter 20.16 records both for that reason.

7. Putting It in the Record

UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.mon [SMP] sampled resp=0xdeadbeef
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] write returned 0xdeadbeef
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying once
UVM_INFO seq.sv(140) @ 200000: uvm_test_top.env.agt.seqr [SEQ] done

import re

UVM_FAIL = re.compile(r"^UVM_(?P<sev>ERROR|FATAL)\b.*@\s+(?P<t>\d+):")
BEFORE = 2
AFTER = 1


def parse(path):
    """One pass: counts, the first failure, and the lines around it."""
    record = {"errors": 0, "fatals": 0, "first_failure": None,
              "context": [], "context_marker": None}
    recent = []
    pending = 0
    after = []

    with open(path, encoding="utf-8") as handle:
        for line in handle:
            stripped = line.rstrip()

            if pending:
                after.append(stripped)
                pending -= 1

            m = UVM_FAIL.match(stripped)
            if m is not None:
                record["errors" if m["sev"] == "ERROR" else "fatals"] += 1
                if record["first_failure"] is None:
                    record["first_failure"] = stripped
                    record["context"] = recent[-BEFORE:]
                    record["context_marker"] = len(record["context"])
                    pending = AFTER

            recent.append(stripped)
            if len(recent) > BEFORE:
                recent.pop(0)

    record["context"] = record["context"] + [record["first_failure"]] + after \
        if record["first_failure"] is not None else []
    return record


r = parse("ctx.log")
print("errors :", r["errors"], " fatals:", r["fatals"])
print("marker :", r["context_marker"])
for index, line in enumerate(r["context"]):
    prefix = ">>>" if index == r["context_marker"] else "   "
    print(f"  {prefix} {line[:52]}")

errors : 1  fatals: 0
marker : 2
      UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.d
      UVM_INFO mon.sv(44) @ 141800: uvm_test_top.env.agt.m
  >>> UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.
      UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.d

One list, plus an index saying which element is the failure. That shape is better than three separate keys for a reason Chapter 20.16 depends on: context goes into a CSV cell or a JSON array as one value, and context_marker tells a renderer where to put the arrow.

context_marker is computed as len(record["context"]) before the failing line is appended, which is the index the failing line will have. Capturing it at that moment rather than recomputing later is what keeps it correct when BEFORE lines were not available — on a failure in the first line of the log, context_before is empty and the marker is 0.

Note the final assembly line. Building context as before + failure + after at the end rather than incrementally is what lets after keep filling during the loop without the list having to be spliced each time.

8. Predict, Run, Observe

LINES = ["a", "b", "c", "FAIL1", "d", "FAIL2", "e"]
BEFORE, AFTER = 2, 2

recent, first, before, after, pending = [], None, [], [], 0
for line in LINES:
    if pending:
        after.append(line)
        pending -= 1
    if first is None and line.startswith("FAIL"):
        first = line
        before = recent[-BEFORE:]
        pending = AFTER
    recent.append(line)
    if len(recent) > BEFORE:
        recent.pop(0)

# A
print("A:", before)

# B
print("B:", first)

# C
print("C:", after)

# D
print("D:", len(recent))

# E
print("E:", recent)

# F
print("F:", ["x"][-5:], [][-5:])

The verified output:

A: ['b', 'c']
B: FAIL1
C: ['d', 'FAIL2']
D: 2
E: ['FAIL2', 'e']
F: ['x'] []

A — the two lines before, from the ring buffer.

B — the first failure, not the second. The is None guard again.

C — two lines after, and the second one is another failure. Section 5.

D and E — at the end the buffer still holds exactly BEFORE lines, and they are the last two of the log. Bounded, whatever the log.

F — a negative slice longer than the list returns the whole list, and on an empty list returns []. That is why recent[-BEFORE:] needs no guard for a failure in the first few lines.

9. Exercises

Exercise 1 — one line is not enough. Take a failing line from a real log and write down three questions it does not answer. Say which lines would answer them.

Exercise 2 — the two directions. Explain in two sentences why the lines before and the lines after need different mechanisms in a single pass.

Exercise 3 — the ring buffer. Implement the before-context with append and pop(0). Print how many lines are held at the end of a long log.

Exercise 4 — forget the prune. Remove the pop(0) and confirm the context is still correct. Then print the buffer's length and say what it would be on a twenty-million-line log.

Exercise 5 — the countdown. Implement the after-context with a pending counter. Confirm it stops after exactly AFTER lines.

Exercise 6 — a boolean instead. Replace pending with a collecting = True flag and no countdown. Record how many lines you collect.

Exercise 7 — the order of the ifs. Swap the two if blocks and record what appears twice in your output.

Exercise 8 — a failure in the window. Build a log where a second failure falls inside the after-window. Confirm it appears in the context and say why that is correct.

Exercise 9 — do not double count. Say what goes wrong if a verdict counts failures by scanning the context block instead of using the tally.

Exercise 10 — the first line. Put the failure on line 1 of the log. Confirm the before-context is empty, nothing raises, and the marker is 0.

Exercise 11 — window size. Produce a summary over ten logs with a 3-line window and with a 20-line window. Count the total lines of each and say which one gets read.

10. Summary

• The failing line says what, when, where and who, and not what led to it — which is what a debugger looks at first.
• A single pass meets the two halves of the context at different times: the lines before have gone, the lines after have not arrived.
• The canonical recent[-5:] solves only the before half, and a one-sided context still looks like context.
• A ring buffer keeps the lines before: append, then pop(0) once the list exceeds the window.
• The version without the prune is shorter and gives the same answer on every log small enough to test with — and holds the entire file on a real one.
• collections.deque(maxlen=N) is the production tool; the explicit prune is used here because seeing it is the point.
• A pending countdown keeps the lines after, and bounds them where a boolean flag would collect to the end of the log.
• Check pending before testing for the failure, or the failing line appears twice.
• The after-window can contain another failure, and that is correct and informative — but the verdict must count from the tally, never from the context block.
• Window size is a report decision, not a memory one. Twenty lines over five hundred logs is a report nobody opens.
• Context tells a reader whether this is the failure they are looking for. It is not a substitute for the log.
• Store one list plus a marker index, computed as the length of the before-context at the moment the failure is found.
• A negative slice longer than the list returns the whole list, so a failure on line 1 needs no special case.

The next chapter turns all of these facts into a verdict — and makes the case that two outcomes are not enough.