Negative Tests: Proving a Parser Can Fail

Part II · Module 27 · Chapter 27.4 · Negative Tests: Proving a Parser Can Fail

1. The Question 27.3 Did Not Ask

Every test in Chapter 27.3's suite has the same shape: give the parser a real log, check it returns the right answer. Those are positive tests, and they are necessary. They answer "does the parser recognise what it should?"

They cannot answer the other question: does the parser refuse what it should? A parser can get every good log right and still call an empty log a pass, still accept a file that is not a simulation log at all, still count a harmless line as an error. None of those mistakes shows up when every input is good.

That matters more for a flow parser than for most code, because of where its mistakes land. A positive-case bug — a real failure reported as a failure of the wrong kind — is noticed by the engineer who triages it. A negative-case bug usually reports something bad as fine, and nobody triages a pass.

A negative test gives the parser an input that must not produce a good answer, and asserts that it reports a problem. Chapter 18.4 made the matching argument about patterns — a pattern must be tested against the lines it must not match. This chapter does it for a whole parser.

2. Bad Inputs, Captured From the Real Tools

Chapter 27.2's rule applies to bad inputs exactly as it does to good ones: capture them from the real tools. A hand-typed "truncated log" encodes the author's idea of truncation. The script below produces four bad inputs a flow really meets, each in the way it really happens.

module tb;
  reg clk = 0, done = 0;
  always #5 clk = ~clk;     // keeps the simulation alive
  initial begin
    $display("TEST PASSED");
    wait (done);            // never set: the run hangs after reporting a pass
    $finish;
  end
endmodule

module tb;
  initial begin
    $display("INFO: next phase injects an ERROR response on purpose");
    $display("INFO: the slave returned the expected ERROR response");
    $display("TEST PASSED");
    $finish;
  end
endmodule

module tb;
  initial begin
    $display("missing semicolon")
  end
endmodule

#!/bin/bash
# capture_negative.sh -- capture the BAD inputs a parser will meet, from the
# real tools, the same way 27.2 captured the good ones.
set -uo pipefail
d=t/data
mkdir -p "$d"

# 1. A job whose simulator never started: the wrapper's redirect still
#    creates the log, so the log exists and is empty.
no_such_simulator -n sim.vvp > "$d/icarus_empty.log" 2> /dev/null

# 2. A run that printed TEST PASSED and was then killed before $finish.
iverilog -g2012 -o pth.vvp tb/pass_then_hang.v
vvp -n pth.vvp > "$d/icarus_pass_then_killed.log" 2>&1 &
pid=$!; sleep 0.5; kill -TERM "$pid"; wait "$pid"

# 3. A passing run whose INFO lines mention the word ERROR.
iverilog -g2012 -o ime.vvp tb/info_mentions_error.v
vvp -n ime.vvp > "$d/icarus_info_mentions_error.log" 2>&1

# 4. Another tool's output: the COMPILER's log, handed to the sim parser.
iverilog -g2012 -o syn.vvp tb/syntax.v > "$d/iverilog_compile_error.log" 2>&1

for f in icarus_empty icarus_pass_then_killed icarus_info_mentions_error iverilog_compile_error; do
    printf '%-30s %3d bytes\n' "$f.log" "$(wc -c < "$d/$f.log")"
done

#!/bin/bash
bash capture_negative.sh 2> /dev/null
for f in icarus_empty icarus_pass_then_killed icarus_info_mentions_error iverilog_compile_error; do
    echo "--- $f.log"
    sed 's/^/  | /' "t/data/$f.log"
done

icarus_empty.log                 0 bytes
icarus_pass_then_killed.log     12 bytes
icarus_info_mentions_error.log 172 bytes
iverilog_compile_error.log      39 bytes
--- icarus_empty.log
--- icarus_pass_then_killed.log
  | TEST PASSED
--- icarus_info_mentions_error.log
  | INFO: next phase injects an ERROR response on purpose
  | INFO: the slave returned the expected ERROR response
  | TEST PASSED
  | tb/info_mentions_error.v:6: $finish called at 0 (1s)
--- iverilog_compile_error.log
  | tb/syntax.v:4: syntax error
  | I give up.

Each one is a real event:

icarus_empty.log — zero bytes. The simulator never started (here, a mistyped command), but the wrapper's > file redirect created the log anyway. This is how most empty logs come into existence: the log's existence says a job ran, its size says nothing happened. Chapter 18.9 distinguished missing, empty and truncated; this is the empty case, produced the way production produces it.

icarus_pass_then_killed.log — one line, TEST PASSED. The testbench reported success, then waited for an event that never came and was killed by TERM, before $finish. Whether this run passed is genuinely unknown — the check that printed PASSED may have run before the part of the test that hangs — and the parser must not decide for the reader that it did.

A detail from building this fixture is worth recording, because it is the kind of thing only real runs reveal. The first version of this testbench waited with wait (0) and had nothing else scheduled. It was not killed: it ended on its own, with no $finish line, because a simulation with nothing left to simulate simply stops. That is a third way for a log to end without $finish, and the free-running clock in the final version is what makes it a genuine hang.

icarus_info_mentions_error.log — a passing run that says "ERROR". An INFO line describing an expected error response is everyday testbench output — a test that injects errors on purpose talks about them. A parser that counts the word rather than the severity tag (Chapter 18.4) fails this run.

iverilog_compile_error.log — another tool's output. This is the compiler's log, not the simulator's — the kind of file that ends up in the wrong place when a script's paths are off by one directory. It contains no $finish, no TEST line, no ERROR: prefix.

3. The Negative Test File

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

# Bad inputs, captured from the real tools. None of them may come out as PASS.
is parse_log("$Bin/data/icarus_empty.log")->{verdict}, "EMPTY_LOG",
    "empty log (the simulator never started): EMPTY_LOG";
is parse_log("$Bin/data/icarus_pass_then_killed.log")->{verdict}, "NO_FINISH",
    "said TEST PASSED, then killed before \$finish: NO_FINISH";

# Another tool's output. The contract does not name a verdict for a file
# that is not a simulation log, so assert the property that matters.
isnt parse_log("$Bin/data/iverilog_compile_error.log")->{verdict}, "PASS",
    "a compiler log handed to the sim parser is not a PASS";

# A line that mentions ERROR without being an error report.
my $r = parse_log("$Bin/data/icarus_info_mentions_error.log");
is $r->{errors},  0,      "INFO lines mentioning ERROR are not errors";
is $r->{verdict}, "PASS", "and that run still passes";

# A missing file is the caller's mistake: it must croak, and say which file.
my $lived = eval { parse_log("$Bin/data/no_such.log"); 1 };
ok !$lived, "a missing log croaks";
like $@, qr/cannot open \S*no_such\.log: No such file/, "and the message names the file";

done_testing;

Each test states what the parser must not do with one bad input:

• Empty log → EMPTY_LOG. The contract from Chapter 27.1 names this verdict, so the test checks for it exactly.
• Killed after PASSED → NO_FINISH. The run printed the pass marker and still did not finish. The test pins the order of the parser's checks: completion is asked before the pass marker is believed (Chapter 21.2).
• Another tool's file → not PASS. This test uses isnt, and deliberately. The contract does not say which verdict a non-simulation file should get — NO_FINISH is what the parser returns today, and a later version might reasonably return something more specific. What must never change is that it is not a pass. Asserting the exact current value would make the test fail on a legitimate improvement; asserting the property makes it fail only on a real regression.
• INFO mentioning ERROR → 0 errors, still PASS. This is the one negative test whose correct answer is a pass: the bad thing being tested for is a false failure.
• Missing file → croaks, naming the file. A missing log is the caller's mistake, and the contract says the parser croaks.

Running the whole suite, positive and negative together:

#!/bin/bash
bash capture_negative.sh > /dev/null 2>&1
prove t/ 2>&1 | sed -E 's/[0-9]+ wallclock secs.*/(timing removed)/'
echo "prove exit status: ${PIPESTATUS[0]}"

t/negative.t ... ok
t/parse_log.t .. ok
All tests successful.
Files=2, Tests=22,  (timing removed)
Result: PASS
prove exit status: 0

Twenty-two tests, all passing — on the real parser. Whether these new tests are worth anything is a separate question, and section 5 measures it.

4. Testing That Something Dies

The last two tests check that parse_log croaks. Core Perl has no dedicated function for that, and needs none: eval catches the die and leaves the message in $@ (Chapter 14.4).

my $lived = eval { parse_log("$Bin/data/no_such.log"); 1 };
ok !$lived, "a missing log croaks";
like $@, qr/cannot open \S*no_such\.log: No such file/, "and the message names the file";

The ; 1 at the end of the eval block is the important part. If the call dies, eval returns undef; if it completes, the block's last value — 1 — is returned. Testing that value, rather than testing whether $@ is empty, avoids a classic trap: an object destroyed while the stack unwinds can run its own eval and reset $@, so a failure looks like success. Modern Perl protects $@ far better than older versions did, but the return-value test costs nothing and is correct on every version.

The canonical example for this chapter writes the same test with exception { ... }:

like exception { parse_log('/nonexistent') }, qr/No such file/;

That exception function comes from Test::Fatal, which Chapter 27.3 showed is not core. It reads well, and on the machine these examples were run on it happens to be installed, because the operating system bundles it. A compute farm with a plain Perl does not have it — which is easy to show by removing the bundled extras from @INC:

#!/bin/bash
echo "with this machine's bundled extras:"
perl -MTest::Fatal -e 'print "  Test::Fatal loads\n"'
echo "with only what core Perl provides:"
perl -e 'BEGIN { @INC = grep { !m{/Extras/} } @INC } use Test::Fatal;' 2>&1 \
    | sed -e 's/ (@INC contains.*//' -e 's/^/  /' | head -n 1

with this machine's bundled extras:
  Test::Fatal loads
with only what core Perl provides:
  Can't locate Test/Fatal.pm in @INC (you may need to install the Test::Fatal module)

If your site installs Test::Fatal everywhere the tests run, use it. If you cannot be sure, the three-line eval form above does the same job with nothing to install.

5. Mutation Testing: Do the Tests Catch Anything?

Twenty-two passing tests prove that the real parser behaves. They do not prove that the tests would notice if it did not. A test suite is only worth something if it fails when the code is wrong — and the direct way to find out is to make the code wrong on purpose and see.

That is mutation testing: plant one realistic bug at a time — a mutant — and run the suite. A suite that still passes has missed the bug; a suite that fails has caught it. Each bug below is the kind of small change a real edit makes:

• "An empty log is a PASS" — one word changed in the verdict ladder.
• "A missing file is not an error" — someone replaces the croak with a quiet return, so a typo in a path becomes a verdict instead of an error.
• "TEST PASSED is enough" — someone decides the pass marker should win over a missing $finish.
• "ERROR anywhere on a line" — the anchored ^ERROR: is "simplified" to ERROR.

use strict;
use warnings;

# Plant one realistic bug at a time in the parser, and ask two suites whether
# they notice: the positive suite from 27.3 alone, and with the negative tests.
my $MOD = "lib/VLSI/Report.pm";
my $original = do { open my $f, "<", $MOD or die "$MOD: $!\n"; local $/; <$f> };

my @MUTANTS = (
    [ "none (the real parser)", undef, undef ],
    [ "an empty log is a PASS",
      q{!$r{lines}                       ? "EMPTY_LOG"},
      q{!$r{lines}                       ? "PASS"} ],
    [ "a missing file is not an error",
      q{or croak "parse_log: cannot open $path: $!";},
      q{or return { lines => 0, errors => 0, fatals => 0, finished => 0, verdict => "EMPTY_LOG" };} ],
    [ "TEST PASSED is enough",
      q{: !$r{finished}                    ? "NO_FINISH"},
      q{: (!$r{finished} && ($r{result} // "") ne "PASSED") ? "NO_FINISH"} ],
    [ "ERROR anywhere on a line",
      q{$r{errors}++          if $line =~ /^ERROR: /;},
      q{$r{errors}++          if $line =~ /ERROR/;} ],
);

sub suite_passes {                       # exit status of prove, 0 = all passed
    system("prove @_ > /dev/null 2>&1");
    return $? == 0;
}

printf "%-32s %-22s %s\n", "bug planted in parse_log", "27.3 suite (15 tests)", "with negative tests";
my ($missed_pos, $missed_all) = (0, 0);
for my $m (@MUTANTS) {
    my ($name, $from, $to) = @$m;
    my $src = $original;
    if (defined $from) {
        my $at = index($src, $from);
        die "mutation '$name' does not apply\n" if $at < 0;
        substr($src, $at, length $from) = $to;
    }
    open my $w, ">", $MOD or die; print {$w} $src; close $w;

    my $pos = suite_passes("t/parse_log.t");
    my $all = suite_passes("t/parse_log.t", "t/negative.t");
    if (defined $from) { $missed_pos++ if $pos; $missed_all++ if $all }
    printf "%-32s %-22s %s\n", $name,
        $pos ? "passes" : "FAILS",
        $all ? "passes" : "FAILS";
}
open my $w, ">", $MOD or die; print {$w} $original; close $w;   # put it back
printf "\nbugs the 27.3 suite missed: %d of %d.  With negative tests: %d of %d.\n",
    $missed_pos, $#MUTANTS, $missed_all, $#MUTANTS;

#!/bin/bash
bash capture_negative.sh > /dev/null 2>&1
before=$(cksum < lib/VLSI/Report.pm)
perl mutate.pl
[ "$(cksum < lib/VLSI/Report.pm)" = "$before" ] && echo "lib/VLSI/Report.pm is byte-for-byte restored"

bug planted in parse_log         27.3 suite (15 tests)  with negative tests
none (the real parser)           passes                 passes
an empty log is a PASS           passes                 FAILS
a missing file is not an error   passes                 FAILS
TEST PASSED is enough            passes                 FAILS
ERROR anywhere on a line         passes                 FAILS

bugs the 27.3 suite missed: 4 of 4.  With negative tests: 0 of 4.
lib/VLSI/Report.pm is byte-for-byte restored

Chapter 27.3's fifteen tests passed all four bugs. Every one of them would have gone into production behind a green test run. With the seven negative tests added, all four are caught. The first row is the control: the real parser passes both suites, so a failure in the other rows is caused by the planted bug and by nothing else.

The result is the strongest argument in this module for negative tests, and it is not specific to this parser. All four bugs change what happens to a bad input, and a suite made only of good inputs has no way to see them — not because the positive tests are poor, but because they never feed the parser the input on which these bugs show.

The script restores the original module after the last mutant, and the driver's last line proves it with a checksum. Mutation testing changes production code, so a harness that might leave a mutant behind is worse than no harness; this one rewrites the file from the copy it read at the start.

6. What a Negative Test Cannot Do

Negative tests close a large gap, but they have limits worth stating plainly.

They cover the bad inputs someone thought of. Each test above exists because a real failure mode was named and captured. A bad input nobody has seen yet — a new tool version's way of being truncated, a log written by a different simulator — is not covered until it is captured. Chapter 27.2's re-capture habit is how new ones are found.

They prove the parser rejects these inputs, not that it is correct. Passing twenty-two tests is evidence, not proof. Mutation testing measures how much evidence: a suite that kills every realistic mutant is a strong suite; one that kills none is decoration.

The assertion has to be the right strength. isnt ... "PASS" for the compiler log is weaker than is ... "NO_FINISH", on purpose. Too strong, and the test breaks on legitimate improvements and people learn to ignore it. Too weak — ok defined $r->{verdict} — and it passes for nearly any bug. The right strength is the property the contract promises.

7. Exercises

1. A fifth mutant. Write a mutant that the full suite of twenty-two tests still misses. Then write the negative test — and capture the real input it needs — that kills it. What kind of bad input was missing?

2. Make the compiler-log test earn its place. Write a mutant that changes how parse_log treats a file with no recognisable lines, such that only the compiler-log test catches it. Add it to mutate.pl and run the table. Is your mutant a bug someone might really write?

3. The run that ran out of events. Rebuild the first version of pass_then_hang.v — wait (0) with no clock — capture its log, and record its exit status. What should parse_log report for it, and does it? Add the test.

4. Too strong, too weak. Rewrite the compiler-log test with is ... "NO_FINISH", then change parse_log so it returns a new verdict, NOT_A_SIM_LOG, for files with no simulator output at all. Which version of the test fails, and is that failure telling you about a bug? Write the version you would keep.

5. Your own suite. Run a mutation pass by hand on a parser you maintain: make three small, realistic edits, one at a time, and run its tests after each. Report how many it caught. If the answer is not three, write the missing negative tests before changing anything else.

8. What To Remember

• Positive tests check that good input is recognised; negative tests check that bad input is refused. A flow needs both.
• Negative-case bugs usually report something bad as fine, and nobody triages a pass.
• Capture bad inputs from the real tools: an empty log from a failed launch, a run killed after TEST PASSED, a passing log that mentions ERROR, another tool's file.
• A simulation with nothing left to do ends without $finish — measured while building the hanging fixture.
• Test that something dies with eval { ...; 1 } and check $@ (14.4). Test::Fatal's exception is CPAN — measured: not loadable without this machine's bundled extras.
• Assert the property the contract promises — isnt ... "PASS" when the exact verdict is not specified.
• Mutation testing measures a suite: plant a realistic bug, run the tests, count what is caught.
• Measured: 27.3's 15 positive tests missed 4 of 4 planted bugs; with 7 negative tests, 0 of 4 were missed.
• Keep a control row (the unmodified code) and always restore the original after mutating.
• A test no mutant has ever failed has not been shown to work.
• Negative tests cover the bad inputs someone named. Re-capture to find new ones (27.2).

Chapter 27.5 narrows from whole logs to single lines: the regular expression at the heart of a parser, tested against a table of lines from every tool version in use — including the lines it must not match.