Stripping ANSI Codes, Banners and Timestamps

Part II · Module 18 · Chapter 18.3 · Stripping ANSI Codes, Banners and Timestamps

1. The Same Message, Three Shapes

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

# ---- three SAMPLE lines, written to resemble what different tools emit:
#      a) a filename wrapped in ANSI colour escapes
#      b) a wall-clock timestamp prefix, added by a wrapper script
#      c) a leading severity marker of the "# ** Error:" kind
my $dir = tempdir(CLEANUP => 1);
my %raw = (
  "a.log" => "UVM_ERROR \e[31mtb/sb.sv(151)\e[0m \@ 2400: mismatch\n",
  "b.log" => "[09:14:22] UVM_ERROR tb/sb.sv(151) \@ 2400: mismatch\n",
  "c.log" => "# ** Error: UVM_ERROR tb/sb.sv(151) \@ 2400: mismatch\n",
);
for my $f (sort keys %raw) {
    open my $w, ">", File::Spec->catfile($dir, $f) or die "cannot write: $!\n";
    print $w $raw{$f};
    close $w;
}

# ---- the three strippers
my $ANSI  = qr/\e\[[0-9;?]*[ -\/]*[\@-~]/;          # a CSI escape sequence
my $STAMP = qr/\A\[\d{2}:\d{2}:\d{2}(?:\.\d+)?\]\s*/;
my $MARK  = qr/\A#\s*\*\*\s*(?:Error|Warning|Note|Fatal)\s*:\s*/;

sub clean {
    my ($line) = @_;
    $line =~ s/$ANSI//g;      # colour first: a stamp could be coloured too
    $line =~ s/$STAMP//;
    $line =~ s/$MARK//;
    $line =~ s/\s+\z//;
    return $line;
}

my @cleaned;
printf "%-7s %-6s %s\n", "FILE", "STAGE", "LINE";
for my $f (sort keys %raw) {
    open my $fh, "<", File::Spec->catfile($dir, $f) or die "cannot read: $!\n";
    my $line = <$fh>;
    close $fh;
    chomp $line;
    (my $shown = $line) =~ s/\e/<ESC>/g;            # make the escape visible
    printf "%-7s %-6s %s\n", $f, "raw",   $shown;
    my $c = clean($line);
    printf "%-7s %-6s %s\n", "",  "clean", $c;
    push @cleaned, $c;
}

printf "\nall three clean to identical text? %s\n",
    ((grep { $_ eq $cleaned[0] } @cleaned) == 3 ? "YES" : "no");

# ---- and what an anchored pattern does to the RAW lines
print "\n/^UVM_ERROR\\s/ applied to each RAW line:\n";
my $hits = 0;
for my $f (sort keys %raw) {
    my $line = $raw{$f};
    chomp $line;
    my $m = $line =~ /^UVM_ERROR\s/;
    $hits += !!$m;
    printf "   %-7s %s\n", $f, ($m ? "match" : "NO MATCH");
}
printf "   -> %d of %d raw lines matched; a parser would report %d error(s)\n",
    $hits, scalar(keys %raw), $hits;
printf "   after cleanup, all %d match\n", scalar(keys %raw);

FILE    STAGE  LINE
a.log   raw    UVM_ERROR <ESC>[31mtb/sb.sv(151)<ESC>[0m @ 2400: mismatch
        clean  UVM_ERROR tb/sb.sv(151) @ 2400: mismatch
b.log   raw    [09:14:22] UVM_ERROR tb/sb.sv(151) @ 2400: mismatch
        clean  UVM_ERROR tb/sb.sv(151) @ 2400: mismatch
c.log   raw    # ** Error: UVM_ERROR tb/sb.sv(151) @ 2400: mismatch
        clean  UVM_ERROR tb/sb.sv(151) @ 2400: mismatch

all three clean to identical text? YES

/^UVM_ERROR\s/ applied to each RAW line:
   a.log   match
   b.log   NO MATCH
   c.log   NO MATCH
   -> 1 of 3 raw lines matched; a parser would report 1 error(s)
   after cleanup, all 3 match

Two measured results, and the second is the one that costs time.

All three clean to byte-identical text. The message was always the same; only the decoration differed.

/^UVM_ERROR\s/ matched one of the three raw lines. The ANSI line matched, because its escape codes come after the severity. The timestamped line and the marked line did not, because something else is at the start of the line — and an anchored pattern means exactly that.

So a parser developed against one tool, pointed at logs from another, reports zero errors. Chapter 18.2 measured why that is the worst available answer: zero errors is a pass.

2. The Three Strippers

ANSI escape sequences. A colour escape is ESC [ then parameters then a final letter:

my $ANSI = qr/\e\[[0-9;?]*[ -\/]*[\@-~]/;

\e is the escape character — Chapter 4.3's escape sequences. The character classes cover the parameter bytes, the intermediate bytes and the final byte of a CSI sequence, which is more than colour alone and catches cursor movement a progress indicator leaves behind.

Strip this first, because a tool that colours its output may also colour the timestamp, and a $STAMP pattern anchored with \A will not match a line that starts with an escape.

A timestamp prefix.

my $STAMP = qr/\A\[\d{2}:\d{2}:\d{2}(?:\.\d+)?\]\s*/;

Anchored with \A so a time inside a message is left alone — which matters, because a message quoting a time is data. The optional (?:\.\d+)? covers sub-second stamps.

A leading severity marker.

my $MARK = qr/\A#\s*\*\*\s*(?:Error|Warning|Note|Fatal)\s*:\s*/;

Note the escaped \*: an asterisk is a quantifier otherwise — Chapter 11.4. And note that this is stripped after the timestamp, since a wrapper may have prefixed a marked line.

Order matters and is worth a comment in the code, because the three are not commutative.

3. What Not to Strip

This is the half that keeps a parser honest.

Do not strip the severity itself. The marker # ** Error: is the tool's severity; UVM_ERROR is the testbench's. They are different facts and sometimes disagree — a UVM_INFO line can carry a tool-level error marker when the tool had its own problem writing it. Strip the wrapper, keep both severities available.

Do not strip leading whitespace indiscriminately. Indentation is structure in a sectioned report — an STA path block indents its elements, and Chapter 18.6 relies on that to find where a record ends. A global s/^\s+// destroys it.

Do not strip the line number or the simulation time. tb/sb.sv(151) and @ 2400 are the two most useful fields on the line. Chapter 18.5 extracts them.

Do not strip carriage returns blindly. A log written on one platform and read on another has \r\n endings, and the \r survives chomp on Unix — so (\S+)\z captures a trailing \r and a later eq fails. The fix is targeted:

$line =~ s/\r\z//;          # a DOS line ending

not a global tr/\r//d, which would also delete a \r inside a quoted string in a message.

4. Normalise for Diffing, Too

The same strippers solve the other problem in this module, which is comparing two runs.

Chapter 17.8 measured that a report differing between identical runs makes a diff meaningless. A log has three sources of that, and all of them are per-line decoration:

Wall-clock timestamps. Two runs of the same test have different ones on every line, so diff reports every line as changed.

Absolute paths containing the run directory. /scratch/jm/runs/alu_1_4412/sim.log differs per run. Strip the run directory to a relative path, as Chapter 17.8's final section showed.

CPU and memory figures in the epilogue. Real measurements, and never identical. Drop them from a comparison rather than from the log.

So a comparison pipeline normalises more aggressively than a parser does:

# for DIFFING only -- not for parsing
sub for_diff {
    my ($l) = @_;
    $l = normalise($l);                               # the shared strippers
    $l =~ s/\@\s*\d+/\@ <TIME>/g;                     # simulation time
    $l =~ s{\Q$rundir\E/?}{}g;                        # the run directory
    return $l;
}

And the distinction between normalise and for_diff is the point: a parser must keep the simulation time, because Chapter 18.5 extracts it. A diff must mask it, because it changes. Using one function for both loses one of the two jobs — which is how a flow ends up either with an unusable diff or a parser that cannot report when something happened.

5. What To Remember

• A parser that works on one tool's logs can find nothing in another's, and the message is usually identical.
• Measured: three raw lines normalise to byte-identical text.
• Measured: /^UVM_ERROR\s/ matched 1 of 3 raw lines — so the parser reports zero errors for the other two, which is a pass.
• The ANSI line matched because its escapes come after the severity; the prefixed lines did not.
• Do not fix it by dropping the anchor — that reintroduces every false positive from Chapter 18.1.
• Normalise, then anchor. Two jobs.
• Strip ANSI first, because a stamp may itself be coloured and \A would then not match.
• Anchor the timestamp stripper with \A, so a time inside a message survives.
• Escape the * in # ** Error: — it is a quantifier otherwise.
• The three strippers are not commutative; comment the order.
• Keep the tool's severity and the testbench's severity — they are different facts and can disagree.
• Do not strip leading whitespace — indentation is structure that Chapter 18.6 depends on.
• Keep the line number and the simulation time — Chapter 18.5 extracts both.
• Strip \r with s/\r\z//, not a global delete that would eat one inside a message.
• Put the strippers in one shared function, so two parsers cannot disagree about what a line contained.
• A diff needs more masking than a parser: simulation time and the run directory must go for comparison and must stay for extraction. Two functions.

Chapter 18.4 is where the pattern itself gets built properly. Anchoring is necessary and it is not sufficient — the measurement shows that an anchored severity pattern still counts the log's own summary line.