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 --- .cirrus.yml | 24 ++- contrib/cirrus/logformatter | 437 ++++++++++++++++++++++++++++++++++++++++++ test/e2e/libpod_suite_test.go | 2 + 3 files changed, 454 insertions(+), 9 deletions(-) create mode 100755 contrib/cirrus/logformatter diff --git a/.cirrus.yml b/.cirrus.yml index 151153b14..39b2bdc1a 100644 --- a/.cirrus.yml +++ b/.cirrus.yml @@ -27,6 +27,9 @@ env: # (can't do inline awk script, Cirrus-CI or YAML mangles quoting) TIMESTAMP: "awk --file ${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/timestamp.awk" + # HTMLify ginkgo and bats logs + LOGFORMAT: "${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/logformatter" + #### #### Cache-image names to test with (double-quotes around names are critical) ### @@ -396,9 +399,9 @@ testing_task: networking_script: '${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/networking.sh' setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}' unit_test_script: '$SCRIPT_BASE/unit_test.sh |& ${TIMESTAMP}' - integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}' - system_test_script: '$SCRIPT_BASE/system_test.sh |& ${TIMESTAMP}' - apiv2_test_script: '$SCRIPT_BASE/apiv2_test.sh |& ${TIMESTAMP}' + integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} integration_test' + system_test_script: '$SCRIPT_BASE/system_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} system_test' + apiv2_test_script: '$SCRIPT_BASE/apiv2_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} apiv2_test' build_release_script: '$SCRIPT_BASE/build_release.sh |& ${TIMESTAMP}' # For PRs this confirms uploading releases after merge, is functional. upload_release_archive_script: '$SCRIPT_BASE/upload_release_archive.sh |& ${TIMESTAMP}' @@ -419,6 +422,9 @@ testing_task: journal_script: '$SCRIPT_BASE/logcollector.sh journal' varlink_script: '$SCRIPT_BASE/logcollector.sh varlink' podman_system_info_script: '$SCRIPT_BASE/logcollector.sh podman' + html_artifacts: + path: "*.log.html" + type: "text/html" # This task executes tests under unique environments/conditions @@ -446,9 +452,9 @@ special_testing_rootless_task: networking_script: '${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/networking.sh' setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}' - integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}' - system_test_script: '$SCRIPT_BASE/system_test.sh |& ${TIMESTAMP}' - apiv2_test_script: '$SCRIPT_BASE/apiv2_test.sh |& ${TIMESTAMP}' + integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} integration_test' + system_test_script: '$SCRIPT_BASE/system_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} system_test' + apiv2_test_script: '$SCRIPT_BASE/apiv2_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} apiv2_test' on_failure: failed_branch_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_branch_failure.sh' @@ -490,7 +496,7 @@ special_testing_in_podman_task: networking_script: '${CIRRUS_WORKING_DIR}/${SCRIPT_BASE}/networking.sh' setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}' - integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}' + integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} integration_test' on_failure: failed_branch_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_branch_failure.sh' @@ -552,7 +558,7 @@ special_testing_bindings_task: timeout_in: 40m setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}' - integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}' + integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} integration_test' on_failure: failed_branch_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_branch_failure.sh' @@ -578,7 +584,7 @@ special_testing_endpoint_task: timeout_in: 20m setup_environment_script: '$SCRIPT_BASE/setup_environment.sh |& ${TIMESTAMP}' - integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP}' + integration_test_script: '$SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} | ${LOGFORMAT} integration_test' on_failure: failed_branch_script: '$CIRRUS_WORKING_DIR/$SCRIPT_BASE/notice_branch_failure.sh' 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; diff --git a/test/e2e/libpod_suite_test.go b/test/e2e/libpod_suite_test.go index 43f08bf03..dc5e91c72 100644 --- a/test/e2e/libpod_suite_test.go +++ b/test/e2e/libpod_suite_test.go @@ -122,6 +122,8 @@ func populateCache(podman *PodmanTestIntegration) { for _, image := range CACHE_IMAGES { podman.RestoreArtifactToCache(image) } + // logformatter uses this to recognize the first test + fmt.Printf("-----------------------------\n") } func removeCache() { -- cgit v1.2.3-54-g00ecf