From 137c8ef4d511e77fb493f65533fee39fd7c3a26b Mon Sep 17 00:00:00 2001
From: Ed Santiago <santiago@redhat.com>
Date: Tue, 6 Jun 2023 06:40:07 -0600
Subject: [PATCH] logformatter: better recognition of ginkgo test names
Ginkgo test names can have more than two levels: there can be
a nested series of Describes() before the final It(). (e.g.,
quadlet_test.go). Handle that.
Before: we just assumed that the third-or-maybe-fourth line
after a "-----" divider was the test name.
Now: examine every line after the "-----" divider, until the
first empty line. Lines with /path/to/source/file are ignored,
lines with text strings are assembled together to make anchors.
This is still imperfect but it's much better than before.
SPECIAL NOTE: in order to allow linking to timing results
in the AfterSuite, I've changed the test name from Leaf to Full.
This will now be a much longer string, and hence much less
readable, but I'm inclined to think it's more correct. Please
review carefully and lmk if I should revert.
Finally, as an unrelated add-on, add links (at top) to original
log, journal, and (if applicable) podman-remote server logs.
Signed-off-by: Ed Santiago <santiago@redhat.com>
---
contrib/cirrus/logformatter | 74 ++++++++++++++++++++++++++++-------
contrib/cirrus/logformatter.t | 10 +++--
test/e2e/common_test.go | 2 +-
3 files changed, 67 insertions(+), 19 deletions(-)
diff --git a/contrib/cirrus/logformatter b/contrib/cirrus/logformatter
index 5c888038bd..e2eebd4eb6 100755
--- a/contrib/cirrus/logformatter
+++ b/contrib/cirrus/logformatter
@@ -234,6 +234,7 @@ END_HTML
my $cirrus_task; # Cirrus task number, used for linking
my $git_commit; # git SHA, used for linking to source files
my $subtest_status; # pass, fail, skip, flake - for each subtest
+ my $subtest_name; # assembled from two or more Describe()/It()s
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 = 999; # Count of lines after seeing '-----'
@@ -475,6 +476,10 @@ END_HTML
lc($block);
$line = "$indent→ Enter [<b>$block</b>]$line";
$print_line->();
+
+ # machine tests, run without -p, don't have a blank line
+ # separating headers from logs; but this works just fine.
+ $after_divider = 999;
}
else {
# Can be a div within a div
@@ -564,6 +569,7 @@ END_HTML
}
$after_divider = 1;
$subtest_status = 'passed'; # until proven otherwise
+ $subtest_name = '';
print { $out_fh } "</pre>\n<hr />\n<pre>\n";
# Always show timestamp at start of each new test
@@ -622,16 +628,44 @@ END_HTML
# FIXME: gray out entire block if it's skipped?
}
- # Three lines after each divider (four, if ginkgo is run with "-p",
- # see above), there's a test name. Make it an anchor so we can link
- # to it later.
- if ($after_divider == 3) {
- # Sigh. There is no actual marker. Assume that anything with
- ## two leading spaces then alpha or hyphen (not slashes) is
- ## a test name.
- if ($line =~ /^ (\[It\]\s*)?([a-zA-Z-].*\S)/) {
- my $id = make_id($2, 'anchor');
-
+ # Test name recognition, linking, and highlighting.
+ # The lines after each divider, until the first empty line, are
+ # one or more test name specifiers, a nested level of Description()
+ # and It() names:
+ # -----------
+ # * blah [N seconds] <<<---- only when run with -p
+ # Podman foo
+ # /var/tmp/go/src/path/to/this/file.go:lineno
+ # podman bar
+ # /var/tmp/go/src/path/to/this/file.go:lineno
+ #
+ # There may even be three nested levels (e.g., quadlet). We
+ # look for non-path lines and assemble them -- "Podman foo",
+ # " Podman foo podman bar" -- giving each an HTML anchor
+ # to which we can link from the summary section at bottom.
+ if ($after_divider <= 10) { # Assume no more than ~5 levels
+ if ($line =~ /^\s*$/) {
+ # Stop looking when we get to the blank line
+ $after_divider = 999;
+ }
+ elsif ($line =~ /span.*class=.boring./) {
+ # Sigh. Bindings tests run without -p, and have no blank line
+ # separator. Use the first command to signal real logs.
+ # FIXME: can we solve this with ReportBeforeEach()?
+ # https://onsi.github.io/ginkgo/#generating-reports-programmatically
+ $after_divider = 999;
+ }
+ elsif ($line =~ m!^\s*/\S+!) {
+ # Source code path: skip
+ }
+ elsif ($line =~ /<b/) {
+ # Already-formatted line (like the "N seconds" one): skip
+ }
+ elsif ($line =~ /^\s*(\[It\]\s*)?(.*)/) {
+ # Test description or name! Remove the "It", and make an anchor
+ $subtest_name .= " " if $subtest_name;
+ $subtest_name .= $2;
+ my $id = make_id($subtest_name, 'anchor');
$line = "<a name='t--$id'><h2 class=\"log-$subtest_status\">$line</h2></a>";
}
}
@@ -643,10 +677,10 @@ END_HTML
$line =~ s!^(\s*)(\[It\]\s+.*)!$1<span class="testname">$2</span>!;
# Failure name corresponds to a previously-seen block.
- # 1 2 2 3 3 14 4
- if ($line =~ /^(\s*\[(FAIL|PANIC!)\] .* \[(It|BeforeEach|AfterEach)\] )([A-Za-z-].*)/) {
- my ($lhs, $type, $ginkgo_fluff, $testname) = ($1, $2, $3, $4);
- my $id = make_id($testname, 'link');
+ # 1 2 2 3 3 4 4 15 5
+ if ($line =~ /^(\s*\[(FAIL|PANIC!)\] (.*) \[(It|BeforeEach|AfterEach)\] )([A-Za-z-].*)/) {
+ my ($lhs, $type, $desc, $ginkgo_fluff, $testname) = ($1, $2, $3, $4, $5);
+ my $id = make_id("$desc $testname", 'link');
$line = "<span class=\"log-error\">$lhs<a href='#t--$id'>$testname</a></span>";
}
@@ -812,6 +846,18 @@ END_SYNOPSIS
_a("{CIRRUS_BUILD_ID}", "https://cirrus-ci.com/build/{CIRRUS_BUILD_ID}"),
_a("{CIRRUS_TASK_ID}", "https://cirrus-ci.com/task/{CIRRUS_TASK_ID}")));
+ # Logs: link to original (unformatted) log; journal; and, if remote, server
+ my @logs = (
+ _a("main", "https://api.cirrus-ci.com/v1/task/{CIRRUS_TASK_ID}/logs/main.log"),
+ _a("journal", "https://api.cirrus-ci.com/v1/task/{CIRRUS_TASK_ID}/logs/journal.log"),
+ );
+
+ # System tests are single-threaded, and have a server log available
+ if ($test_name =~ /sys\s+remote\s/) {
+ push @logs, _a("remote server", "https://api.cirrus-ci.com/v1/artifact/task/{CIRRUS_TASK_ID}/server_log/podman-server.log");
+ }
+ $s .= _tr("Logs", join(" / ", @logs));
+
# BASE_SHA can tell us if our parent includes--or doesn't--a purported
# fix for a flake. Note that "commits", plural, links to a git history
# listing; if we used "commit", singular, that would be less useful.
diff --git a/contrib/cirrus/logformatter.t b/contrib/cirrus/logformatter.t
index 2a74709123..4513e11d7c 100755
--- a/contrib/cirrus/logformatter.t
+++ b/contrib/cirrus/logformatter.t
@@ -34,6 +34,8 @@ while (my $line = <DATA>) {
$context = 'expect';
}
elsif (@tests && $line) {
+ # Handles trailing spaces in log, because we can't have actual ones.
+ $line =~ s/\&TRAILINGSPACE;/ /g;
push @{ $tests[-1]{$context} }, $line;
}
}
@@ -189,7 +191,7 @@ ok 4 blah
[+0271s] /var/tmp/go/src/github.com/containers/podman/test/e2e/restart_test.go:14
[+0271s] podman restart non-stop container with short timeout
[+0271s] /var/tmp/go/src/github.com/containers/podman/test/e2e/restart_test.go:148
-[+0271s]
+[+0271s]&TRAILINGSPACE;
[+0271s] Timeline >>
[+0271s] > Enter [BeforeEach] Podman restart - /var/tmp/go/src/github.com/containers/podman/test/e2e/restart_test.go:21 @ 04/17/23 10:00:28.653
[+0271s] < Exit [BeforeEach] Podman restart - /var/tmp/go/src/github.com/containers/podman/test/e2e/restart_test.go:21 @ 04/17/23 10:00:28.653 (0s)
@@ -217,11 +219,11 @@ ok 4 blah
<hr />
<pre>
<span class="timestamp">[+0271s] </span>⢠<b>[3.327 seconds]</b>
-<span class="timestamp"> </span>Podman restart
+<span class="timestamp"> </span><a name='t--Podman-restart--1'><h2 class="log-passed">Podman restart</h2></a>
<span class="timestamp"> </span>/var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/074143b0fac7af72cd92048d27931a92fe745084/test/e2e/restart_test.go#L14'>/containers/podman/test/e2e/restart_test.go:14</a>
-<span class="timestamp"> </span><a name='t--podman-restart-non-stop-container-with-short-timeout--1'><h2 class="log-passed"> podman restart non-stop container with short timeout</h2></a>
+<span class="timestamp"> </span><a name='t--Podman-restart-podman-restart-non-stop-container-with-short-timeout--1'><h2 class="log-passed"> podman restart non-stop container with short timeout</h2></a>
<span class="timestamp"> </span> /var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/074143b0fac7af72cd92048d27931a92fe745084/test/e2e/restart_test.go#L148'>/containers/podman/test/e2e/restart_test.go:148</a>
-[+0271s]
+<span class="timestamp"> </span>
<span class="timestamp"> </span> Timeline >>
<div class="ginkgo-timeline ginkgo-beforeeach"><span class="timestamp"> </span> → Enter [<b>BeforeEach</b>] Podman restart - /var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/074143b0fac7af72cd92048d27931a92fe745084/test/e2e/restart_test.go#L21'>/containers/podman/test/e2e/restart_test.go:21</a> @ 04/17/23 10:00:28.653
<span class="timestamp"> </span> ← Exit [BeforeEach] Podman restart - /var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/074143b0fac7af72cd92048d27931a92fe745084/test/e2e/restart_test.go#L21'>/containers/podman/test/e2e/restart_test.go:21</a> @ 04/17/23 10:00:28.653 (0s)
diff --git a/test/e2e/common_test.go b/test/e2e/common_test.go
index 78334d4814..2b71e79c4e 100644
--- a/test/e2e/common_test.go
+++ b/test/e2e/common_test.go
@@ -462,7 +462,7 @@ func (p *PodmanTestIntegration) InspectContainer(name string) []define.InspectCo
}
func processTestResult(r SpecReport) {
- tr := testResult{length: r.RunTime.Seconds(), name: r.LeafNodeText}
+ tr := testResult{length: r.RunTime.Seconds(), name: r.FullText()}
testResultsMutex.Lock()
testResults = append(testResults, tr)
testResultsMutex.Unlock()