Keeping Real Tool Output as Test Data

Part II · Module 27 · Chapter 27.2 · Keeping Real Tool Output as Test Data

1. Tested Against What the Author Expected

Here is how a parser usually acquires its first tests. The author knows roughly what the simulator prints — errors start with ERROR, the end of a run says $finish — so they write a parser around that knowledge and a handful of small example logs to test it with. The examples are typed from the same knowledge.

The script below does exactly that, then runs the same parser against the six real logs from Chapter 27.1.

use strict;
use warnings;

# A parser written from memory of what the simulator prints ...
sub guess_parse {
    my ($path) = @_;
    open my $fh, "<", $path or die "$path: $!\n";
    my ($err, $fatal, $done) = (0, 0, 0);
    while (my $line = <$fh>) {
        $err++    if $line =~ /^ERROR/;
        $fatal++  if $line =~ /^FATAL/;
        $done = 1 if $line =~ /^\$finish/;
    }
    close $fh;
    return $fatal ? "FAIL" : !$done ? "NO_FINISH" : $err ? "FAIL" : "PASS";
}

# ... tested against logs written from the same memory.
my %GUESS = (
    "guess/pass.log"   => [ "TEST PASSED\n\$finish called\n",       "PASS"      ],
    "guess/fail.log"   => [ "ERROR: mismatch\n\$finish called\n",   "FAIL"      ],
    "guess/fatal.log"  => [ "FATAL: overflow\n",                     "FAIL"      ],
    "guess/killed.log" => [ "test running\n",                        "NO_FINISH" ],
);
mkdir "guess";
my $ok = 0;
for my $f (sort keys %GUESS) {
    open my $o, ">", $f or die; print {$o} $GUESS{$f}[0]; close $o;
    my $got = guess_parse($f);
    $ok++ if $got eq $GUESS{$f}[1];
    printf "  %-22s want %-9s got %-9s %s\n", $f, $GUESS{$f}[1], $got, $got eq $GUESS{$f}[1] ? "ok" : "WRONG";
}
printf "against the hand-written logs: %d of %d right\n\n", $ok, scalar keys %GUESS;

# The same parser against the real simulator's logs.
my %TRUTH = (pass => "PASS", mismatch => "FAIL", sv_error => "FAIL",
             finish_1 => "FAIL", sv_fatal => "FAIL", killed => "NO_FINISH");
$ok = 0;
for my $t (sort keys %TRUTH) {
    my $f = "t/data/icarus_$t.log";
    my $got = guess_parse($f);
    $ok++ if $got eq $TRUTH{$t};
    printf "  %-28s want %-9s got %-9s %s\n", $f, $TRUTH{$t}, $got, $got eq $TRUTH{$t} ? "ok" : "WRONG";
}
printf "against the real logs: %d of %d right\n", $ok, scalar keys %TRUTH;

  guess/fail.log         want FAIL      got FAIL      ok
  guess/fatal.log        want FAIL      got FAIL      ok
  guess/killed.log       want NO_FINISH got NO_FINISH ok
  guess/pass.log         want PASS      got PASS      ok
against the hand-written logs: 4 of 4 right

  t/data/icarus_finish_1.log   want FAIL      got NO_FINISH WRONG
  t/data/icarus_killed.log     want NO_FINISH got NO_FINISH ok
  t/data/icarus_mismatch.log   want FAIL      got NO_FINISH WRONG
  t/data/icarus_pass.log       want PASS      got NO_FINISH WRONG
  t/data/icarus_sv_error.log   want FAIL      got NO_FINISH WRONG
  t/data/icarus_sv_fatal.log   want FAIL      got FAIL      ok
against the real logs: 2 of 6 right

Four of four against the hand-written logs. Two of six against the real tool.

And the two real "rights" are not really right. Read the got column: the parser says NO_FINISH for every real log except the fatal one. It got the killed run right because it gets everything NO_FINISH, and the fatal run right because FATAL happens to start a line in both the guess and the reality. The parser does not recognise a single real finished run.

The cause is one character position. The author remembered that the simulator prints $finish, and wrote /^\$finish/ — $finish at the start of a line. The real simulator prints tb/pass.v:4: $finish called at 0 (1s): the source file and line come first. The hand-written logs put $finish at the start of the line, because the same person wrote them.

2. Why Hand-Written Logs Always Agree

This is not bad luck in one example. It is structural.

When the same person writes the parser and the examples, every assumption in the parser is also in the examples. A test can only find a difference between two things, and here there is no difference to find: the examples are a second copy of the assumptions. The suite is guaranteed to pass, and that guarantee is exactly why it proves nothing about the tool.

Real output differs from remembered output in ways nobody remembers, because they are small and nobody was looking for them. In just six short Icarus logs:

• The $finish line starts with file:line:.
• $finish(1) is spelled differently from $finish.
• $error and $fatal print a second, indented Time: ... Scope: ... line.
• A fatal run never prints a $finish line at all.
• A killed run prints nothing to say it was killed.

Any of these can defeat a parser, and none of them is in the guessed examples. A parser is only tested against a tool's behaviour when its test inputs came from the tool.

3. Capture, Never Type

Golden fixtures are real tool output, saved as test data. The rule that makes them trustworthy is simple: they are produced by running the tool, by a script, and never typed or edited by hand.

These are the testbenches that produce them — the same run endings Chapter 26.7 measured, one per behaviour a parser must handle:

module tb;
  initial begin
    $display("TEST PASSED");
    $finish;
  end
endmodule

module tb;
  initial begin
    $display("ERROR: data mismatch exp=5 got=4");
    $display("TEST FAILED");
    $finish;
  end
endmodule

module tb;
  initial begin
    $error("data mismatch exp=5 got=4");
    $finish;
  end
endmodule

module tb;
  initial begin
    $display("TEST FAILED");
    $finish(1);
  end
endmodule

module tb;
  initial begin
    $fatal(1, "scoreboard overflow");
  end
endmodule

module tb;
  reg clk = 0;
  always #5 clk = ~clk;      // no $finish anywhere: runs until stopped
  initial $display("waiting for a handshake that never comes");
endmodule

And the capture script. It compiles and runs each testbench, writes each log, and records where every fixture came from in a manifest beside them:

#!/bin/bash
# capture_fixtures.sh -- regenerate every golden log from the REAL simulator.
# Fixtures are never typed and never edited: they are re-captured.
# Usage: capture_fixtures.sh OUTDIR
set -euo pipefail
out=${1:?usage: capture_fixtures.sh OUTDIR}
mkdir -p "$out"

version=$(iverilog -V 2>/dev/null | sed -n 1p)   # sed reads everything: no SIGPIPE (26.1)
manifest="$out/MANIFEST"
{
    echo "# golden logs: captured, never edited -- regenerate with capture_fixtures.sh"
    echo "# simulator: $version"
} > "$manifest"

run() {                                   # run NAME [LIMIT_SECONDS]
    local name=$1 limit=${2:-}
    iverilog -g2012 -o "$out/$name.vvp" "tb/$name.v"
    if [ -n "$limit" ]; then              # a run that must be stopped from outside
        vvp -n "$out/$name.vvp" > "$out/icarus_$name.log" 2>&1 &
        local pid=$!
        sleep "$limit"
        kill -TERM "$pid"
        wait "$pid" || true
        echo "icarus_$name.log  vvp -n $name.vvp, stopped with TERM after ${limit}s" >> "$manifest"
    else
        vvp -n "$out/$name.vvp" > "$out/icarus_$name.log" 2>&1 || true
        echo "icarus_$name.log  vvp -n $name.vvp" >> "$manifest"
    fi
    rm -f "$out/$name.vvp"
}

run pass; run mismatch; run sv_error; run finish_1; run sv_fatal
cp tb/hang.v tb/killed.v                  # the killed fixture is the hang bench, stopped
run killed 0.5

Three details of the script matter.

The manifest. The first line it writes records the simulator's own version string, and each fixture gets a line saying exactly which command produced it. Six months later, when a fixture and the tool disagree, the manifest answers the first question — which version of the tool wrote this? — without anyone having to remember. It is Chapter 26.8's run record, applied to test data.

The killed run is produced, not imitated. It is the hanging testbench, started for real and stopped with TERM after half a second — so its log is genuinely what a killed simulation leaves behind. Writing one by hand would mean guessing what a killed run looks like, and section 1 showed where guessing leads.

sed -n 1p, not head -n 1. The script runs under pipefail (Chapter 26.1). head exits after one line, and if the program writing into the pipe has more to say, that program can be killed by SIGPIPE — which pipefail reports as a failure. On this machine the version output fits in the pipe and the head version happened to work. sed -n 1p reads everything and prints the first line, so it cannot fail that way on any machine.

4. Re-Capture to Detect a Tool Change

Because the fixtures come from a script, they can be re-made at any time and compared with the stored copies. On the same tool version, the comparison should find nothing:

#!/bin/bash
bash capture_fixtures.sh fresh
sed 's/^/  /' fresh/MANIFEST
same=0
for f in t/data/icarus_*.log; do
    if cmp -s "$f" "fresh/$(basename "$f")"; then same=$((same + 1)); else echo "  CHANGED: $f"; fi
done
echo "$same of $(ls t/data/icarus_*.log | wc -l | tr -d ' ') stored fixtures are byte-identical to a fresh capture"

  # golden logs: captured, never edited -- regenerate with capture_fixtures.sh
  # simulator: Icarus Verilog version 13.0 (stable) (v13_0)
  icarus_pass.log  vvp -n pass.vvp
  icarus_mismatch.log  vvp -n mismatch.vvp
  icarus_sv_error.log  vvp -n sv_error.vvp
  icarus_finish_1.log  vvp -n finish_1.vvp
  icarus_sv_fatal.log  vvp -n sv_fatal.vvp
  icarus_killed.log  vvp -n killed.vvp, stopped with TERM after 0.5s
6 of 6 stored fixtures are byte-identical to a fresh capture

Six of six identical. That is the expected result, and it is also a test of the tool. The day the simulator is upgraded and a fresh capture differs from the stored one, the difference is the news: the output format changed, and every parser that reads it needs to be checked before the new version goes into production. Without re-capture, the first sign of a format change is a wrong answer in a nightly report.

When a change does appear, do not overwrite the old fixture. Keep both, named for the version that produced them, and make the tests run the parser against both. A flow nearly always has more than one tool version in use at once — Chapter 18.8's version-tolerance problem — and the parser has to keep handling the old one until nobody uses it.

5. Short Extracts of Long Logs, Checked

Real production logs are long. A regression log can run to hundreds of thousands of lines, and a test suite full of them is slow, hard to read, and impossible to review. Fixtures should be short — but cutting a real log is exactly where a fixture can quietly stop being real.

To show it, a testbench that prints two thousand lines of progress and then passes:

module tb;
  integer i;
  initial begin
    for (i = 0; i < 2000; i = i + 1)
      $display("INFO: cycle %0d: scoreboard ok", i);
    $display("TEST PASSED");
    $finish;
  end
endmodule

The usual way to cut a log is to keep the start of it. The script below does something more careful: it keeps the first and last three lines plus every line the parser looks at, then runs the parser on both the full log and the extract and refuses the extract if any fact differs.

#!/usr/bin/perl
# extract_fixture.pl FULL_LOG OUT -- cut a long real log down to a small
# fixture that the parser reads EXACTLY as it reads the full log.
use strict;
use warnings;
use FindBin qw($Bin);
use lib "$Bin/lib";
use VLSI::Report qw(parse_log);

my ($full, $out) = @ARGV;
die "usage: extract_fixture.pl FULL_LOG OUT\n" unless defined $out;

open my $in, "<", $full or die "$full: $!\n";
my @lines = <$in>;
close $in;

# Keep the first and last three lines, and every line the parser looks at.
my $MATTERS = qr/^(?:ERROR: |FATAL: |TEST (?:PASSED|FAILED)$)|\$finish/;
my %keep = map { $_ => 1 } 0 .. 2, $#lines - 2 .. $#lines;
$keep{$_} = 1 for grep { $lines[$_] =~ $MATTERS } 0 .. $#lines;

open my $o, ">", $out or die "$out: $!\n";
print {$o} $lines[$_] for sort { $a <=> $b } grep { $_ >= 0 && $_ <= $#lines } keys %keep;
close $o;

# The check that makes it a fixture: same facts from both files.
my ($whole, $cut) = (parse_log($full), parse_log($out));
my @differ = grep { ($whole->{$_} // "") ne ($cut->{$_} // "") } qw(verdict errors fatals finished result);
printf "%s: %d lines -> %d lines, %s\n", $out, $whole->{lines}, $cut->{lines},
    @differ ? "FACTS CHANGED: @differ" : "same verdict ($cut->{verdict}) and counts";
exit(@differ ? 1 : 0);

#!/bin/bash
iverilog -g2012 -o long.vvp tb/long_pass.v && vvp -n long.vvp > long_pass.log
echo "the full log: $(wc -l < long_pass.log | tr -d ' ') lines"

echo "--- extract_fixture.pl"
perl extract_fixture.pl long_pass.log icarus_long_pass.log
sed 's/^/  | /' icarus_long_pass.log

echo "--- the usual cut: head -n 20"
head -n 20 long_pass.log > cut.log
perl -Ilib -MVLSI::Report=parse_log -e 'print "  verdict of the cut: ", parse_log("cut.log")->{verdict}, "\n"'

the full log: 2002 lines
--- extract_fixture.pl
icarus_long_pass.log: 2002 lines -> 6 lines, same verdict (PASS) and counts
  | INFO: cycle 0: scoreboard ok
  | INFO: cycle 1: scoreboard ok
  | INFO: cycle 2: scoreboard ok
  | INFO: cycle 1999: scoreboard ok
  | TEST PASSED
  | tb/long_pass.v:7: $finish called at 0 (1s)
--- the usual cut: head -n 20
  verdict of the cut: NO_FINISH

Two thousand and two lines became six, with the same verdict and the same counts. The first three and last progress lines are kept as context, so a reader can see what kind of log it was, and every line that carries a fact the parser uses is there.

The usual cut changed the answer. head -n 20 kept twenty lines of progress and none of the ending — so the parser, correctly, reported a run with no $finish line as NO_FINISH. The fixture would now be testing the parser's handling of a truncated log while its name and its author both believed it was a pass. That is Chapter 18.9's truncated-log case, created by the person cutting the fixture.

The check at the end of extract_fixture.pl is what makes the difference. An extract is a fixture only if the parser reads it the way it reads the original — and the only way to know that is to run the parser on both. A cut that changes a fact exits 1.

6. The Rules for a Fixture Set

Putting the chapter together, a golden fixture set that can be trusted follows these rules:

The table is also a description of the files Chapters 27.3 to 27.5 test against. Those six logs in t/data were captured by the script in section 3, and section 4 proved they are still exactly what the tool prints.

7. Exercises

1. Improve the guess. Fix guess_parse so it handles all six real logs correctly, without looking at the module from Chapter 27.1. Then write down every assumption your fixed version still makes about the logs. Which of them would a seventh real log — say, a run that prints TEST PASSED and then hits $fatal — break?

2. A fixture for a new behaviour. Add a testbench whose run ends with a $warning and then passes. Capture it with capture_fixtures.sh, look at the real output, and decide what parse_log should report. Is a warning-only run a PASS? Where in the module's contract does that decision belong?

3. Detect a change on purpose. Simulate a tool upgrade by editing one testbench so its $display text changes, re-run recapture.sh, and confirm it reports exactly that fixture as changed. Then explain why a fixture comparison like this would also catch someone hand-editing a stored fixture.

4. The extractor's own copy. extract_fixture.pl decides what to keep with its own pattern, $MATTERS — a second copy of what the parser reads, which is Chapter 27.1's drift problem in miniature. Add a warnings count to parse_log (lines starting WARNING: ) and add warnings to the extractor's comparison list, but leave $MATTERS alone. Capture a long log containing warnings, run the extractor, and confirm its check now exits 1. Then remove the duplication: how could the module tell the extractor which lines matter?

5. Inventory your own fixtures. For a parser you maintain, list its test inputs and mark each one: captured from the tool, or typed? For every typed one, write down which assumption it encodes, and how you would capture a real equivalent.

8. What To Remember

• A parser tested against logs its author typed is tested against the author's memory. Measured: 4 of 4 on typed logs, 2 of 6 on real ones.
• Both real "rights" were accidents — the parser called almost every real log NO_FINISH.
• One remembered detail was wrong: real Icarus prints file:line: $finish called at ..., not $finish at the start of a line.
• Typed examples share every assumption of the parser, so the suite cannot fail. That is why it proves nothing.
• Golden fixtures are captured by a script from the real tool, and never typed or edited.
• Keep a manifest: the tool version and the command that produced each fixture (26.8).
• Produce failure fixtures for real — the killed log is a real run stopped with TERM.
• Re-capture and compare on every tool upgrade. Measured: 6 of 6 identical on the same version; a difference is a format change.
• Keep old-version fixtures beside new ones, named by version (18.8).
• Cut long logs with a script that proves the facts did not change. Measured: 2,002 lines to 6, same verdict; head -n 20 turned a PASS into NO_FINISH.
• Scrub only with same-shape names, and check the facts afterwards.

Chapter 27.3 turns these fixtures into an automated test suite with Test::More and prove, so that a parser change which breaks one of these real logs is caught in seconds rather than in the next morning's report.