From 7a83d16f95d261de7b479f82d9825717d67d7171 Mon Sep 17 00:00:00 2001 From: Ed Santiago Date: Tue, 15 Feb 2022 15:23:44 -0700 Subject: [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 --- contrib/cirrus/logformatter | 68 ++++++++++++++++--- contrib/cirrus/logformatter.t | 148 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 208 insertions(+), 8 deletions(-) (limited to 'contrib/cirrus') 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 } "

Synopsis

\n
\n", job_synopsis($test_name), "
\n"; - # FOR DEBUGGING: dump environment, but in HTML comments to not clutter - print { $out_fh } "\n"; - for my $e (sort keys %ENV) { - my $val = escapeHTML($ENV{$e}); - $val =~ s/--/--/g; # double dash not valid in comments - printf { $out_fh } "\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 } "
 \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$2$6};
+
+            # Same, for python errors
+            #           1  12  3                 34         4             5   526
+            $line =~ s{^(.*)(\/(containers\/[^/]+)(\/\S+\.py).*,\s+line\s+(\d+))(,\s+in.*)$}
+                      {$1$2$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 } "\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 } "$timestamp"
+                    if $timestamp;
+                print { $out_fh } "", $line, "\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 } "
\n" unless $in_failure;
+                $in_failure = 1;
+            }
+
+            if ($css) {
+                $line = "$line";
+
+                $bats_count{$css}++;
+            }
+            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*$/) {
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]
          [Fail] Podman play kube with build [It] --build should override image in store
          /var/tmp/go/src/github.com/containers/podman/test/e2e/play_build_test.go:259
+
+
+== 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 
+[+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 
+[+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 
+[+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
+>>>
+[+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
+           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)>
+           waiters_to_notify = _deque(_islice(all_waiters, n))
+         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)>
+           for ateof in reversed(self._eofstack):
+         ResourceWarning: Enable tracemalloc to get the object allocation traceback
+         /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)>
+           for ateof in reversed(self._eofstack):
+         ResourceWarning: Enable tracemalloc to get the object allocation traceback
+         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
+         test_get_image_exists_not (compat.test_images.TestImages)
+[+0274s] Negative test for get image ... ok
+         test_image_history (compat.test_images.TestImages)
+         Image history ... ok
+         test_list_images (compat.test_images.TestImages)
+[+0276s] List images ... ok
+         test_load_corrupt_image (compat.test_images.TestImages)
+[+0277s] Import|Load Image failure ... ok
+         test_load_image (compat.test_images.TestImages)
+[+0279s] Import|Load Image ... ok
+         test_remove_image (compat.test_images.TestImages)
+[+0280s] Remove image ... ok
+         test_retag_valid_image (compat.test_images.TestImages)
+         Validates if name updates when the image is retagged ... ok
+         test_save_image (compat.test_images.TestImages)
+[+0282s] Export Image ... ok
+         test_search_bogus_image (compat.test_images.TestImages)
+[+0290s] Search for bogus image should throw exception ... ok
+         test_search_image (compat.test_images.TestImages)
+[+0291s] Search for image ... FAIL
+         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
+

+         ======================================================================
+         FAIL: test_search_image (compat.test_images.TestImages)
+         Search for image
+         ----------------------------------------------------------------------
+         Traceback (most recent call last):
+           File "/var/tmp/go/src/github.com/containers/podman/test/python/docker/compat/test_images.py", line 90, in test_search_image
+             self.assertIn("alpine", r["Name"])
+         AssertionError: 'alpine' not found in 'docker.io/docker/desktop-kubernetes'
+         ----------------------------------------------------------------------
+

+         Ran 33 tests in 63.138s
+         FAILED (failures=1, skipped=1)
+         make: *** [Makefile:616: localapiv2] Error 1
+
Summary: 28 Passed, 1 Failed, 1 Skipped. Total tests: 30 (WARNING: expected 33)
-- 
cgit v1.2.3-54-g00ecf