github.com/containers/podman/v2@v2.2.2-0.20210501105131-c1e07d070c4c/contrib/cirrus/logformatter (about) 1 #!/usr/bin/perl 2 # 3 # logformatter - highlight a Cirrus test log (ginkgo or bats) 4 # 5 # Adapted from https://raw.githubusercontent.com/edsantiago/greasemonkey/podman-ginkgo-highlight 6 # 7 package LibPod::CI::LogFormatter; 8 9 use v5.14; 10 use utf8; 11 12 # Grumble. CI system doesn't have 'open' 13 binmode STDIN, ':utf8'; 14 binmode STDOUT, ':utf8'; 15 16 use strict; 17 use warnings; 18 19 (our $ME = $0) =~ s|.*/||; 20 21 our $VERSION = '0.1'; 22 23 # For debugging, show data structures using DumpTree($var) 24 #use Data::TreeDumper; $Data::TreeDumper::Displayaddress = 0; 25 26 ############################################################################### 27 # BEGIN user-customizable section 28 29 # Stylesheet for highlighting or de-highlighting parts of lines 30 our $CSS = <<'END_CSS'; 31 /* wrap long lines - don't require user to scroll right */ 32 pre { line-break: normal; overflow-wrap: normal; white-space: pre-wrap; } 33 34 /* synopsis table at top */ 35 table.synopsis { border: none; border-collapse: collapse; margin-left: 2em; margin-top: 2ex; } 36 .synopsis th { font-weight: normal; font-size: 110%; text-align: right; } 37 .synopsis td { font-weight: bold; font-size: 120%; font-family: monospace; } 38 39 /* test results */ 40 .boring { color: #999; } 41 .timestamp { color: #999; } 42 .log-debug { color: #999; } 43 .log-info { color: #333; } 44 .log-warn { color: #f60; } 45 .log-error { color: #900; font-weight: bold; } 46 .subtest { background: #eee; } 47 .subsubtest { color: #F39; font-weight: bold; } 48 .string { color: #00c; } 49 .command { font-weight: bold; color: #000; } 50 .changed { color: #000; font-weight: bold; } 51 52 /* links to source files: not as prominent as links to errors */ 53 a.codelink:link { color: #000; } 54 a.codelink:visited { color: #666; } 55 a.codelink:hover { background: #000; color: #999; } 56 57 /* The timing tests at bottom: remove underline, it's too cluttery. */ 58 a.timing { text-decoration: none; } 59 .timing:hover { background: #FF9; } /* highlight row for easy reading */ 60 61 /* BATS styles */ 62 .bats-passed { color: #393; } 63 .bats-failed { color: #F00; font-weight: bold; } 64 .bats-skipped { color: #F90; } 65 .bats-log { color: #900; } 66 .bats-log-esm { color: #b00; font-weight: bold; } 67 68 .bats-summary { font-size: 150%; } 69 70 /* error titles: display next to timestamp, not on separate line */ 71 h2 { display: inline; } 72 END_CSS 73 74 # END user-customizable section 75 ############################################################################### 76 77 ############################################################################### 78 # BEGIN boilerplate args checking, usage messages 79 80 sub usage { 81 print <<"END_USAGE"; 82 Usage: $ME [OPTIONS] TEST_NAME 83 84 $ME is a filter; it HTMLifies an input stream (presumably 85 Ginkgo or BATS log results), writing HTML results to an output file 86 but passing stdin unmodified to stdout. It is intended to run in 87 the Cirrus CI environment. 88 89 Parameters: 90 91 TEST_NAME descriptive name; output file will be TEST_NAME.log.html 92 93 OPTIONS: 94 95 --help display this message 96 --man display program man page 97 --version display program name and version 98 END_USAGE 99 100 exit; 101 } 102 103 # Command-line options. Note that this operates directly on @ARGV ! 104 our $debug = 0; 105 our $force = 0; 106 our $verbose = 0; 107 our $NOT = ''; # print "blahing the blah$NOT\n" if $debug 108 sub handle_opts { 109 use Getopt::Long; 110 GetOptions( 111 'debug!' => \$debug, 112 'dry-run|n!' => sub { $NOT = ' [NOT]' }, 113 'force' => \$force, 114 'verbose|v' => \$verbose, 115 116 help => \&usage, 117 version => sub { print "$ME version $VERSION\n"; exit 0 }, 118 ) or die "Try `$ME --help' for help\n"; 119 } 120 121 # END boilerplate args checking, usage messages 122 ############################################################################### 123 124 ############################## CODE BEGINS HERE ############################### 125 126 # The term is "modulino". 127 __PACKAGE__->main() unless caller(); 128 129 # Main code. 130 sub main { 131 # Note that we operate directly on @ARGV, not on function parameters. 132 # This is deliberate: it's because Getopt::Long only operates on @ARGV 133 # and there's no clean way to make it use @_. 134 handle_opts(); # will set package globals 135 136 # In case someone is tempted to run us on the command line 137 die "$ME: this is a filter, not an interactive script\n" if -t *STDIN; 138 139 # Fetch command-line arguments. Barf if too many. 140 my $test_name = shift(@ARGV) 141 or die "$ME: missing TEST_NAME argument; try $ME --help\n"; 142 warn "$ME: Too many arguments; ignoring extras. try $ME --help\n" if @ARGV; 143 144 format_log($test_name); 145 } 146 147 148 sub format_log { 149 my $test_name = shift; # in: e.g. 'integration_test' 150 151 my $outfile = "$test_name.log.html"; 152 my $out_tmp = "$outfile.tmp.$$"; 153 open my $out_fh, '>:utf8', $out_tmp 154 or warn "$ME: Cannot create $out_tmp: $!\n"; 155 156 # Boilerplate: HTML headers for output file 157 print { $out_fh } <<"END_HTML" if $out_fh; 158 <?xml version="1.0" encoding="utf-8"?> 159 <!DOCTYPE html 160 PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 161 "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"> 162 <html xmlns="http://www.w3.org/1999/xhtml" lang="en-US"> 163 <head> 164 <meta http-equiv="Content-Type" content="text/html; charset=utf-8" /> 165 <title>$test_name</title> 166 <style type="text/css"> 167 $CSS 168 </style> 169 170 <!-- on page load, go to bottom: that's where the error summary is --> 171 <script language="javascript"> 172 function scrollToBottom() { 173 if (window.scrollY < 10) { 174 window.scrollTo(0, document.body.scrollHeight); 175 } 176 } 177 window.addEventListener("load", scrollToBottom, false); 178 </script> 179 </head> 180 <body> 181 END_HTML 182 183 # Synopsis of this job: show job environment, links to PR and Cirrus 184 print { $out_fh } "<h2>Synopsis</h2>\n<hr/>\n", 185 job_synopsis($test_name), "<hr/>\n"; 186 187 # FOR DEBUGGING: dump environment, but in HTML comments to not clutter 188 print { $out_fh } "<!-- Environment: -->\n"; 189 for my $e (sort keys %ENV) { 190 my $val = escapeHTML($ENV{$e}); 191 $val =~ s/--/--/g; # double dash not valid in comments 192 printf { $out_fh } "<!-- %-20s %s -->\n", $e, $val; 193 } 194 195 # State variables 196 my $previous_timestamp = ''; # timestamp of previous line 197 my $cirrus_task; # Cirrus task number, used for linking 198 my $git_commit; # git SHA, used for linking to source files 199 my $in_failure; # binary flag: are we in an error dump? 200 my $in_timing; # binary flag: are we in the timing section? 201 my $after_divider = 0; # Count of lines after seeing '-----' 202 my $current_output; # for removing duplication 203 my $looks_like_bats; # binary flag: for detecting BATS results 204 my %bats_count; # For summary line: count of pass/fail/skip 205 206 print { $out_fh } "<pre> <!-- begin processed output -->\n"; 207 208 # Main loop: read input, one line at a time, and write out reformatted 209 LINE: 210 while (my $line = <STDIN>) { 211 print $line; # Immediately dump back to stdout 212 213 # Remain robust in face of errors: always write stdout even if no HTML 214 next LINE if ! $out_fh; 215 216 chomp $line; 217 $line =~ s/\0//g; # Some log files have NULs???? 218 $line = escapeHTML($line); 219 220 # Temporarily strip off leading timestamp 221 $line =~ s/^(\[\+\d+s\]\s)//; 222 my $timestamp = $1 || ''; 223 if ($previous_timestamp && $timestamp eq $previous_timestamp) { 224 $timestamp = ' ' x length($timestamp); 225 } 226 elsif ($timestamp) { 227 $previous_timestamp = $timestamp; 228 } 229 230 # Try to identify the git commit we're working with... 231 if ($line =~ m!/define.gitCommit=([0-9a-f]+)!) { 232 $git_commit = $1; 233 } 234 # ...so we can link to specific lines in source files 235 if ($git_commit) { 236 # 1 12 3 34 4 5 526 6 237 $line =~ s{^(.*)(\/(containers\/[^/]+)(\/\S+):(\d+))(.*)$} 238 {$1<a class="codelink" href='https://github.com/$3/blob/$git_commit$4#L$5'>$2</a>$6}; 239 } 240 241 # Try to identify the cirrus task 242 if ($line =~ /cirrus-task-(\d+)/) { 243 $cirrus_task = $1; 244 } 245 246 # BATS handling (used also for apiv2 tests, which emit TAP output) 247 if ($line =~ /^1\.\.(\d+)$/ || $line =~ m!/test-apiv2!) { 248 $looks_like_bats = 1; 249 $bats_count{expected_total} = $1; 250 } 251 if ($looks_like_bats) { 252 my $css; 253 254 # Readability: /long/path/to/podman -> podman (hover for full path) 255 # Also make it boldface, to make commands stand out 256 $line =~ s{^(#\s+(#|\$)\s+)(\S+/)(podman\S*)(\s.*)} 257 {$1<b><span title="$3$4">$4</span>$5</b>}; 258 259 if ($line =~ /^ok\s.*\s# skip/) { $css = 'skipped' } 260 elsif ($line =~ /^ok\s/) { $css = 'passed' } 261 elsif ($line =~ /^not\s+ok\s/) { $css = 'failed' } 262 elsif ($line =~ /^#\s#\|\s/) { $css = 'log-esm' } 263 elsif ($line =~ /^#\s/) { $css = 'log' } 264 265 if ($css) { 266 # Make it linkable, e.g. foo.html#t--00001 267 if ($line =~ /^(not\s+)?ok\s+(\d+)/) { 268 $line = sprintf("<a name='t--%05d'>%s</a>", $2, $line); 269 } 270 $line = "<span class='bats-$css'>$line</span>"; 271 272 $bats_count{$css}++; 273 } 274 275 print { $out_fh } "<span class=\"timestamp\">$timestamp</span>" 276 if $timestamp; 277 print { $out_fh } $line, "\n"; 278 next LINE; 279 } 280 281 # Timing section at the bottom of the page 282 if ($line =~ / timing results\s*$/) { 283 $in_timing = 1; 284 } 285 elsif ($in_timing) { 286 if ($line =~ /^(\S.*\S)\s+(\d+\.\d+)\s*$/) { 287 my ($name, $time) = ($1, $2); 288 my $id = make_id($1, 'timing'); 289 290 # Try to column-align the timing numbers. Some test names 291 # will be longer than our max - oh well. 292 my $spaces = 80 - length(unescapeHTML($name)); 293 $spaces = 1 if $spaces < 1; 294 $spaces++ if $time < 10; 295 my $spacing = ' ' x $spaces; 296 $line = qq{<span class="timing"><a href="#t--$id">$name</a>$spacing$time</span>}; 297 } 298 else { 299 $in_timing = 0; 300 } 301 } 302 303 # 304 # Ginkgo error reformatting 305 # 306 if ($line =~ /^.{1,4} (Failure|Panic)( in .*)? \[/) { 307 # Begins a block of multiple lines including a stack trace 308 print { $out_fh } "<div class='log-error'>\n"; 309 $in_failure = 1; 310 } 311 elsif ($line =~ /^-----------/) { 312 if ($in_failure) { 313 # Ends a stack trace block 314 $in_failure = 0; 315 print { $out_fh } "</div>\n"; 316 } 317 $after_divider = 1; 318 319 print { $out_fh } "</pre>\n<hr />\n<pre>\n"; 320 # Always show timestamp at start of each new test 321 $previous_timestamp = ''; 322 next LINE; 323 } 324 # (bindings test sometimes emits 'Running' with leading bullet char) 325 elsif ($line =~ /^•?Running:/) { 326 # Highlight the important (non-boilerplate) podman command. 327 $line =~ s/\s+--remote\s+/ /g; # --remote takes no args 328 # Strip out the global podman options, but show them on hover 329 $line =~ s{(\S+\/podman(-remote)?)((\s+--(root|runroot|runtime|tmpdir|storage-opt|conmon|cgroup-manager|cni-config-dir|storage-driver|events-backend|url) \S+)*)(.*)}{ 330 my ($full_path, $remote, $options, $args) = ($1, $2||'', $3, $6); 331 332 $options =~ s/^\s+//; 333 # Separate each '--foo bar' with newlines for readability 334 $options =~ s/ --/\n--/g; 335 qq{<span title="$full_path"><b>podman$remote</b></span> <span class=\"boring\" title=\"$options\">[options]</span><b>$args</b>}; 336 }e; 337 $current_output = ''; 338 } 339 # Grrr. 'output:' usually just tells us what we already know. 340 elsif ($line =~ /^output:/) { 341 $current_output =~ s!^\s+|\s+$!!g; # Trim leading/trailing blanks 342 $current_output =~ s/\s+/ /g; # Collapse multiple spaces 343 if ($line eq "output: $current_output" || $line eq 'output: ') { 344 next LINE; 345 } 346 } 347 elsif ($line =~ /^Error:/ || $line =~ / level=(warning|error) /) { 348 $line = "<span class='log-warn'>" . $line . "</span>"; 349 } 350 elsif ($line =~ /^panic:/) { 351 $line = "<span class='log-error'>" . $line . "</span>"; 352 } 353 else { 354 $current_output .= ' ' . $line; 355 } 356 357 358 # Two lines after each divider, there's a test name. Make it 359 # an anchor so we can link to it later. 360 if ($after_divider++ == 2) { 361 # Sigh. There is no actual marker. Assume that anything with 362 ## two leading spaces then alpha (not slashes) is a test name. 363 if ($line =~ /^ [a-zA-Z]/) { 364 my $id = make_id($line, 'anchor'); 365 366 $line = "<a name='t--$id'><h2>$line</h2></a>"; 367 } 368 } 369 370 # Failure name corresponds to a previously-seen block. 371 ## FIXME: sometimes there are three failures with the same name. 372 ## ...I have no idea why or how to link to the right ones. 373 # 1 2 2 3 3 14 4 374 if ($line =~ /^(\[(Fail|Panic!)\] .* \[(It|BeforeEach)\] )([A-Za-z].*)/) { 375 my ($lhs, $type, $ginkgo_fluff, $testname) = ($1, $2, $3, $4); 376 my $id = make_id($testname, 'link'); 377 378 $line = "<b>$lhs<a href='#t--$id'>$testname</a></b>"; 379 } 380 381 print { $out_fh } "<span class=\"timestamp\">$timestamp</span>" 382 if $timestamp; 383 print { $out_fh } $line, "\n"; 384 } 385 386 my $have_formatted_log; # Set on success 387 388 if ($out_fh) { 389 # Summary line for BATS tests 390 if (keys %bats_count) { 391 print { $out_fh } "<hr/><span class='bats-summary'>Summary:"; 392 my $total = 0; 393 my $comma = ''; 394 for my $class (qw(passed failed skipped)) { 395 if (my $n = $bats_count{$class}) { 396 printf { $out_fh } "%s <span class='bats-%s'>%d %s</span>", 397 $comma, $class, $n, ucfirst($class); 398 $total += $n; 399 $comma = ','; 400 } 401 } 402 403 printf { $out_fh } ". Total tests: $total"; 404 if (my $expected_total = $bats_count{expected_total}) { 405 if ($total != $expected_total) { 406 print { $out_fh } " <span class='bats-failed'>(WARNING: expected $expected_total)</span>"; 407 } 408 } 409 print { $out_fh } "</span>\n"; 410 } 411 412 print { $out_fh } "</pre> <!-- end processed output -->\n"; 413 414 # Did we find a cirrus task? Link back. 415 if ($cirrus_task) { 416 print { $out_fh } <<"END_HTML"; 417 <hr /> 418 <h3>Cirrus <a href="https://cirrus-ci.com/task/$cirrus_task">task $cirrus_task</a></h3> 419 END_HTML 420 } 421 422 # FIXME: need a safe way to get TZ 423 printf { $out_fh } <<"END_HTML", scalar(CORE::localtime); 424 <hr /> 425 <small>Processed %s by $ME v$VERSION</small> 426 </body> 427 </html> 428 END_HTML 429 430 if (close $out_fh) { 431 if (rename $out_tmp => $outfile) { 432 $have_formatted_log = 1; 433 } 434 else { 435 warn "$ME: Could not rename $out_tmp: $!\n"; 436 } 437 } 438 else { 439 warn "$ME: Error writing $out_tmp: $!\n"; 440 } 441 } 442 443 # If Cirrus magic envariables are available, write a link to results. 444 # FIXME: it'd be so nice to make this a clickable live link. 445 # 446 # STATIC_MAGIC_BLOB is the name of a google-storage bucket. It is 447 # unlikely to change often, but if it does you will suddenly start 448 # seeing errors when trying to view formatted logs: 449 # 450 # AccessDeniedAccess denied.Anonymous caller does not have storage.objects.get access to the Google Cloud Storage object. 451 # 452 # This happened in July 2020 when github.com/containers/libpod was 453 # renamed to podman. If something like that ever happens again, you 454 # will need to get the new magic blob value from: 455 # 456 # https://console.cloud.google.com/storage/browser?project=libpod-218412 457 # 458 # You will also probably need to set the bucket Public by clicking on 459 # the bucket name, then the Permissions tab. This is safe, since this 460 # project is fully open-source. 461 if ($have_formatted_log && $ENV{CIRRUS_TASK_ID}) { 462 my $URL_BASE = "https://storage.googleapis.com"; 463 my $STATIC_MAGIC_BLOB = "cirrus-ci-6707778565701632-fcae48"; 464 my $ARTIFACT_NAME = "html"; 465 466 my $URL = "${URL_BASE}/${STATIC_MAGIC_BLOB}/artifacts/$ENV{CIRRUS_REPO_FULL_NAME}/$ENV{CIRRUS_TASK_ID}/${ARTIFACT_NAME}/${outfile}"; 467 468 print "\n\nAnnotated results:\n $URL\n"; 469 } 470 } 471 472 473 ############# 474 # make_id # Given a test name, generate an anchor link name 475 ############# 476 sub make_id { 477 my $name = shift; # in: test title 478 my $type = shift; # in: differentiator (anchor, link) 479 480 state %counter; 481 482 $name =~ s/^\s+|\s+$//g; # strip leading/trailing whitespace 483 $name =~ s/[^a-zA-Z0-9_-]/-/g; # Convert non-alphanumeric to dash 484 485 # Keep a running tally of how many times we've seen this identifier 486 # for this given type! This lets us cross-match, in the bottom of 487 # the page, the first/second/third failure of a given test. 488 $name .= "--" . ++$counter{$type}{$name}; 489 490 $name; 491 } 492 493 494 ############################################################################### 495 # BEGIN job_synopsis and related helpers 496 497 ################## 498 # job_synopsis # Job details, links to github/cirrus 499 ################## 500 sub job_synopsis { 501 my $subtest_name = shift; # e.g. integration_test 502 503 my $s = <<"END_SYNOPSIS"; 504 <table class="synopsis"> 505 END_SYNOPSIS 506 507 # PR 1234 - title of the pr 508 my $pr_title = escapeHTML(_env_replace("{CIRRUS_CHANGE_TITLE}")); 509 $s .= _tr("Github PR", sprintf("%s - %s", 510 _a("{CIRRUS_PR}", "https://{CIRRUS_REPO_CLONE_HOST}/{CIRRUS_REPO_FULL_NAME}/pull/{CIRRUS_PR}"), 511 $pr_title)); 512 513 # PR author, if signed-off-by 514 if (my $msg = _env_replace("{CIRRUS_COMMIT_MESSAGE}")) { 515 while ($msg =~ /^Signed-off-by:\s+(\S.*\S)$/gmi) { 516 $s .= _tr("Author", escapeHTML($1)); 517 } 518 } 519 520 # eg "test fedora", "special_testing_rootless" 521 # WARNING: As of 2020-10-05, $CIRRUS_TASK_NAME reflects the same 522 # descriptive content as our $subtest_name argument (confirm via 523 # cross-checking runner.sh:logformatter() vs cirrus.yml:&std_name_fmt). 524 # If this ever becomes untrue, just add _tr("Subtest", $subtest_name). 525 my $test_name = _env_replace("{CIRRUS_TASK_NAME}"); 526 # (Special-case cleanup: Cirrus\ quotes\ spaces; remove for readability). 527 $test_name =~ s/\\\s+/ /g; 528 $s .= _tr("Test name", $test_name); 529 530 # Link to further Cirrus results, e.g. other runs. 531 # Build is mostly boring, it's usually TASK that we want to see. 532 $s .= _tr("Cirrus", sprintf("<small>Build %s</small> / <b>Task %s</b>", 533 _a("{CIRRUS_BUILD_ID}", "https://cirrus-ci.com/build/{CIRRUS_BUILD_ID}"), 534 _a("{CIRRUS_TASK_ID}", "https://cirrus-ci.com/task/{CIRRUS_TASK_ID}"))); 535 536 $s .= "</table>\n"; 537 return $s; 538 } 539 540 541 sub _tr { 542 my ($th, $td) = @_; 543 return "<tr><th>$th:</th><td>$td</td></tr>\n"; 544 } 545 546 sub _a { 547 my ($name, $href) = map { _env_replace($_) } @_; 548 549 if ($href =~ /UNDEFINED/) { 550 return "$name ($href)"; 551 } 552 return "<a href='$href'>$name</a>"; 553 } 554 555 sub _env_replace { 556 my $s_in = shift; 557 558 $s_in =~ s[\{(.*?)\}][$ENV{$1} || "[$1 UNDEFINED]"]ge; 559 560 return $s_in; 561 } 562 563 # END job_synopsis and related helpers 564 ############################################################################### 565 # BEGIN html-formatting helpers 566 567 sub escapeHTML { 568 my $s = shift; 569 570 state %chars; 571 %chars = ('&' => '&', '<' => '<', '>' => '>', '"' => '"', "'" => ''') 572 if keys(%chars) == 0; 573 my $class = join('', sort keys %chars); 574 $s =~ s/([$class])/$chars{$1}/ge; 575 576 return $s; 577 } 578 579 sub unescapeHTML { 580 my $s = shift; 581 582 # We don't actually care about the character, only its length 583 $s =~ s/\&\#?[a-z0-9]+;/./g; 584 585 return $s; 586 } 587 588 # END html-formatting helpers 589 ############################################################################### 590 591 1;