From 1814638000985ccc0297a8694d1fa8c4aacae3b8 Mon Sep 17 00:00:00 2001 From: Ed Santiago Date: Thu, 27 Feb 2020 08:17:37 -0700 Subject: CI: format cirrus logs This introduces a new cirrus helper script, logformatter. Usage is: [commands...] | logformatter TEST-NAME It reformats its input into a readable, highlighed, linkable form. Some features: - boring stuff (timestamps, standard podman options) is deemphasized - important stuff (warnings, errors) is emphasized - in-page links to the actual failures - active links to source files - jumps to bottom of page on load, because that's where the errors are. (All errors are linked) Add it to select test commands (integration, system) and add a new artifacts_html, run in the 'always' block, which uploads generated *.log.html into Cirrus; from there we generate a live URL that can be viewed in browser. Unfortunately, due to security concerns in Cirrus, it is not currently possible to make the link a live one. Kludge: add a line of dashes after Restoring images; without this, the first test ("systemd PID 1") has no dashes before it, so logformatter doesn't see it. Signed-off-by: Ed Santiago --- contrib/cirrus/logformatter | 437 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 437 insertions(+) create mode 100755 contrib/cirrus/logformatter (limited to 'contrib/cirrus') diff --git a/contrib/cirrus/logformatter b/contrib/cirrus/logformatter new file mode 100755 index 000000000..4cc4480f5 --- /dev/null +++ b/contrib/cirrus/logformatter @@ -0,0 +1,437 @@ +#!/usr/bin/perl +# +# logformatter - highlight a Cirrus test log (ginkgo or bats) +# +# Adapted from https://raw.githubusercontent.com/edsantiago/greasemonkey/podman-ginkgo-highlight +# +package LibPod::CI::LogFormatter; + +use v5.14; +use utf8; + +# Grumble. CI system doesn't have 'open' +binmode STDIN, ':utf8'; +binmode STDOUT, ':utf8'; + +use strict; +use warnings; + +(our $ME = $0) =~ s|.*/||; + +our $VERSION = '0.1'; + +# For debugging, show data structures using DumpTree($var) +#use Data::TreeDumper; $Data::TreeDumper::Displayaddress = 0; + +############################################################################### +# BEGIN user-customizable section + +# Stylesheet for highlighting or de-highlighting parts of lines +our $CSS = <<'END_CSS'; +/* wrap long lines - don't require user to scroll right */ +pre { line-break: normal; overflow-wrap: normal; white-space: pre-wrap; } + +.boring { color: #999; } +.timestamp { color: #999; } +.log-debug { color: #999; } +.log-info { color: #333; } +.log-warn { color: #f60; } +.log-error { color: #900; font-weight: bold; } +.subtest { background: #eee; } +.subsubtest { color: #F39; font-weight: bold; } +.string { color: #00c; } +.command { font-weight: bold; color: #000; } +.changed { color: #000; font-weight: bold; } + +/* links to source files: not as prominent as links to errors */ +a.codelink:link { color: #000; } +a.codelink:visited { color: #666; } +a.codelink:hover { background: #000; color: #999; } + +/* The timing tests at bottom: remove underline, it's too cluttery. */ +a.timing { text-decoration: none; } + +/* BATS styles */ +.bats-ok { color: #3f3; } +.bats-notok { color: #F00; font-weight: bold; } +.bats-skip { color: #F90; } +.bats-log { color: #900; } +.bats-log-esm { color: #b00; font-weight: bold; } + +/* error titles: display next to timestamp, not on separate line */ +h2 { display: inline; } +END_CSS + +# END user-customizable section +############################################################################### + +############################################################################### +# BEGIN boilerplate args checking, usage messages + +sub usage { + print <<"END_USAGE"; +Usage: $ME [OPTIONS] TEST_NAME + +$ME is a filter; it HTMLifies an input stream (presumably +Ginkgo or BATS log results), writing HTML results to an output file +but passing stdin unmodified to stdout. It is intended to run in +the Cirrus CI environment. + +Parameters: + + TEST_NAME descriptive name; output file will be TEST_NAME.log.html + +OPTIONS: + + --help display this message + --man display program man page + --version display program name and version +END_USAGE + + exit; +} + +# Command-line options. Note that this operates directly on @ARGV ! +our $debug = 0; +our $force = 0; +our $verbose = 0; +our $NOT = ''; # print "blahing the blah$NOT\n" if $debug +sub handle_opts { + use Getopt::Long; + GetOptions( + 'debug!' => \$debug, + 'dry-run|n!' => sub { $NOT = ' [NOT]' }, + 'force' => \$force, + 'verbose|v' => \$verbose, + + help => \&usage, + version => sub { print "$ME version $VERSION\n"; exit 0 }, + ) or die "Try `$ME --help' for help\n"; +} + +# END boilerplate args checking, usage messages +############################################################################### + +############################## CODE BEGINS HERE ############################### + +# The term is "modulino". +__PACKAGE__->main() unless caller(); + +# Main code. +sub main { + # Note that we operate directly on @ARGV, not on function parameters. + # This is deliberate: it's because Getopt::Long only operates on @ARGV + # and there's no clean way to make it use @_. + handle_opts(); # will set package globals + + # In case someone is tempted to run us on the command line + die "$ME: this is a filter, not an interactive script\n" if -t *STDIN; + + # Fetch command-line arguments. Barf if too many. + my $test_name = shift(@ARGV) + or die "$ME: missing TEST_NAME argument; try $ME --help\n"; + warn "$ME: Too many arguments; ignoring extras. try $ME --help\n" if @ARGV; + + format_log($test_name); +} + + +sub format_log { + my $test_name = shift; # in: e.g. 'integration_test' + + my $outfile = "$test_name.log.html"; + my $out_tmp = "$outfile.tmp.$$"; + open my $out_fh, '>:utf8', $out_tmp + or warn "$ME: Cannot create $out_tmp: $!\n"; + + # Boilerplate: HTML headers for output file + print { $out_fh } <<"END_HTML" if $out_fh; + + + + + +$test_name + + + + + + +
+END_HTML
+
+    # State variables
+    my $previous_timestamp = '';  # timestamp of previous line
+    my $cirrus_task;              # Cirrus task number, used for linking
+    my $git_commit;               # git SHA, used for linking to source files
+    my $in_failure;               # binary flag: are we in an error dump?
+    my $in_timing;                # binary flag: are we in the timing section?
+    my $after_divider = 0;        # Count of lines after seeing '-----'
+    my $current_output;           # for removing duplication
+    my $looks_like_bats;          # binary flag: for detecting BATS results
+
+    # Main loop: read input, one line at a time, and write out reformatted
+  LINE:
+    while (my $line = ) {
+        print $line;                    # Immediately dump back to stdout
+
+        # Remain robust in face of errors: always write stdout even if no HTML
+        next LINE if ! $out_fh;
+
+        chomp $line;
+        $line =~ s/\0//g;               # Some log files have NULs????
+        $line = escapeHTML($line);
+
+        # Temporarily strip off leading timestamp
+        $line =~ s/^(\[\+\d+s\]\s)//;
+        my $timestamp = $1 || '';
+        if ($previous_timestamp && $timestamp eq $previous_timestamp) {
+            $timestamp = ' ' x length($timestamp);
+        }
+        elsif ($timestamp) {
+            $previous_timestamp = $timestamp;
+        }
+
+        # Try to identify the git commit we're working with...
+        if ($line =~ m!libpod/define.gitCommit=([0-9a-f]+)!) {
+            $git_commit = $1;
+        }
+        # ...so we can link to specific lines in source files
+        if ($git_commit) {
+            #           1  12  3                  34     4 5   526  6
+            $line =~ s{^(.*)(\/(containers\/libpod)(\/\S+):(\d+))(.*)$}
+                      {$1$2$6};
+        }
+
+        # Try to identify the cirrus task
+        if ($line =~ /cirrus-task-(\d+)/) {
+            $cirrus_task = $1;
+        }
+
+        # BATS handling
+        if ($line =~ /^1\.\.\d+$/) {
+            $looks_like_bats = 1;
+        }
+        if ($looks_like_bats) {
+            my $css;
+
+            if    ($line =~ /^ok\s.*\s# skip/) { $css = 'skip'    }
+            elsif ($line =~ /^ok\s/)           { $css = 'ok'      }
+            elsif ($line =~ /^not\s+ok\s/)     { $css = 'notok'   }
+            elsif ($line =~ /^#\s#\|\s/)       { $css = 'log-esm' }
+            elsif ($line =~ /^#\s/)            { $css = 'log'     }
+
+            if ($css) {
+                $line = "$line";
+            }
+
+            print { $out_fh } "$timestamp"
+                if $timestamp;
+            print { $out_fh } $line, "\n";
+            next LINE;
+        }
+
+        # Timing section at the bottom of the page
+        if ($line =~ / timing results\s*$/) {
+            $in_timing = 1;
+        }
+        elsif ($in_timing) {
+            if ($line =~ /^(\S.*\S)\s+(\d+\.\d+)\s*$/) {
+                my ($name, $time) = ($1, $2);
+                my $id = make_id($1, 'timing');
+
+                # Try to column-align the timing numbers. Some test names
+                # will be longer than our max - oh well.
+                my $spaces = 80 - length(unescapeHTML($name));
+                $spaces = 1 if $spaces < 1;
+                $spaces++ if $time < 10;
+                my $spacing = ' ' x $spaces;
+                $line = qq{$name$spacing$time};
+            }
+            else {
+                $in_timing = 0;
+            }
+        }
+
+        #
+        # Ginkgo error reformatting
+        #
+        if ($line =~ /^.{1,4} (Failure|Panic)( in .*)? \[/) {
+            # Begins a block of multiple lines including a stack trace
+            print { $out_fh } "
\n";
+            $in_failure = 1;
+        }
+        elsif ($line =~ /^-----------/) {
+            if ($in_failure) {
+                # Ends a stack trace block
+                $in_failure = 0;
+                print { $out_fh } "
\n";
+            }
+            $after_divider = 1;
+
+            print { $out_fh } "
\n
\n
\n";
+            # Always show timestamp at start of each new test
+            $previous_timestamp = '';
+            next LINE;
+        }
+        elsif ($line =~ /^Running:/) {
+            # Highlight the important (non-boilerplate) podman command.
+            # Strip out the global podman options, but show them on hover
+            $line =~ s{(\S+\/podman)((\s+--(root|runroot|runtime|tmpdir|storage-opt|conmon|cgroup-manager|cni-config-dir|storage-driver|events-backend) \S+)*)(.*)}{
+                my ($full_path, $options, $args) = ($1, $2, $5);
+
+                $options =~ s/^\s+//;
+                # Separate each '--foo bar' with newlines for readability
+                $options =~ s/ --/\n--/g;
+                qq{podman [options]$args};
+            }e;
+            $current_output = '';
+        }
+        # Grrr. 'output:' usually just tells us what we already know.
+        elsif ($line =~ /^output:/) {
+            $current_output =~ s!^\s+|\s+$!!g;  # Trim leading/trailing blanks
+            $current_output =~ s/\s+/ /g;       # Collapse multiple spaces
+            if ($line eq "output: $current_output" || $line eq 'output: ') {
+                next LINE;
+            }
+        }
+        elsif ($line =~ /^Error:/ || $line =~ / level=(warning|error) /) {
+            $line = "" . $line . "";
+        }
+        else {
+            $current_output .= ' ' . $line;
+        }
+
+
+        # Two lines after each divider, there's a test name. Make it
+        # an anchor so we can link to it later.
+        if ($after_divider++ == 2) {
+            # Sigh. There is no actual marker. Assume that anything with
+            ## two leading spaces then alpha (not slashes) is a test name.
+            if ($line =~ /^  [a-zA-Z]/) {
+                my $id = make_id($line, 'anchor');
+
+                $line = "
$line
";
+            }
+        }
+
+        # Failure name corresponds to a previously-seen block.
+        ## FIXME: sometimes there are three failures with the same name.
+        ##        ...I have no idea why or how to link to the right ones.
+        #              1  2           2        3             3   14          4
+        if ($line =~ /^(\[(Fail|Panic!)\] .* \[(It|BeforeEach)\] )([A-Za-z].*)/) {
+            my ($lhs, $type, $ginkgo_fluff, $testname) = ($1, $2, $3, $4);
+            my $id = make_id($testname, 'link');
+
+            $line = "$lhs$testname";
+        }
+
+        print { $out_fh } "$timestamp"
+            if $timestamp;
+        print { $out_fh } $line, "\n";
+    }
+
+    my $have_formatted_log;     # Set on success
+
+    if ($out_fh) {
+        print { $out_fh } "
\n"; + + # Did we find a cirrus task? Link back. + if ($cirrus_task) { + print { $out_fh } <<"END_HTML"; +
+

Cirrus task $cirrus_task

+END_HTML + } + + # FIXME: need a safe way to get TZ + printf { $out_fh } <<"END_HTML", scalar(CORE::localtime); +
+Processed %s by $ME v$VERSION + + +END_HTML + + if (close $out_fh) { + if (rename $out_tmp => $outfile) { + $have_formatted_log = 1; + } + else { + warn "$ME: Could not rename $out_tmp: $!\n"; + } + } + else { + warn "$ME: Error writing $out_tmp: $!\n"; + } + } + + # FIXME: if Cirrus magic envariables are available, write a link to results + if ($have_formatted_log && $ENV{CIRRUS_TASK_ID}) { + my $URL_BASE = "https://storage.googleapis.com"; + my $STATIC_MAGIC_BLOB = "cirrus-ci-5385732420009984-fcae48"; + my $ARTIFACT_NAME = "html"; + + my $URL = "${URL_BASE}/${STATIC_MAGIC_BLOB}/artifacts/$ENV{CIRRUS_REPO_FULL_NAME}/$ENV{CIRRUS_TASK_ID}/${ARTIFACT_NAME}/${outfile}"; + + print "\n\nAnnotated results:\n $URL\n"; + } +} + + +############# +# make_id # Given a test name, generate an anchor link name +############# +sub make_id { + my $name = shift; # in: test title + my $type = shift; # in: differentiator (anchor, link) + + state %counter; + + $name =~ s/^\s+|\s+$//g; # strip leading/trailing whitespace + $name =~ s/[^a-zA-Z0-9_-]/-/g; # Convert non-alphanumeric to dash + + # Keep a running tally of how many times we've seen this identifier + # for this given type! This lets us cross-match, in the bottom of + # the page, the first/second/third failure of a given test. + $name .= "--" . ++$counter{$type}{$name}; + + $name; +} + + + +sub escapeHTML { + my $s = shift; + + state %chars; + %chars = ('&' => '&', '<' => '<', '>' => '>', '"' => '"', "'" => ''') + if keys(%chars) == 0; + my $class = join('', sort keys %chars); + $s =~ s/([$class])/$chars{$1}/ge; + + return $s; +} + +sub unescapeHTML { + my $s = shift; + + # We don't actually care about the character, only its length + $s =~ s/\&\#?[a-z0-9]+;/./g; + + return $s; +} + + +1; -- cgit v1.2.3-54-g00ecf