Composing Reusable Parsing Helpers

Part II · Module 27 · Chapter 27.1 · Composing Reusable Parsing Helpers

1. Three Scripts, Three Copies, Six Real Logs

A regression flow usually grows several scripts that need the same fact about a simulation log — did the test pass? One produces the nightly summary, one sorts failures for triage, one writes the email that goes to the team. Each was written at a different time, by someone who needed the answer quickly, and each contains its own few lines for reading a log.

These are six real logs, captured from the Icarus Verilog simulator running six small testbenches — the same run endings Chapter 26.7 measured. Chapter 27.2 shows how they were captured and why that matters. For now, read them for what they contain.

TEST PASSED
tb/pass.v:4: $finish called at 0 (1s)

ERROR: data mismatch exp=5 got=4
TEST FAILED
tb/mismatch.v:5: $finish called at 0 (1s)

ERROR: tb/sv_error.v:3: data mismatch exp=5 got=4
       Time: 0  Scope: tb
tb/sv_error.v:4: $finish called at 0 (1s)

TEST FAILED
tb/finish_1.v:4: $finish(1) called at 0 (1s)

FATAL: tb/sv_fatal.v:3: scoreboard overflow
       Time: 0  Scope: tb

waiting for a handshake that never comes

A person reading them reaches six clear conclusions: one pass, four failures of different kinds, and one run that was stopped before it finished — there is no $finish line in icarus_killed.log.

Now the three scripts. Each one reads every log and prints a verdict; each has its own copy of the logic, and each copy is a reasonable thing for someone to have written.

# regress_summary.pl -- the nightly summary, with its own copy of the parsing
use strict;
use warnings;

for my $log (sort glob "t/data/*.log") {
    open my $fh, "<", $log or die "$log: $!\n";
    my $text = do { local $/; <$fh> };
    close $fh;
    my $verdict = $text =~ /ERROR/ ? "FAIL" : "PASS";
    print "$log $verdict\n";
}

# triage.pl -- sorts failures for the morning, with its own copy
use strict;
use warnings;

for my $log (sort glob "t/data/*.log") {
    open my $fh, "<", $log or die "$log: $!\n";
    my ($bad, $done) = (0, 0);
    while (my $line = <$fh>) {
        $bad++    if $line =~ /^(?:ERROR|FATAL)/;
        $done = 1 if $line =~ /\$finish called/;
    }
    close $fh;
    my $verdict = !$done ? "NO_FINISH" : $bad ? "FAIL" : "PASS";
    print "$log $verdict\n";
}

# mail_report.pl -- the team email, with its own copy
use strict;
use warnings;

for my $log (sort glob "t/data/*.log") {
    open my $fh, "<", $log or die "$log: $!\n";
    my $text = do { local $/; <$fh> };
    close $fh;
    my $verdict = $text =~ /^TEST PASSED$/m ? "PASS" : "FAIL";
    print "$log $verdict\n";
}

The driver runs all three and lines their answers up against what a person reading the logs concluded:

use strict;
use warnings;

my %TRUTH = (pass => "PASS", mismatch => "FAIL", sv_error => "FAIL",
             finish_1 => "FAIL", sv_fatal => "FAIL", killed => "NO_FINISH");
my @SCRIPTS = qw(regress_summary triage mail_report);

my %said;                                  # $said{script}{test} = verdict
for my $s (@SCRIPTS) {
    open my $fh, "-|", "perl", "bin/$s.pl" or die "bin/$s.pl: $!\n";
    while (my $line = <$fh>) {
        my ($log, $verdict) = split ' ', $line;
        my ($test) = $log =~ /icarus_(\w+)\.log$/;
        $said{$s}{$test} = $verdict;
    }
    close $fh;
}

printf "%-9s %-10s %-16s %-12s %-12s %s\n", "log", "truth", @SCRIPTS, "agree?";
my $split = 0;
for my $t (qw(pass mismatch sv_error finish_1 sv_fatal killed)) {
    my @v = map { $said{$_}{$t} } @SCRIPTS;
    my %distinct = map { $_ => 1 } @v;
    $split++ if keys %distinct > 1;
    printf "%-9s %-10s %-16s %-12s %-12s %s\n", $t, $TRUTH{$t},
        map({ $_ eq $TRUTH{$t} ? $_ : "$_ *" } @v),
        keys %distinct > 1 ? "NO" : "yes";
}
my %wrong = map { my $s = $_; $s => scalar grep { $said{$s}{$_} ne $TRUTH{$_} } keys %TRUTH } @SCRIPTS;
print "\nthe three scripts disagree on $split of 6 logs  (* = wrong)\n";
print "wrong answers: ", join(", ", map { "$_ $wrong{$_}" } @SCRIPTS), "\n";

log       truth      regress_summary  triage       mail_report  agree?
pass      PASS       PASS             PASS         PASS         yes
mismatch  FAIL       FAIL             FAIL         FAIL         yes
sv_error  FAIL       FAIL             FAIL         FAIL         yes
finish_1  FAIL       PASS *           NO_FINISH *  FAIL         NO
sv_fatal  FAIL       PASS *           NO_FINISH *  FAIL         NO
killed    NO_FINISH  PASS *           NO_FINISH    FAIL *       NO

the three scripts disagree on 3 of 6 logs  (* = wrong)
wrong answers: regress_summary 3, triage 2, mail_report 1

Three scripts, the same six logs, and they disagree on three of them. Every one of the three is wrong at least once, and the nightly summary is wrong three times — always in the same direction. It calls the $fatal run a pass, because that log says FATAL, not ERROR. It calls the $finish(1) run a pass, because that log says TEST FAILED, not ERROR. And it calls the killed run a pass, because a log that simply stopped contains no ERROR at all (Chapter 21.2's argument, failing in a fresh place). The triage script calls $finish(1) and the fatal run "did not finish", because its copy looks for the exact text $finish called and checks for completion before checking for a fatal. The email calls the killed run a failure, which is closer to the truth than a pass but loses the reason.

None of these is a careless script. Each copy was correct for the logs its author had in front of them on the day it was written.

2. Why Copies Drift

Copied logic diverges for ordinary reasons, and every one of them is at work above.

A fix lands in one copy. Someone notices that a killed run reports PASS in the summary, fixes the summary, and does not know that two other scripts have the same lines. The fix exists; it just does not exist everywhere.

Each copy is tested against different examples. The triage script's author saw $finish called in the logs they were looking at, and $finish(1) never appeared in them. The summary's author never saw a killed run.

The copies answer slightly different questions. "Does it contain ERROR?", "did it finish without errors?" and "did it print TEST PASSED?" are three definitions of "passed", and nobody decided between them because nobody saw them side by side.

The result is the worst kind of inconsistency: the same run is a pass in one report and a failure in another, and every report looks authoritative. Chapter 12.1 made the general case for putting shared code in a module. In a flow, the specific case is that there must be exactly one definition of what each log means.

3. The Module: One Contract Per Function

The canonical example for this chapter names three functions that most flows need: one that turns a simulation log into facts, one that pulls a slack value out of a timing-report line, and one that turns a list of results into a summary. Here they are as one module, written the way Chapter 12.5 wrote a first .pm file and exported the way Chapter 12.6 showed.

package VLSI::Report;
# VLSI::Report -- the one implementation of log and report parsing that
# every flow script shares. Each function has one contract:
#
#   parse_log(PATH)        -> hash ref, always the same keys:
#                               lines, errors, fatals, finished, result, verdict
#                             verdict is one of EMPTY_LOG NO_FINISH FAIL PASS NO_VERDICT
#                             croaks if PATH is missing or cannot be read
#   extract_slack(LINE)    -> the slack as a number, or undef if LINE is not a slack line
#   generate_summary(LIST) -> one string; LIST holds [test, verdict] pairs
#
# Nothing here prints, exits or reads a global. The caller decides what to do.
use strict;
use warnings;
use Carp qw(croak);
use Exporter qw(import);

our @EXPORT_OK = qw(parse_log extract_slack generate_summary);

my $FINISH = qr/^\S+:\d+: \$finish(?:\(\d\))? called at /;   # Icarus: file:line: $finish called at
my $SLACK  = qr/^\s*slack \((?:MET|VIOLATED)\)\s+(-?\d+\.\d+)\s*$/;

sub parse_log {
    my ($path) = @_;
    croak "parse_log: no path given" unless defined $path && length $path;
    open my $fh, "<", $path or croak "parse_log: cannot open $path: $!";
    my %r = (lines => 0, errors => 0, fatals => 0, finished => 0, result => undef);
    while (my $line = <$fh>) {
        $r{lines}++;
        $r{finished} = 1      if $line =~ $FINISH;
        $r{errors}++          if $line =~ /^ERROR: /;
        $r{fatals}++          if $line =~ /^FATAL: /;
        $r{result} = $1       if $line =~ /^TEST (PASSED|FAILED)$/;
    }
    close $fh;
    $r{verdict} = !$r{lines}                       ? "EMPTY_LOG"
                : $r{fatals}                       ? "FAIL"
                : !$r{finished}                    ? "NO_FINISH"
                : $r{errors}                       ? "FAIL"
                : ($r{result} // "") eq "FAILED"   ? "FAIL"
                : ($r{result} // "") eq "PASSED"   ? "PASS"
                :                                    "NO_VERDICT";
    return \%r;
}

sub extract_slack {
    my ($line) = @_;
    return undef unless defined $line;
    return $line =~ $SLACK ? 0 + $1 : undef;
}

sub generate_summary {
    my (@results) = @_;
    my %count;
    $count{ $_->[1] }++ for @results;
    my $text = join "", map { sprintf "%-12s %s\n", @$_ } sort { $a->[0] cmp $b->[0] } @results;
    $text .= sprintf "%d tests: %s\n", scalar @results,
        join(", ", map { "$_ $count{$_}" } sort keys %count);
    return $text;
}

1;

The comment block at the top is the most important part of the file. It states the contract for each function: what it takes, what it returns, and what it does when the input is wrong. Everything below the comment is one way of keeping that promise, and could be rewritten tomorrow without changing a single caller — as long as the promise still holds.

4. What Makes a Contract

Four properties make those three functions safe to share. They are the practical form of Chapter 10.12's advice on designing a subroutine worth reusing.

One return shape, always. parse_log returns a hash reference with the same six keys every time — for a passing log, a failing log, and an empty one. A caller can write $r->{verdict} without first checking whether it got a hash, an undef, or a list. A function that returns undef "when there is nothing to report" forces every caller to remember a special case, and the caller that forgets is the one that fails at two in the morning. Chapter 10.8 covered returning structures safely; this is the same rule applied across scripts.

A closed set of answers. verdict is one of five words, listed in the contract. A caller can handle all five, and a new kind of ending — if one is ever needed — is a visible change to the contract rather than a new string appearing in a report.

Bad input is the caller's problem, loudly. A missing file is not a verdict; it means the caller asked for something that does not exist. So parse_log croaks, and the caller decides whether that ends the job or becomes a NO_LOG row in a table. An empty file, by contrast, is a real outcome — a job that died before writing anything — so it gets a verdict, EMPTY_LOG. The line between those two cases is a design decision, and the contract is where it is written down.

No side effects. Nothing in the module prints, exits, changes a global, or depends on the current directory. generate_summary returns its text; the caller prints it, writes it to a file, or puts it in an email. A library that prints its own output can only be used by callers that want exactly that output in exactly that place, and a library that calls exit takes the decision about the job's status away from the only code that knows the job.

The two patterns are defined once, as qr// objects (Chapter 11.18), with a comment saying what real output they match. $FINISH accepts both spellings measured in the logs — $finish and $finish(1) — and requires the file:line: prefix the simulator actually prints.

5. The Three Scripts, Thin

With the module in place, each script shrinks to the part that is genuinely its own: what it does with the answer. They find the module through FindBin, which gives the directory the script lives in, so they work wherever they are called from (Chapter 12.4 covered how @INC is searched).

use strict;
use warnings;
use FindBin qw($Bin);
use lib "$Bin/../lib";
use VLSI::Report qw(parse_log);

print "$_ ", parse_log($_)->{verdict}, "\n" for sort glob "t/data/*.log";

use strict;
use warnings;
use FindBin qw($Bin);
use lib "$Bin/../lib";
use VLSI::Report qw(parse_log);

for my $log (sort glob "t/data/*.log") {
    my $r = parse_log($log);
    print "$log $r->{verdict}\n";
    print STDERR "  triage: $log has $r->{errors} error(s), $r->{fatals} fatal(s)\n"
        if $r->{verdict} ne "PASS";
}

use strict;
use warnings;
use FindBin qw($Bin);
use lib "$Bin/../lib";
use VLSI::Report qw(parse_log generate_summary);

my @results = map { [ m{icarus_(\w+)\.log$}, parse_log($_)->{verdict} ] } sort glob "t/data/*.log";
print STDERR generate_summary(@results);
print "$_ ", parse_log($_)->{verdict}, "\n" for sort glob "t/data/*.log";

#!/bin/bash
for s in regress_summary triage mail_report; do cp "bin/${s}_v2.pl" "bin/$s.pl"; done
perl compare_copies.pl
echo "--- and the email's summary, from generate_summary:"
perl bin/mail_report.pl 2>&1 >/dev/null

log       truth      regress_summary  triage       mail_report  agree?
pass      PASS       PASS             PASS         PASS         yes
mismatch  FAIL       FAIL             FAIL         FAIL         yes
sv_error  FAIL       FAIL             FAIL         FAIL         yes
finish_1  FAIL       FAIL             FAIL         FAIL         yes
sv_fatal  FAIL       FAIL             FAIL         FAIL         yes
killed    NO_FINISH  NO_FINISH        NO_FINISH    NO_FINISH    yes

the three scripts disagree on 0 of 6 logs  (* = wrong)
wrong answers: regress_summary 0, triage 0, mail_report 0
--- and the email's summary, from generate_summary:
finish_1     FAIL
killed       NO_FINISH
mismatch     FAIL
pass         PASS
sv_error     FAIL
sv_fatal     FAIL
6 tests: FAIL 4, NO_FINISH 1, PASS 1

Six of six, and the three scripts agree because they cannot disagree — they no longer contain the logic that differed. The driver is the same compare_copies.pl as section 1; only the scripts changed.

Two details in the thin scripts are worth noticing. The triage script still prints its own extra information — error and fatal counts — using fields the module already returns; sharing the parsing did not take away its freedom to present the answer differently. And all the human-facing text goes to stderr, while each script's stdout stays a clean log verdict stream that another program can read (Chapter 26.3's rule).

6. croak: The Error Names the Caller

When parse_log is given a file that does not exist, it calls croak rather than die. Chapter 14.9 explained the difference; in a shared module it decides whether the error message is useful.

use strict;
use warnings;
use FindBin qw($Bin);
use lib "$Bin/../lib";
use VLSI::Report qw(parse_log);

my $r = parse_log("t/data/icarus_pas.log");     # a typo in the caller
print "verdict: $r->{verdict}\n";

#!/bin/bash
perl bin/bad_call.pl 2>&1
echo "exit $?"

parse_log: cannot open t/data/icarus_pas.log: No such file or directory at bin/bad_call.pl line 7.
exit 2

The message names bin/bad_call.pl line 7 — the line with the typo — not a line inside Report.pm. (The exit status is 2 because an uncaught croak is a die, and Chapter 15.4 measured that die exits with $! — here ENOENT, which is 2.) With die, the message would point into the module, and every engineer using it would start debugging in the wrong file. A shared library is called from many places; its errors must point at the place that made the mistake.

7. Exercises

1. Find a fourth definition. Write a fourth script with its own copy of the parsing that agrees with the truth on all six logs, but by a different rule from the module's. Then construct a seventh log — realistic for Icarus — on which your rule and the module's disagree. Which one is right, and where should that decision be written down?

2. A contract change. The triage team wants parse_log to return the text of the first error line. Add it without breaking any existing caller. What has to be true of the new key's value when there is no error, and why is "the key is missing" the wrong answer?

3. extract_slack's promise. The contract says extract_slack returns "the slack as a number". Find an input line on which the current implementation returns something a caller might not expect, or argue that there is none. Chapter 27.5 tests this function across many lines; write down three of the lines you would put in that table.

4. Where should NO_LOG live? A missing log croaks; an empty one is a verdict. Argue the opposite design — parse_log returns { verdict => "NO_LOG" } for a missing file — and list what each caller in section 5 would have to change. Which design makes a typo in a path harder to miss?

5. Your own flow. Find two scripts in a flow you know that each parse the same kind of file. Run them on the same inputs and record where they disagree. The disagreements are the specification you did not know you had.

8. What To Remember

• Copied parsing drifts. Measured: three scripts disagreed on 3 of 6 real logs, every one was wrong at least once, and one called a fatal run, a failed run and a killed run PASS.
• Copies drift because fixes land in one place, each copy sees different examples, and each answers a slightly different question.
• There must be exactly one definition of what each log means — in a module (12.1, 12.5, 12.6).
• Write the contract first: inputs, one return shape, the closed set of answers, and what happens on bad input.
• Always return the same shape. A function that sometimes returns undef makes every caller remember a special case.
• Missing input croaks; an empty input is a verdict. Decide the line and write it in the contract.
• A library never prints or exits. It returns; the caller presents and decides.
• Define each pattern once, as qr//, with a comment naming the real output it matches (11.18).
• Find the module with FindBin and use lib, so scripts work from any directory (12.4).
• croak names the caller's line (14.9) — measured: bin/bad_call.pl line 7, the typo.
• After factoring, the scripts agree by construction: measured 6 of 6.

Chapter 27.2 is about the six logs this chapter used: why they are real tool output rather than examples someone typed, how they were captured, and what goes wrong when a parser is tested against what its author expected a tool to print.