mirror of
https://github.com/podman-container-tools/podman.git
synced 2026-09-20 14:47:48 +00:00
ec30a4f7b7
The step summary posted when a CI job fails is useless for the bindings suite: it carries a bare failure count and never the failure itself. Two reasons stack up. github_log_summary.py picks between the ginkgo and bats parsers by looking for "int-" in the file name, but int is not the only ginkgo suite - bindings runs ginkgo as well, so its log is handed to the bats parser, which finds nothing beyond the count in ginkgo's summary line. logformatter decides the layout from the log contents, so do the same here. That alone still leaves the summary empty. Only ginkgo run under -p reports a failure on the line logformatter reads the test status from, and `make testbindings` does not pass -p, so every test in a bindings log heads 'log-passed' and the stack trace div is the sole mark of a failure. Key on that div as well. Not on the class by itself: logformatter gives it to error-level logrus lines too, which passing tests emit, but those are spans. Three more things the script got wrong along the way, all of them kept out of sight by the "|| true" on the workflow step. The workflow passes it a glob but only argv[1] was ever read, so any further log was dropped without a word. A job that produces no html log at all leaves that glob unexpanded, which ended in a traceback. And logformatter reads its input through ':utf8', which validates nothing, so a test that wrote raw bytes leaves behind a log that the summary could not even decode. Signed-off-by: rjgoyln <pt40419@gmail.com>
249 lines
11 KiB
Python
Executable file
249 lines
11 KiB
Python
Executable file
#!/usr/bin/env python3
|
|
|
|
"""
|
|
Verify github_log_summary.py picks the right parser and reports every log
|
|
"""
|
|
|
|
import os
|
|
import subprocess
|
|
import sys
|
|
import tempfile
|
|
import unittest
|
|
|
|
from github_log_summary import GINKGO_CLASS, GINKGO_CLASS_PREFIX
|
|
|
|
# Assumes directory structure of this file relative to repo.
|
|
SCRIPT_DIRPATH = os.path.dirname(os.path.realpath(__file__))
|
|
SCRIPT = os.path.join(SCRIPT_DIRPATH, 'github_log_summary.py')
|
|
LOGFORMATTER = os.path.join(SCRIPT_DIRPATH, 'logformatter')
|
|
|
|
# The stylesheet logformatter writes into every log names all the classes, so a
|
|
# summary that looked for them in the raw html would call any log a ginkgo one.
|
|
STYLE = """<style type="text/css">
|
|
.log-failed { color: #F00; font-weight: bold; font-size: 150%; }
|
|
.log-passed { color: #393; }
|
|
.log-error { background: #fee; color: #900; font-weight: bold; }
|
|
.ginkgo-timeline { margin-top: 1ex; margin-bottom: 1ex; }
|
|
.bats-failed { color: #F00; font-weight: bold; }
|
|
.bats-log-failblock { color: #b00; background-color: #fee; }
|
|
</style>"""
|
|
|
|
GINKGO_FAILURE = "Expected error to be nil, got: exit status 125"
|
|
GINKGO_LOG = f"""<html><head>{STYLE}</head><body>
|
|
<div class='tt'>
|
|
<span class="timestamp">[+0298s] </span><span class="log-failed">[FAILED]</span>
|
|
<span class="timestamp"> </span><a name='t--Podman-pod-create--1' /><h2 class="log-failed"> Podman pod create</h2>
|
|
<span class="timestamp"> </span> {GINKGO_FAILURE}
|
|
</div>
|
|
</body></html>"""
|
|
|
|
BATS_FAILURE = "# #| FAIL: exit code is 1; expected 0"
|
|
BATS_LOG = f"""<html><head>{STYLE}</head><body>
|
|
<div class='tt'>
|
|
<span class="timestamp">[+0017s] </span>time=<span class='log-error'>2026-09-11T10:00:00Z</span> level=<span class='log-error'>error</span> msg=<span class='log-error'>cannot remove container: in use</span>
|
|
<span class="timestamp">[+0018s] </span><span class='bats-failed'><a name='t--00002'>not ok 2 podman images</a></span>
|
|
<span class="timestamp"> </span><span class='bats-log-failblock'>{BATS_FAILURE}</span>
|
|
</div>
|
|
</body></html>"""
|
|
|
|
# Shape of a suite run without -p, where ginkgo reports the status too late for
|
|
# logformatter to pick it up, so every test heads 'log-passed' and only the
|
|
# stack trace div tells the failure apart. Taken from ginkgo 2.32.1 output run
|
|
# under the flags `make testbindings` uses.
|
|
PASSING_TEST_NOISE = "level=error msg=cannot connect, retrying"
|
|
NO_PARALLEL_LOG = f"""<html><head>{STYLE}</head><body>
|
|
<div class='tt'>
|
|
<span class="timestamp">[+0000s] </span><h2 class="log-passed">Podman containers podman inspect a container</h2>
|
|
<span class="timestamp"> </span><span class='log-error'>{PASSING_TEST_NOISE}</span>
|
|
</div>
|
|
<hr />
|
|
<div class='tt'>
|
|
<span class="timestamp">[+0000s] </span><h2 class="log-passed">Podman containers podman start a container</h2>
|
|
<div class='log-error'>
|
|
<span class="timestamp"> </span><h2 class="log-passed"> [FAILED] in [It] - containers_test.go:23</h2>
|
|
<span class="timestamp"> </span> {GINKGO_FAILURE}
|
|
</div>
|
|
</div>
|
|
<hr />
|
|
<div class='tt'>
|
|
<span class="ginkgo-final-fail">FAIL!</span> -- <span class="bats-passed"><b>1</b> Passed</span> | <span class="bats-failed"><b>1</b> Failed</span>
|
|
</div>
|
|
</body></html>"""
|
|
|
|
# logformatter nests the stack trace div inside another and does not always
|
|
# close them, which the real bindings logs show two levels deep.
|
|
FIRST_NESTED = "first failure, two divs deep"
|
|
SECOND_NESTED = "second failure, also nested"
|
|
NESTED_FAILURES_LOG = f"""<html><head>{STYLE}</head><body>
|
|
<div class='tt'>
|
|
<h2 class="log-passed">Podman info podman info</h2>
|
|
<div class='log-error'>
|
|
<div class='log-error'>
|
|
<span class="timestamp"> </span> {FIRST_NESTED}
|
|
</div>
|
|
</div>
|
|
<hr />
|
|
<div class='tt'>
|
|
<h2 class="log-passed">Podman info podman info container counts</h2>
|
|
<div class='log-error'>
|
|
<div class='log-error'>
|
|
<span class="timestamp"> </span> {SECOND_NESTED}
|
|
</div>
|
|
<hr />
|
|
<div class='tt'>
|
|
<span class="ginkgo-final-fail">FAIL!</span> -- <span class="bats-failed"><b>2</b> Failed</span>
|
|
</div>
|
|
</body></html>"""
|
|
|
|
# A job that died before any test ran carries neither layout's markers.
|
|
UNMARKED_LOG = f"""<html><head>{STYLE}</head><body>
|
|
<div class='tt'>
|
|
<span class="timestamp">[+0004s] </span>make: *** [Makefile:1: binaries] Error 2
|
|
</div>
|
|
</body></html>"""
|
|
|
|
|
|
class TestCase(unittest.TestCase):
|
|
|
|
def setUp(self):
|
|
self.tmpdir = tempfile.TemporaryDirectory()
|
|
self.addCleanup(self.tmpdir.cleanup)
|
|
|
|
def write_log(self, name, content):
|
|
path = os.path.join(self.tmpdir.name, name)
|
|
with open(path, 'w') as log:
|
|
log.write(content)
|
|
return path
|
|
|
|
def summarize(self, *args):
|
|
return subprocess.run([sys.executable, SCRIPT, *args],
|
|
capture_output=True, text=True)
|
|
|
|
def test_ginkgo_log_not_named_int(self):
|
|
"""bindings is a ginkgo suite too, its failures must be reported"""
|
|
log = self.write_log('bindings-root-fedora-current.log.html', GINKGO_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(GINKGO_FAILURE, result.stdout)
|
|
|
|
def test_bats_log(self):
|
|
log = self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(BATS_FAILURE, result.stdout)
|
|
|
|
def test_all_given_logs_are_summarized(self):
|
|
"""the workflow passes a glob, none of the matches may be dropped"""
|
|
result = self.summarize(
|
|
self.write_log('int-local-root-fedora-current.log.html', GINKGO_LOG),
|
|
self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG))
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(GINKGO_FAILURE, result.stdout)
|
|
self.assertIn(BATS_FAILURE, result.stdout)
|
|
self.assertLess(result.stdout.index(GINKGO_FAILURE),
|
|
result.stdout.index(BATS_FAILURE),
|
|
msg="logs must be reported in the order given")
|
|
|
|
def test_logs_are_named_only_when_there_is_more_than_one(self):
|
|
"""a single log needs no heading, several would run into each other"""
|
|
one = self.write_log('int-local-root-fedora-current.log.html', GINKGO_LOG)
|
|
self.assertNotIn('###', self.summarize(one).stdout)
|
|
|
|
two = self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG)
|
|
stdout = self.summarize(one, two).stdout
|
|
self.assertIn(f"### {os.path.basename(one)}", stdout)
|
|
self.assertIn(f"### {os.path.basename(two)}", stdout)
|
|
|
|
def test_ginkgo_suite_run_without_parallel(self):
|
|
"""without -p the stack trace div is the only mark of a failure"""
|
|
log = self.write_log('bindings-root-fedora-current.log.html', NO_PARALLEL_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(GINKGO_FAILURE, result.stdout)
|
|
|
|
def test_logrus_error_does_not_mark_a_passing_test(self):
|
|
"""that class also lands on error-level logrus lines, as a span"""
|
|
log = self.write_log('bindings-root-fedora-current.log.html', NO_PARALLEL_LOG)
|
|
self.assertNotIn(PASSING_TEST_NOISE, self.summarize(log).stdout)
|
|
|
|
def test_bats_log_holding_a_logrus_error(self):
|
|
"""that class must not pull a bats log over to the ginkgo parser"""
|
|
log = self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(BATS_FAILURE, result.stdout)
|
|
|
|
def test_nested_and_unclosed_failure_divs(self):
|
|
"""logformatter nests the trace div and leaves some of them open"""
|
|
log = self.write_log('bindings-root-fedora-current.log.html',
|
|
NESTED_FAILURES_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(FIRST_NESTED, result.stdout)
|
|
self.assertIn(SECOND_NESTED, result.stdout)
|
|
|
|
def test_an_unreadable_log_between_two_good_ones(self):
|
|
"""one bad path must not cost us the logs listed after it"""
|
|
first = self.write_log('int-local-root-fedora-current.log.html', GINKGO_LOG)
|
|
empty = self.write_log('unit-fedora-current.log.html', '')
|
|
last = self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG)
|
|
result = self.summarize(first, os.path.join(self.tmpdir.name, '*.html'),
|
|
empty, last)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(GINKGO_FAILURE, result.stdout)
|
|
self.assertIn(BATS_FAILURE, result.stdout)
|
|
self.assertLess(result.stdout.index(GINKGO_FAILURE),
|
|
result.stdout.index(BATS_FAILURE))
|
|
self.assertIn('skipping', result.stderr)
|
|
|
|
def test_every_failure_block_is_reported(self):
|
|
"""ginkgo logs hold one block per failing test, not just one in total"""
|
|
second = GINKGO_FAILURE.replace('125', '126')
|
|
log = self.write_log('int-local-root-fedora-current.log.html',
|
|
GINKGO_LOG + GINKGO_LOG.replace(GINKGO_FAILURE, second))
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(GINKGO_FAILURE, result.stdout)
|
|
self.assertIn(second, result.stdout)
|
|
|
|
def test_log_without_failures_says_nothing(self):
|
|
"""an empty code fence is noise, the step summary is better off blank"""
|
|
log = self.write_log('build-fedora-current.log.html', UNMARKED_LOG)
|
|
result = self.summarize(log)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertEqual(result.stdout, '')
|
|
|
|
def test_log_holding_invalid_utf8(self):
|
|
"""logformatter reads through ':utf8', which lets raw bytes past"""
|
|
path = os.path.join(self.tmpdir.name, 'int-local-root-fedora-current.log.html')
|
|
with open(path, 'wb') as log:
|
|
log.write(GINKGO_LOG.encode().replace(b'exit status 125',
|
|
b'exit status \xff\xfe125'))
|
|
result = self.summarize(path)
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn('Expected error to be nil', result.stdout)
|
|
|
|
def test_logformatter_still_emits_the_classes_we_look_for(self):
|
|
"""the layout is detected by classes logformatter has to keep emitting"""
|
|
with open(LOGFORMATTER) as source:
|
|
body = source.read()
|
|
self.assertIn(GINKGO_CLASS, body)
|
|
self.assertIn(GINKGO_CLASS_PREFIX, body)
|
|
|
|
def test_unreadable_log_is_skipped(self):
|
|
"""jobs without any html log hand over an unexpanded glob"""
|
|
result = self.summarize(
|
|
os.path.join(self.tmpdir.name, '*.html'),
|
|
self.write_log('sys-local-root-fedora-current.log.html', BATS_LOG))
|
|
self.assertEqual(result.returncode, 0, msg=result.stderr)
|
|
self.assertIn(BATS_FAILURE, result.stdout)
|
|
self.assertIn('skipping', result.stderr)
|
|
|
|
def test_no_logs_given(self):
|
|
result = self.summarize()
|
|
self.assertEqual(result.returncode, 2)
|
|
self.assertIn('usage', result.stderr)
|
|
|
|
|
|
if __name__ == "__main__":
|
|
unittest.main()
|