Truncated, Empty and Missing Logs

Part II · Module 18 · Chapter 18.9 · Truncated, Empty and Missing Logs

1. Measured: Wrong On Five Of Seven

use strict;
use warnings;
use File::Temp qw(tempdir);

my $dir = tempdir(CLEANUP => 1);
sub mk { my ($n, $t) = @_; open my $o, ">", "$dir/$n" or die $!; print $o $t; close $o }

mk("empty.log", "");                                     # 0 bytes
mk("truncated.log", "UVM_INFO @ 0: starting test\nUVM_INFO @ 1200: phase ru");
mk("notstarted.log", "ERROR: could not check out license 'Sim_HDL'\n");
mk("good.log", "UVM_INFO @ 0: starting test\nUVM_INFO @ 9000: done\n"
             . "--- UVM Report Summary ---\nUVM_ERROR : 0\n\$finish called\n");
mk("realfail.log", "UVM_INFO @ 0: starting test\n"
             . "UVM_ERROR /proj/tb/scoreboard.sv(214) @ 4100: mismatch exp=3f got=00\n"
             . "--- UVM Report Summary ---\nUVM_ERROR : 1\n\$finish called\n");
mk("both.log", "UVM_INFO @ 0: starting test\n"
             . "UVM_ERROR /proj/tb/scoreboard.sv(214) @ 4100: mismatch exp=3f got=00\n"
             . "UVM_INFO @ 4200: contin");
# missing.log is deliberately never created

my @LOGS = qw(missing.log empty.log truncated.log notstarted.log
              good.log realfail.log both.log);

# ---- A: the scanner almost everybody writes first
sub naive {
    my ($f) = @_;
    my $n = 0;
    if (open my $fh, "<", $f) {                 # note: no else branch
        while (my $l = <$fh>) { $n++ if $l =~ /^UVM_(?:ERROR|FATAL)/ }
        close $fh;
    }
    return $n == 0 ? "PASS" : "FAIL($n)";
}

# ---- B: the ladder
sub classify {
    my ($f) = @_;
    return ("NO_LOG", 0)    unless -e $f;
    return ("EMPTY_LOG", 0) if     -z $f;
    open my $fh, "<", $f or return ("UNREADABLE", 0);
    my ($start, $end, $errs) = (0, 0, 0);
    while (my $l = <$fh>) {
        $start = 1 if $l =~ /^UVM_INFO/;
        $end   = 1 if $l =~ /^\$finish called/;
        next       if $l =~ /^UVM_\w+\s*:\s*\d+\s*\z/;     # 18.4: the summary's own count
        $errs++    if $l =~ /^UVM_(?:ERROR|FATAL)\b/;
    }
    close $fh;
    return ("NEVER_STARTED", $errs) unless $start;
    return ("NO_FINISH",     $errs) unless $end;
    return ($errs ? "FAIL" : "PASS", $errs);
}

printf "%-16s %-9s %-15s %s\n", "LOG", "naive", "classifier", "errors seen";
for my $l (@LOGS) {
    my ($verdict, $e) = classify("$dir/$l");
    printf "%-16s %-9s %-15s %d\n", $l, naive("$dir/$l"), $verdict, $e;
}

print "\nverdict counts:\n";
print "  naive says PASS for: ",
    join(", ", grep { naive("$dir/$_") eq "PASS" } @LOGS), "\n";
print "  only ONE of those is a real pass (good.log)\n";

LOG              naive     classifier      errors seen
missing.log      PASS      NO_LOG          0
empty.log        PASS      EMPTY_LOG       0
truncated.log    PASS      NO_FINISH       0
notstarted.log   PASS      NEVER_STARTED   0
good.log         FAIL(1)   PASS            0
realfail.log     FAIL(2)   FAIL            1
both.log         FAIL(1)   NO_FINISH       1

verdict counts:
  naive says PASS for: missing.log, empty.log, truncated.log, notstarted.log
  only ONE of those is a real pass (good.log)

Read the first column. The naive scanner is wrong on five of the seven, and wrong in both directions:

Four false passes. An absent log, an empty log, a log cut off mid-run and a log from a tool that never started are all reported PASS. Not one of them contains an error line, which is exactly why — there is nothing in any of them to find.

One false failure, on the only healthy log. good.log is reported FAIL(1), because its report summary contains the line UVM_ERROR : 0 and ^UVM_(?:ERROR|FATAL) matches it. That is Chapter 18.4's first false positive, and it is why realfail.log is reported as FAIL(2) when it holds one error.

So on these seven inputs the naive verdict is not merely unreliable. It is anti-correlated: the four broken runs pass and the clean run fails.

2. The Ladder, In Order

Each gate earns its place, and two of them are easy to get wrong.

Gate 1, existence. -e (Chapter 13.6). The common mistake is the if (open ...) with no else, as in the naive version — a missing file then takes the same path as a file with no errors in it.

Gate 2, emptiness. -z, and only after -e. Section 4 measures why the order matters.

Gate 3, readability. The or branch on open (Chapter 13.5). A log can exist, be non-empty, and still be unreadable: wrong permissions after a job ran as another user, a stale NFS handle, a path that is actually a directory.

Gate 4, did the tool start. A start marker — the tool's banner, or the first line it always prints. notstarted.log has content, so gates 1 to 3 pass it; what it contains is a licence error from a tool that then exited. Without this gate it reads as a clean run.

Gate 5, did the tool finish. An end marker — $finish called, a report summary header, whatever the tool always prints last. This is the only gate that detects truncation, because a truncated log is, by construction, indistinguishable from a complete one up to the point where it stops.

Then, and only then, a verdict about the design.

3. Incomplete And Failing Are Independent

Look at both.log in the measured table: classifier NO_FINISH, errors seen 1.

That row exists to make a point the four-way classification can obscure. A log can be both truncated and full of errors, and those two facts answer different questions:

• Is the design broken? — There is one real error, so yes, at least one.
• Do I know the full extent? — No. The run stopped early; there may be twenty more.

So the classifier returns a pair, not a verdict. Collapsing the pair loses information in whichever direction you collapse it: report only NO_FINISH and you discard a real, actionable error; report only FAIL(1) and you publish a count that is a floor, not a total, with nothing saying so.

In a flow this becomes two separate outputs:

my ($state, $errs) = classify($log);

if ($state eq "FAIL")      { print "FAIL: $errs error(s)\n";            exit 1 }
if ($state eq "PASS")      { print "PASS\n";                            exit 0 }

# every remaining state means the log is not a basis for a verdict
printf STDERR "incomplete: %s (%d error(s) seen before the log ended)\n",
    $state, $errs;
exit 3;                                 # 15.4: could not tell

The exit 3 is the whole chapter in one line. An incomplete log is not a pass and not a design failure; it is the absence of a result, and Chapter 15.4's third status is what says so. A flow that maps everything onto 0 and 1 has nowhere to put "the run did not happen", which is why the four broken inputs became passes in the first place.

4. The File Tests That Cannot Tell Them Apart

use strict;
use warnings;
use File::Temp qw(tempdir);

my $dir  = tempdir(CLEANUP => 1);
my $gone = "$dir/missing.log";              # never created
open my $o, ">", "$dir/empty.log" or die $!; close $o;      # created, 0 bytes

printf "%-14s %-8s %-8s %-8s %s\n", "FILE", "-e", "-z", "!-s", "defined(-s)";
for my $f ("$dir/missing.log", "$dir/empty.log") {
    my $s = -s $f;
    printf "%-14s %-8s %-8s %-8s %s\n",
        ($f =~ m{([^/]+)\z})[0],
        (-e $f ? "true" : "false"),
        (-z $f ? "true" : "false"),
        (!-s $f ? "true" : "false"),
        (defined $s ? "yes ($s)" : "no (undef)");
}

FILE           -e       -z       !-s      defined(-s)
missing.log    false    false    true     no (undef)
empty.log      true     true     true     yes (0)

Three things to take from that table.

-z is false for a file that does not exist. It is not "false because the file has bytes" — the test cannot be answered, so it returns false. Testing -z first therefore sends a missing file down the "has content" path.

!-s is true for both. This is the form people reach for because it reads as "no size", and it is the one that silently merges the two cases.

-s on a missing file is undef, not 0. Which is Chapter 2.7 again: the two are different facts and only defined separates them. A size of zero is a measurement; undef means there was nothing to measure.

The rule is the same as every other gate in this module. Test the cheapest, most specific thing first, and test it in an order where each answer is meaningful — -e, then -z, then open.

5. Still Running Looks Exactly Like Truncated

One case the ladder cannot settle, and it is better to know that than to guess.

A log being written right now has no end marker. Neither does a log from a job the queue killed an hour ago. They are byte-for-byte the same shape, and no amount of reading the file distinguishes them, because the difference is not in the file.

What you can do is bound it from outside the file:

Age. If the log has not been modified for longer than any plausible write interval, the writer is gone. Chapter 17.9 measured -M for this, with its two surprises: it is relative to $^T, the script's start, and it is a named unary operator whose precedence silently breaks int(-M $f + 0.5). Parenthesise it.

A done-file. The cleanest answer, and it belongs to whoever runs the tool: have the job write a small marker file after the tool exits. Its existence is then a fact about the job rather than an inference about the log.

The queue. bjobs, qstat or the local equivalent knows whether the job is alive. This is the most accurate source and the least portable, which is a reason to isolate it in one function.

Whichever you use, say which one in the message. "log has not changed in 40 minutes, assuming the job is gone" is a sentence somebody can argue with; NO_FINISH alone is not. And if none is available, the honest report is still exit 3 — an unknown state is a result, as Chapter 18.7's unknown-state rule put it, as long as it is reported as one.

6. What To Remember

• The dangerous failure is not a crash. It is a clean pass on nothing.
• Measured, 7 logs: the naive scanner is wrong on 5 — four false passes and one false failure.
• The four false passes are absent, empty, truncated mid-run, and never started. None contains an error line, which is the point.
• The false failure is on the only healthy log, whose summary line UVM_ERROR : 0 matches ^UVM_ERROR (18.4).
• On these seven inputs the naive verdict is anti-correlated with the truth.
• My own first ladder had the same bug — the summary rule must come before the counting line.
• A test set of only broken inputs cannot prove your checker accepts good ones.
• The ladder: exists → non-empty → opens → start marker → end marker → verdict.
• Order matters: -e before -z. -z is false for a missing file, and !-s is true for both.
• -s on a missing file is undef, not 0 — only defined separates them (2.7).
• The end marker must come from the tool, not the test — verify it appears in a run you know failed.
• Incomplete and failing are independent. Return a pair; both.log is NO_FINISH with 1 error seen.
• An error count from a truncated log is a floor, not a total — say so.
• Every incomplete state exits 3, not 0 and not 1 (15.4).
• Still-running and truncated are identical in the file. Bound it with mtime age (17.9, and parenthesise -M), a done-file, or the queue — and name which one you used.

Chapter 18.10 changes the constraint. Everything so far reads a log that fits comfortably in memory; the next chapter takes one far larger than the machine has RAM, where the question stops being what to match and becomes what never to hold on to.