Testing With Test::More

Part II · Module 27 · Chapter 27.3 · Testing With Test::More

1. What You Have, and What Is Core

Perl has a large testing ecosystem, and the first thing to settle is which parts of it a flow can rely on. A test suite that needs a module the compute farm does not have is a test suite nobody can run. Module::CoreList — itself part of core Perl — answers the question from data rather than memory:

use strict;
use warnings;
use Module::CoreList;

for my $m (qw(Test::More Test::Simple Test::Harness Test::Fatal Test::Deep)) {
    my $first = Module::CoreList->first_release($m);
    my $here  = eval "require $m; 1" ? "installed here" : "not installed here";
    printf "%-14s %-26s %s\n", $m,
        $first ? "core since Perl $first" : "NOT core (from CPAN)", $here;
}

Test::More     core since Perl 5.006002   installed here
Test::Simple   core since Perl 5.006002   installed here
Test::Harness  core since Perl 5          installed here
Test::Fatal    NOT core (from CPAN)       installed here
Test::Deep     NOT core (from CPAN)       installed here

Test::More, Test::Simple and Test::Harness are core — they have shipped with Perl for decades. Test::Harness provides prove, the command that runs test files. Everything in this chapter uses only these.

The last two lines carry a warning worth absorbing. Test::Fatal and Test::Deep are popular, they are not core, and on the machine these examples were run on they are nevertheless installed — this operating system bundles a set of extra CPAN modules with its system Perl. A test written with them would pass here and fail with Can't locate Test/Fatal.pm in @INC on a compute farm with a plain Perl. Chapter 12.10 described that site-library problem in general; for a test suite the rule is simple: check first_release, not whether it happens to load on your machine. Chapter 27.4 shows the core way to do what Test::Fatal is used for.

Test::Simple provides only ok. Test::More is a superset with the comparison functions a parser test needs, and it is what every example below uses.

2. The Test File

By convention, Perl tests live in a t/ directory, one topic per file, with names ending in .t. A .t file is an ordinary Perl script. This one tests all three functions of the shared module from Chapter 27.1 against the six golden logs from Chapter 27.2:

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

# Expected facts for every golden log from 27.2 -- one row per real run ending.
my %EXPECT = (
    pass     => [ PASS      => { errors => 0, fatals => 0, finished => 1 } ],
    mismatch => [ FAIL      => { errors => 1, fatals => 0, finished => 1 } ],
    sv_error => [ FAIL      => { errors => 1, fatals => 0, finished => 1 } ],
    finish_1 => [ FAIL      => { errors => 0, fatals => 0, finished => 1 } ],
    sv_fatal => [ FAIL      => { errors => 0, fatals => 1, finished => 0 } ],
    killed   => [ NO_FINISH => { errors => 0, fatals => 0, finished => 0 } ],
);

for my $name (sort keys %EXPECT) {
    my ($verdict, $counts) = @{ $EXPECT{$name} };
    my $r = parse_log("$Bin/data/icarus_$name.log");
    is $r->{verdict}, $verdict, "icarus_$name.log: verdict";
    is_deeply { map { $_ => $r->{$_} } sort keys %$counts }, $counts,
        "icarus_$name.log: counts";
}

is extract_slack("  slack (VIOLATED)   -0.043"), -0.043, "extract_slack: a violated path";
ok !defined extract_slack("expected slack: none"), "extract_slack: not a slack line";

like generate_summary([ b => "PASS" ], [ a => "FAIL" ]),
     qr/\Aa\s+FAIL\nb\s+PASS\n/, "generate_summary: sorted by test name";

done_testing;

Read it as three parts.

The setup. use Test::More imports the test functions. FindBin and use lib find the module relative to the test file itself, so the tests run from any directory — the same habit Chapter 27.1 used for the scripts.

The expectations, as data. %EXPECT holds one row per golden log: the verdict a person reading that log would give, and the counts. The loop turns each row into two tests. Writing expectations as a table, rather than as fifteen hand-written test lines, means adding a new golden log is adding one row — and anyone reviewing the file can read the specification of the parser at a glance.

The four functions used:

• ok(CONDITION, NAME) passes if the condition is true. It is the most general and the least informative: when it fails it can only say that the condition was false.
• is(GOT, EXPECTED, NAME) compares two values as strings and, on failure, prints both. Most parser tests should use it, because the printed values usually are the diagnosis.
• is_deeply(GOT, EXPECTED, NAME) compares nested structures — here, a hash of counts — and on failure prints the first place they differ.
• like(GOT, QR, NAME) passes if a string matches a pattern. It suits output whose exact text is not the point, like a summary where only the order matters.

done_testing at the end declares that the file reached its end. Section 7 shows why that line matters more than it looks.

Every test has a name. The name is what appears in a failure report, so it should identify which input failed, not just which function — icarus_finish_1.log: verdict tells the reader exactly where to look.

3. TAP: What a Test File Prints

Run a test file with plain perl and it prints its results in TAP, the Test Anything Protocol — a simple line-based text format that prove and many other tools understand:

#!/bin/bash
perl t/parse_log.t
echo "exit status: $?"

ok 1 - icarus_finish_1.log: verdict
ok 2 - icarus_finish_1.log: counts
ok 3 - icarus_killed.log: verdict
ok 4 - icarus_killed.log: counts
ok 5 - icarus_mismatch.log: verdict
ok 6 - icarus_mismatch.log: counts
ok 7 - icarus_pass.log: verdict
ok 8 - icarus_pass.log: counts
ok 9 - icarus_sv_error.log: verdict
ok 10 - icarus_sv_error.log: counts
ok 11 - icarus_sv_fatal.log: verdict
ok 12 - icarus_sv_fatal.log: counts
ok 13 - extract_slack: a violated path
ok 14 - extract_slack: not a slack line
ok 15 - generate_summary: sorted by test name
1..15
exit status: 0

Each test produces one line: ok N - NAME or not ok N - NAME. The line 1..15 is the plan — the number of tests the file ran — printed at the end because done_testing counted them. Diagnostic messages, which section 5 will show, start with # and go to standard error. That split is deliberate: standard output is the machine-readable result, standard error is for the person — the same rule Chapter 26.3 applied to every tool in a flow.

The exit status is part of the protocol too: 0 when every test passed. Section 7 measures what it is otherwise.

4. prove: Running the Suite

prove runs every test file it is given, reads their TAP, and prints a summary. Run against the t/ directory, it finds every .t file in it:

#!/bin/bash
# The last summary line contains elapsed times, which change on every run.
prove t/ 2>&1 | sed -E 's/[0-9]+ wallclock secs.*/(timing removed)/'
echo "prove exit status: ${PIPESTATUS[0]}"

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

All tests successful and exit status 0. The sed in the driver removes the timing figures from the summary line only because they differ on every run; in normal use you would read them, since a test suite that slowly gets slower is worth noticing.

Three prove options are used constantly:

• prove -l adds lib/ to @INC, for test files that do not set it themselves. The file above uses FindBin, so it works with or without it.
• prove -v prints every TAP line, not just the summary — the first thing to reach for when a suite fails.
• prove -r t/ recurses into subdirectories, for a larger suite organised by area.

5. A Harmless-Looking Change, Caught

Here is the change this suite exists to catch. Someone reading lib/VLSI/Report.pm decides the $finish pattern is over-complicated:

my $FINISH = qr/^\S+:\d+: \$finish(?:\(\d\))? called at /;    # before
my $FINISH = qr/^\S+:\d+: \$finish called at /;               # "simplified"

The (?:\(\d\))? looks like noise. It is the part that matches $finish(1) — a spelling the editor has probably never seen, because it appears in only one of the six real logs. The driver makes exactly that edit and runs the suite:

#!/bin/bash
perl -pi -e 's/\Q(?:\(\d\))?\E//' lib/VLSI/Report.pm
echo "the edited line:"
grep -n 'my \$FINISH' lib/VLSI/Report.pm | sed 's/^/  /'
echo
prove t/ 2>&1 | sed -E 's/[0-9]+ wallclock secs.*/(timing removed)/'
echo "prove exit status: ${PIPESTATUS[0]}"

the edited line:
  20:my $FINISH = qr/^\S+:\d+: \$finish called at /;   # Icarus: file:line: $finish called at


#   Failed test 'icarus_finish_1.log: verdict'
#   at t/parse_log.t line 21.
#          got: 'NO_FINISH'
#     expected: 'FAIL'

#   Failed test 'icarus_finish_1.log: counts'
#   at t/parse_log.t line 22.
#     Structures begin differing at:
#          $got->{finished} = '0'
#     $expected->{finished} = '1'
# Looks like you failed 2 tests of 15.
t/parse_log.t .. 
Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/15 subtests 

Test Summary Report
-------------------
t/parse_log.t (Wstat: 512 Tests: 15 Failed: 2)
  Failed tests:  1-2
  Non-zero exit status: 2
Files=1, Tests=15,  (timing removed)
Result: FAIL
prove exit status: 1

Two failures out of fifteen, and both name icarus_finish_1.log. The first says the verdict changed from FAIL to NO_FINISH; the second says why — finished is now 0. Thirteen other tests still pass, so the change is also shown to be harmless for every other real format, which is information too.

Without the suite, the same edit goes into the nightly flow, and the first sign of it is every $finish(1) test in the regression being reported as "did not finish" — a triage queue full of runs that finished perfectly well. With the suite, it is caught by the person who made the edit, in the time it takes prove to run.

This is the point of Chapter 27.2's rule about one fixture per real behaviour. The suite caught the change only because a real $finish(1) log was in it. A suite built from typed examples would have passed.

6. Reading a Failure

The two failure reports above show the two most useful diagnostic shapes.

is prints got and expected side by side. When a test compares a single value, that is almost always enough to diagnose the problem without opening anything else — which is why is is better than ok($got eq $expected), whose failure report can only say the comparison was false.

is_deeply prints the first place two structures differ, as a path into the structure: $got->{finished} versus $expected->{finished}. In a large nested result that path is the diagnosis.

There is a property of is_deeply worth knowing before it surprises you. When several keys of a hash differ, it reports only the first difference it finds — and the order in which Perl visits the keys of a hash is randomised on every run (the hash-ordering behaviour covered in Module 6). Running a test with three differing keys six times on this machine produced reports naming three different keys. The test result is stable; the diagnostic is not. That is one reason the test file above checks verdict with is and the counts separately with is_deeply: each failure then has one reason and one reproducible report.

Two more habits make failures easier to read:

• Compare against what the contract promises, not against everything returned. The test compares only the counts it means to check, taken as a slice. A test that compares the whole returned hash fails the day Chapter 27.1's module gains a new key — every test, at once, for a change that broke nothing.
• Use diag for context a failure needs, and note for commentary. diag("log was: $path") writes to standard error, so prove always shows it; note writes a # comment line to standard output, which prove shows only under -v.

7. What a Test File's Exit Status Means

A CI job decides whether a test run passed from the exit status, so it is worth knowing exactly what each status means. Each file below is a deliberately small case:

use Test::More;
ok 1, "a"; ok 0, "b"; ok 0, "c";
done_testing;

use Test::More;
ok 1, "first";
die "parser blew up\n";
ok 1, "never reached";
done_testing;

use Test::More;
ok 1, "a";

use Test::More tests => 3;
ok 1, "a"; ok 1, "b";

use Test::More;
ok 0, "failure $_" for 1 .. 300;
done_testing;

#!/bin/bash
for t in two_fail dies no_done short_plan many_fail; do
    perl "cases/$t.t" > /dev/null 2> "cases/$t.err"
    printf '%-11s exit %-4s %s\n' "$t" "$?" "$(grep -m1 -E 'Looks like|no plan' "cases/$t.err")"
done
prove cases/ > /dev/null 2>&1
echo "prove over all of them: exit $?"

two_fail    exit 2    # Looks like you failed 2 tests of 3.
dies        exit 255  # Tests were run but no plan was declared and done_testing() was not seen.
no_done     exit 254  # Tests were run but no plan was declared and done_testing() was not seen.
short_plan  exit 255  # Looks like you planned 3 tests but ran 2.
many_fail   exit 254  # Looks like you failed 300 tests of 300.
prove over all of them: exit 1

A file with failures exits with the number of failures — 2 for two. That makes the status informative as well as non-zero.

A file that dies exits 255, and Test::More explains it. The table shows the first of its two diagnostic lines; the second, measured in the same run, reads Looks like your test exited with 255 just after 1. This is the case done_testing exists for. Without a plan, a test file that dies half-way would have printed one ok and stopped — and a careless reader of its output, or a runner that only counts not ok lines, would see no failures at all. Because done_testing was never reached, Test::More knows the file did not finish and says so. It is Chapter 21.2's lesson about logs, applied to the test suite itself: the evidence that a run stopped early is a missing last line.

A file with no done_testing and no plan exits 254, even though its only test passed. A file that planned 3 tests and ran 2 exits 255. Both are failures of the suite's own bookkeeping, and both are caught.

Three hundred failures exit 254, not 44. The exit status is one byte (Chapter 15.4), so 300 failures would wrap to 300 − 256 = 44. Test::More deliberately caps the count at 254 so a large number of failures can never look small — or, at exactly 256, look like zero. Compare Chapter 26.7, where a compiler that did not cap its error count reported 128 broken modules as success.

prove exits 1 if anything failed, whatever the individual statuses were. That is the number a CI job sees, and it is the only one it needs: the details are in the report.

8. Exercises

1. Add a golden log. Add Chapter 27.2's six-line extract of the long passing log to t/data, and add the one row to %EXPECT that tests it. Run prove. How many tests does the suite now have, and why did you not have to write any new test code?

2. Make a test fail usefully. Rewrite the verdict test with ok($r->{verdict} eq $verdict, ...) instead of is, re-run break_and_prove.sh, and compare the two failure reports. Write down what a person debugging the ok version at night would have to do that the is version saved them.

3. The whole-hash trap. Change the counts test to is_deeply($r, { ... all six keys ... }). Then add a seventh key to parse_log's return value (say, warnings => 0) and run the suite. How many tests fail, and what does that tell you about tying tests to the full return shape rather than to the contract?

4. A test that cannot fail. Write a test file that always passes regardless of what parse_log does — without using ok(1). Then explain how Chapter 27.4's negative tests would reveal that it is useless. (Hint: what would the file report if parse_log returned the same hash for every input?)

5. Into the entry point. Add a step to Chapter 26.1's entry point — or a Makefile target — that runs prove t/ and stops the flow if it fails. Where should it run: before every regression, on every commit to the parsing module, or both? What does the answer depend on?

9. What To Remember

• Test::More, Test::Simple and Test::Harness (with prove) are core. Measured with Module::CoreList.
• Test::Fatal and Test::Deep are CPAN — and were installed here anyway. Check first_release, not whether it loads on your machine (12.10).
• Tests live in t/*.t; each is an ordinary Perl script printing TAP: ok N - name, not ok N - name, a plan line 1..N.
• Name every test after the input it checks, so a failure points at the data.
• Write expectations as a table of golden logs; adding a log is adding a row.
• is prints got and expected; prefer it to ok. is_deeply prints the first differing path.
• When several hash keys differ, is_deeply's report changes from run to run — hash order is randomised. Test one reason per assertion.
• Compare a slice of what the contract promises, not the whole return value.
• Measured: a one-line "simplification" of $FINISH failed 2 of 15 tests, both naming icarus_finish_1.log. It was caught because a real $finish(1) log was a fixture.
• Exit statuses: N failures exit N; a file that dies exits 255; no done_testing 254; a plan mismatch 255; failures are capped at 254; prove exits 1 on any failure.
• done_testing is the suite's own finish marker — without it, a test file that died half-way can look like a pass.

Chapter 27.4 asks the uncomfortable question about this suite: every test in it checks that the parser gets a good input right. What happens when the parser is wrong in a way that only shows up on a bad input — and would this suite notice?