#!/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; } /* synopsis table at top */ table.synopsis { border: none; border-collapse: collapse; margin-left: 2em; margin-top: 2ex; } .synopsis th { font-weight: normal; font-size: 110%; text-align: right; } .synopsis td { font-weight: bold; font-size: 120%; font-family: monospace; } /* test results */ .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; } .timing:hover { background: #FF9; } /* highlight row for easy reading */ /* BATS styles */ .bats-passed { color: #393; } .bats-failed { color: #F00; font-weight: bold; } .bats-skipped { color: #F90; } .bats-log { color: #900; } .bats-log-esm { color: #b00; font-weight: bold; } .bats-summary { font-size: 150%; } /* 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;
\n"; # Main loop: read input, one line at a time, and write out reformatted LINE: while (my $line =\n) { 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!/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\/[^/]+)(\/\S+):(\d+))(.*)$} {$1$2$6}; } # Try to identify the cirrus task if ($line =~ /cirrus-task-(\d+)/) { $cirrus_task = $1; } # BATS handling (used also for apiv2 tests, which emit TAP output) if ($line =~ /^1\.\.(\d+)$/ || $line =~ m!/test-apiv2!) { $looks_like_bats = 1; $bats_count{expected_total} = $1; } if ($looks_like_bats) { my $css; # Readability: /long/path/to/podman -> podman (hover for full path) # Also make it boldface, to make commands stand out $line =~ s{^(#\s+(#|\$)\s+)(\S+/)(podman\S*)(\s.*)} {$1$4$5}; if ($line =~ /^ok\s.*\s# skip/) { $css = 'skipped' } elsif ($line =~ /^ok\s/) { $css = 'passed' } elsif ($line =~ /^not\s+ok\s/) { $css = 'failed' } elsif ($line =~ /^#\s#\|\s/) { $css = 'log-esm' } elsif ($line =~ /^#\s/) { $css = 'log' } if ($css) { # Make it linkable, e.g. foo.html#t--00001 if ($line =~ /^(not\s+)?ok\s+(\d+)/) { $line = sprintf("%s", $2, $line); } $line = "$line"; $bats_count{$css}++; } print { $out_fh } " " 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"; # Always show timestamp at start of each new test $previous_timestamp = ''; next LINE; } # (bindings test sometimes emits 'Running' with leading bullet char) elsif ($line =~ /^•?Running:/) { # Highlight the important (non-boilerplate) podman command. $line =~ s/\s+--remote\s+/ /g; # --remote takes no args # Strip out the global podman options, but show them on hover $line =~ s{(\S+\/podman(-remote)?)((\s+--(root|runroot|runtime|tmpdir|storage-opt|conmon|cgroup-manager|cni-config-dir|storage-driver|events-backend|url) \S+)*)(.*)}{ my ($full_path, $remote, $options, $args) = ($1, $2||'', $3, $6); $options =~ s/^\s+//; # Separate each '--foo bar' with newlines for readability $options =~ s/ --/\n--/g; qq{podman$remote [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 . ""; } elsif ($line =~ /^panic:/) { $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 = "\n"; # Did we find a cirrus task? Link back. if ($cirrus_task) { print { $out_fh } <<"END_HTML";$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 } " " if $timestamp; print { $out_fh } $line, "\n"; } my $have_formatted_log; # Set on success if ($out_fh) { # Summary line for BATS tests if (keys %bats_count) { print { $out_fh } "
Summary:"; my $total = 0; my $comma = ''; for my $class (qw(passed failed skipped)) { if (my $n = $bats_count{$class}) { printf { $out_fh } "%s %d %s", $comma, $class, $n, ucfirst($class); $total += $n; $comma = ','; } } printf { $out_fh } ". Total tests: $total"; if (my $expected_total = $bats_count{expected_total}) { if ($total != $expected_total) { print { $out_fh } " (WARNING: expected $expected_total)"; } } print { $out_fh } "\n"; } print { $out_fh } "