diff options
author | Ed Santiago <santiago@redhat.com> | 2022-02-15 15:23:44 -0700 |
---|---|---|
committer | Ed Santiago <santiago@redhat.com> | 2022-02-16 06:31:05 -0700 |
commit | 7a83d16f95d261de7b479f82d9825717d67d7171 (patch) | |
tree | 73b8c0358c8be91695bd6fb771c99eda0a550051 /contrib/cirrus | |
parent | 60b0acb7dc6b5bbe05a9556d80e33217b10dde9b (diff) | |
download | podman-7a83d16f95d261de7b479f82d9825717d67d7171.tar.gz podman-7a83d16f95d261de7b479f82d9825717d67d7171.tar.bz2 podman-7a83d16f95d261de7b479f82d9825717d67d7171.zip |
[CI:DOCS] logformatter: handle python logs
We've got some python tests running in CI, and they're really hard
to troubleshoot. This PR:
1) colorizes python unittest lines (ok / skipped / fail), and
2) links to source files
The color is nice for skimming, but it's the linking that might
make it much easier to diagnose future failures.
(Context: failure today in test/python/docker/compat/test_images.py)
Signed-off-by: Ed Santiago <santiago@redhat.com>
Diffstat (limited to 'contrib/cirrus')
-rwxr-xr-x | contrib/cirrus/logformatter | 68 | ||||
-rwxr-xr-x | contrib/cirrus/logformatter.t | 148 |
2 files changed, 208 insertions, 8 deletions
diff --git a/contrib/cirrus/logformatter b/contrib/cirrus/logformatter index 49ca91399..43173eaa6 100755 --- a/contrib/cirrus/logformatter +++ b/contrib/cirrus/logformatter @@ -187,14 +187,6 @@ END_HTML print { $out_fh } "<h2>Synopsis</h2>\n<hr/>\n", job_synopsis($test_name), "<hr/>\n"; - # FOR DEBUGGING: dump environment, but in HTML comments to not clutter - print { $out_fh } "<!-- Environment: -->\n"; - for my $e (sort keys %ENV) { - my $val = escapeHTML($ENV{$e}); - $val =~ s/--/--/g; # double dash not valid in comments - printf { $out_fh } "<!-- %-20s %s -->\n", $e, $val; - } - # State variables my $previous_timestamp = ''; # timestamp of previous line my $cirrus_task; # Cirrus task number, used for linking @@ -204,8 +196,12 @@ END_HTML 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 + my $looks_like_python; # " " " : for colorizing python tests my %bats_count; # For summary line: count of pass/fail/skip + # When running in cirrus, we have the commit SHA + $git_commit = $ENV{CIRRUS_CHANGE_IN_REPO}; + print { $out_fh } "<pre> <!-- begin processed output -->\n"; # Assume rootful prompt, check for rootless (here and in log itself, below) @@ -245,6 +241,11 @@ END_HTML # 1 12 3 34 4 5 526 6 $line =~ s{^(.*)(\/(containers\/[^/]+)(\/\S+):(\d+))(.*)$} {$1<a class="codelink" href='https://github.com/$3/blob/$git_commit$4#L$5'>$2</a>$6}; + + # Same, for python errors + # 1 12 3 34 4 5 526 + $line =~ s{^(.*)(\/(containers\/[^/]+)(\/\S+\.py).*,\s+line\s+(\d+))(,\s+in.*)$} + {$1<a class="codelink" href='https://github.com/$3/blob/$git_commit$4#L$5'>$2</a>$6}; } # Try to identify the cirrus task @@ -256,13 +257,42 @@ END_HTML if ($line =~ /^1\.\.(\d+)$/) { $looks_like_bats = 1; $bats_count{expected_total} = $1; + undef $looks_like_python; } # Since the number of tests can't always be predicted, recognize # some leading text strings that indicate BATS output to come. elsif ($line =~ /^TAP\s+version\s/ || $line =~ m!/test-apiv2!) { $looks_like_bats = 1; $bats_count{expected_total} = -1; # Expect to be overridden at end! + undef $looks_like_python; + } + + # 'python -m unittest' means we're starting some pythony stuff + elsif ($line =~ m!/python.*\sunittest\s!) { + $looks_like_python = 1; + undef $looks_like_bats; } + elsif ($looks_like_python && $line =~ m!Ran\s+(\d+)\s+tests\s+in\s!) { + # End of python tests. However, we're still likely to see a + # summary line saying 'OK' or 'FAILED'. Deal with that by + # resetting $looks_like_python to 0, which the next elsif catches + $bats_count{expected_total} += $1; + $looks_like_python = 0; + print { $out_fh } "</div>\n" if $in_failure; + undef $in_failure; + } + elsif (defined($looks_like_python) && !$looks_like_python) { + # The final python summary line. Show it in its appropriate color. + if ($line =~ /^\s*(OK|FAILED)\s+\(/) { + undef $looks_like_python; + my $css = ($1 eq 'OK' ? 'passed' : 'failed'); + print { $out_fh } "<span class=\"timestamp\">$timestamp</span>" + if $timestamp; + print { $out_fh } "<span class='bats-$css'>", $line, "</span>\n"; + next LINE; + } + } + if ($looks_like_bats) { my $css; @@ -292,6 +322,28 @@ END_HTML print { $out_fh } $line, "\n"; next LINE; } + elsif ($looks_like_python) { + my $css; + + if ($line =~ /\s\.\.\.\sskipped/) { $css = 'skipped' } + elsif ($line =~ /\s\.\.\.\sok\s*$/) { $css = 'passed' } + elsif ($line =~ /\s\.\.\.\sFAIL/) { $css = 'failed' } + elsif ($line =~ /^\s*={40}/) { + # Begins a block of multiple lines including a stack trace + print { $out_fh } "<div class='log-error'>\n" unless $in_failure; + $in_failure = 1; + } + + if ($css) { + $line = "<span class='bats-$css'>$line</span>"; + + $bats_count{$css}++; + } + print { $out_fh } "<span class=\"timestamp\">$timestamp</span>" + if $timestamp; + print { $out_fh } $line, "\n"; + next LINE; + } # Timing section at the bottom of the page if ($line =~ / timing results\s*$/) { diff --git a/contrib/cirrus/logformatter.t b/contrib/cirrus/logformatter.t index a377faa34..df8154cb9 100755 --- a/contrib/cirrus/logformatter.t +++ b/contrib/cirrus/logformatter.t @@ -12,6 +12,9 @@ use FindBin; use File::Temp qw(tempdir); use Test::More; +# To test links to source files +$ENV{CIRRUS_CHANGE_IN_REPO} = 'ceci-nest-pas-une-sha'; + # # Read the test cases (see __END__ section below) # @@ -264,3 +267,148 @@ $SCRIPT_BASE/integration_test.sh |& ${TIMESTAMP} [+1512s] <span class="timestamp"> </span><b>[Fail] Podman play kube with build [It] <a href='#t----build-should-override-image-in-store--1'>--build should override image in store</a></b> <span class="timestamp"> </span>/var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/40f5d8b1becd381c4e8283ed3940d09193e4fe06/test/e2e/play_build_test.go#L259'>/containers/podman/test/e2e/play_build_test.go:259</a> + + +== simple python + +<<< +[+0234s] env CONTAINERS_CONF=/var/tmp/go/src/github.com/containers/podman/test/apiv2/containers.conf PODMAN=./bin/podman /usr/bin/python3 -m unittest discover -v ./test/python/docker +[+0238s] test_copy_to_container (compat.test_containers.TestContainers) ... /usr/lib/python3.10/site-packages/docker/utils/utils.py:269: DeprecationWarning: urllib.parse.splitnport() is deprecated as of 3.8, use urllib.parse.urlparse() instead +[+0238s] host, port = splitnport(parsed_url.netloc) +[+0241s] ok +[+0243s] test_create_container (compat.test_containers.TestContainers) ... ok +[+0244s] test_create_network (compat.test_containers.TestContainers) ... ok +[+0245s] test_filters (compat.test_containers.TestContainers) ... skipped 'TODO Endpoint does not yet support filters' +[+0246s] test_kill_container (compat.test_containers.TestContainers) ... /usr/lib64/python3.10/threading.py:372: ResourceWarning: unclosed <socket.socket fd=4, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55054), raddr=('127.0.0.1', 8080)> +[+0246s] waiters_to_notify = _deque(_islice(all_waiters, n)) +[+0246s] ResourceWarning: Enable tracemalloc to get the object allocation traceback +[+0247s] ok +[+0248s] test_list_container (compat.test_containers.TestContainers) ... ok +[+0252s] test_mount_preexisting_dir (compat.test_containers.TestContainers) ... ok +[+0253s] test_mount_rw_by_default (compat.test_containers.TestContainers) ... ok +[+0257s] test_non_existant_workdir (compat.test_containers.TestContainers) ... ok +[+0258s] test_pause_container (compat.test_containers.TestContainers) ... ok +[+0260s] test_pause_stopped_container (compat.test_containers.TestContainers) ... ok +[+0261s] test_remove_container (compat.test_containers.TestContainers) ... ok +[+0262s] test_remove_container_without_force (compat.test_containers.TestContainers) ... /usr/lib64/python3.10/email/feedparser.py:89: ResourceWarning: unclosed <socket.socket fd=4, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55068), raddr=('127.0.0.1', 8080)> +[+0262s] for ateof in reversed(self._eofstack): +[+0262s] ResourceWarning: Enable tracemalloc to get the object allocation traceback +[+0262s] /usr/lib64/python3.10/email/feedparser.py:89: ResourceWarning: unclosed <socket.socket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55074), raddr=('127.0.0.1', 8080)> +[+0262s] for ateof in reversed(self._eofstack): +[+0262s] ResourceWarning: Enable tracemalloc to get the object allocation traceback +[+0262s] ok +[+0264s] test_restart_container (compat.test_containers.TestContainers) ... ok +[+0265s] test_start_container (compat.test_containers.TestContainers) ... ok +[+0267s] test_start_container_with_random_port_bind (compat.test_containers.TestContainers) ... ok +[+0268s] test_stop_container (compat.test_containers.TestContainers) ... ok +[+0269s] test_unpause_container (compat.test_containers.TestContainers) ... ok +[+0273s] test_build_image (compat.test_images.TestImages) ... ok +[+0273s] test_get_image_exists_not (compat.test_images.TestImages) +[+0274s] Negative test for get image ... ok +[+0274s] test_image_history (compat.test_images.TestImages) +[+0274s] Image history ... ok +[+0274s] test_list_images (compat.test_images.TestImages) +[+0276s] List images ... ok +[+0276s] test_load_corrupt_image (compat.test_images.TestImages) +[+0277s] Import|Load Image failure ... ok +[+0277s] test_load_image (compat.test_images.TestImages) +[+0279s] Import|Load Image ... ok +[+0279s] test_remove_image (compat.test_images.TestImages) +[+0280s] Remove image ... ok +[+0280s] test_retag_valid_image (compat.test_images.TestImages) +[+0280s] Validates if name updates when the image is retagged ... ok +[+0280s] test_save_image (compat.test_images.TestImages) +[+0282s] Export Image ... ok +[+0282s] test_search_bogus_image (compat.test_images.TestImages) +[+0290s] Search for bogus image should throw exception ... ok +[+0290s] test_search_image (compat.test_images.TestImages) +[+0291s] Search for image ... FAIL +[+0291s] test_tag_valid_image (compat.test_images.TestImages) +[+0292s] Validates if the image is tagged successfully ... ok +[+0296s] test_Info (compat.test_system.TestSystem) ... ok +[+0298s] test_info_container_details (compat.test_system.TestSystem) ... ok +[+0299s] test_version (compat.test_system.TestSystem) ... ok +[+0299s] ====================================================================== +[+0299s] FAIL: test_search_image (compat.test_images.TestImages) +[+0299s] Search for image +[+0299s] ---------------------------------------------------------------------- +[+0299s] Traceback (most recent call last): +[+0299s] File "/var/tmp/go/src/github.com/containers/podman/test/python/docker/compat/test_images.py", line 90, in test_search_image +[+0299s] self.assertIn("alpine", r["Name"]) +[+0299s] AssertionError: 'alpine' not found in 'docker.io/docker/desktop-kubernetes' +[+0299s] ---------------------------------------------------------------------- +[+0299s] Ran 33 tests in 63.138s +[+0299s] FAILED (failures=1, skipped=1) +[+0299s] make: *** [Makefile:616: localapiv2] Error 1 +>>> +<span class="timestamp">[+0234s] </span>env CONTAINERS_CONF=/var/tmp/go/src/github.com/containers/podman/test/apiv2/containers.conf PODMAN=./bin/podman /usr/bin/python3 -m unittest discover -v ./test/python/docker +<span class="timestamp">[+0238s] </span>test_copy_to_container (compat.test_containers.TestContainers) ... /usr/lib/python3.10/site-packages/docker/utils/utils.py:269: DeprecationWarning: urllib.parse.splitnport() is deprecated as of 3.8, use urllib.parse.urlparse() instead +<span class="timestamp"> </span> host, port = splitnport(parsed_url.netloc) +<span class="timestamp">[+0241s] </span>ok +<span class="timestamp">[+0243s] </span><span class='bats-passed'>test_create_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0244s] </span><span class='bats-passed'>test_create_network (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0245s] </span><span class='bats-skipped'>test_filters (compat.test_containers.TestContainers) ... skipped 'TODO Endpoint does not yet support filters'</span> +<span class="timestamp">[+0246s] </span>test_kill_container (compat.test_containers.TestContainers) ... /usr/lib64/python3.10/threading.py:372: ResourceWarning: unclosed <socket.socket fd=4, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55054), raddr=('127.0.0.1', 8080)> +<span class="timestamp"> </span> waiters_to_notify = _deque(_islice(all_waiters, n)) +<span class="timestamp"> </span>ResourceWarning: Enable tracemalloc to get the object allocation traceback +<span class="timestamp">[+0247s] </span>ok +<span class="timestamp">[+0248s] </span><span class='bats-passed'>test_list_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0252s] </span><span class='bats-passed'>test_mount_preexisting_dir (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0253s] </span><span class='bats-passed'>test_mount_rw_by_default (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0257s] </span><span class='bats-passed'>test_non_existant_workdir (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0258s] </span><span class='bats-passed'>test_pause_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0260s] </span><span class='bats-passed'>test_pause_stopped_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0261s] </span><span class='bats-passed'>test_remove_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0262s] </span>test_remove_container_without_force (compat.test_containers.TestContainers) ... /usr/lib64/python3.10/email/feedparser.py:89: ResourceWarning: unclosed <socket.socket fd=4, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55068), raddr=('127.0.0.1', 8080)> +<span class="timestamp"> </span> for ateof in reversed(self._eofstack): +<span class="timestamp"> </span>ResourceWarning: Enable tracemalloc to get the object allocation traceback +<span class="timestamp"> </span>/usr/lib64/python3.10/email/feedparser.py:89: ResourceWarning: unclosed <socket.socket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 55074), raddr=('127.0.0.1', 8080)> +<span class="timestamp"> </span> for ateof in reversed(self._eofstack): +<span class="timestamp"> </span>ResourceWarning: Enable tracemalloc to get the object allocation traceback +<span class="timestamp"> </span>ok +<span class="timestamp">[+0264s] </span><span class='bats-passed'>test_restart_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0265s] </span><span class='bats-passed'>test_start_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0267s] </span><span class='bats-passed'>test_start_container_with_random_port_bind (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0268s] </span><span class='bats-passed'>test_stop_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0269s] </span><span class='bats-passed'>test_unpause_container (compat.test_containers.TestContainers) ... ok</span> +<span class="timestamp">[+0273s] </span><span class='bats-passed'>test_build_image (compat.test_images.TestImages) ... ok</span> +<span class="timestamp"> </span>test_get_image_exists_not (compat.test_images.TestImages) +<span class="timestamp">[+0274s] </span><span class='bats-passed'>Negative test for get image ... ok</span> +<span class="timestamp"> </span>test_image_history (compat.test_images.TestImages) +<span class="timestamp"> </span><span class='bats-passed'>Image history ... ok</span> +<span class="timestamp"> </span>test_list_images (compat.test_images.TestImages) +<span class="timestamp">[+0276s] </span><span class='bats-passed'>List images ... ok</span> +<span class="timestamp"> </span>test_load_corrupt_image (compat.test_images.TestImages) +<span class="timestamp">[+0277s] </span><span class='bats-passed'>Import|Load Image failure ... ok</span> +<span class="timestamp"> </span>test_load_image (compat.test_images.TestImages) +<span class="timestamp">[+0279s] </span><span class='bats-passed'>Import|Load Image ... ok</span> +<span class="timestamp"> </span>test_remove_image (compat.test_images.TestImages) +<span class="timestamp">[+0280s] </span><span class='bats-passed'>Remove image ... ok</span> +<span class="timestamp"> </span>test_retag_valid_image (compat.test_images.TestImages) +<span class="timestamp"> </span><span class='bats-passed'>Validates if name updates when the image is retagged ... ok</span> +<span class="timestamp"> </span>test_save_image (compat.test_images.TestImages) +<span class="timestamp">[+0282s] </span><span class='bats-passed'>Export Image ... ok</span> +<span class="timestamp"> </span>test_search_bogus_image (compat.test_images.TestImages) +<span class="timestamp">[+0290s] </span><span class='bats-passed'>Search for bogus image should throw exception ... ok</span> +<span class="timestamp"> </span>test_search_image (compat.test_images.TestImages) +<span class="timestamp">[+0291s] </span><span class='bats-failed'>Search for image ... FAIL</span> +<span class="timestamp"> </span>test_tag_valid_image (compat.test_images.TestImages) +<span class="timestamp">[+0292s] </span><span class='bats-passed'>Validates if the image is tagged successfully ... ok</span> +<span class="timestamp">[+0296s] </span><span class='bats-passed'>test_Info (compat.test_system.TestSystem) ... ok</span> +<span class="timestamp">[+0298s] </span><span class='bats-passed'>test_info_container_details (compat.test_system.TestSystem) ... ok</span> +<span class="timestamp">[+0299s] </span><span class='bats-passed'>test_version (compat.test_system.TestSystem) ... ok</span> +<div class='log-error'> +<span class="timestamp"> </span>====================================================================== +<span class="timestamp"> </span>FAIL: test_search_image (compat.test_images.TestImages) +<span class="timestamp"> </span>Search for image +<span class="timestamp"> </span>---------------------------------------------------------------------- +<span class="timestamp"> </span>Traceback (most recent call last): +<span class="timestamp"> </span> File "/var/tmp/go/src/github.com<a class="codelink" href='https://github.com/containers/podman/blob/ceci-nest-pas-une-sha/test/python/docker/compat/test_images.py#L90'>/containers/podman/test/python/docker/compat/test_images.py", line 90</a>, in test_search_image +<span class="timestamp"> </span> self.assertIn("alpine", r["Name"]) +<span class="timestamp"> </span>AssertionError: 'alpine' not found in 'docker.io/docker/desktop-kubernetes' +<span class="timestamp"> </span>---------------------------------------------------------------------- +</div> +<span class="timestamp"> </span>Ran 33 tests in 63.138s +<span class="timestamp"> </span><span class='bats-failed'>FAILED (failures=1, skipped=1)</span> +<span class="timestamp"> </span>make: *** [Makefile:616: localapiv2] Error 1 +<hr/><span class='bats-summary'>Summary: <span class='bats-passed'>28 Passed</span>, <span class='bats-failed'>1 Failed</span>, <span class='bats-skipped'>1 Skipped</span>. Total tests: 30 <span class='bats-failed'>(WARNING: expected 33)</span></span> |