diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 731ee3bc5..453634ddc 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -653,9 +653,21 @@ jobs: env: SOCKET_PATCH_GO_E2E_REQUIRED: '1' SOCKET_PATCH_GO_E2E_VERSION: '1.24' + # + # The test output is also teed to a file so that a failing test's + # panic becomes an annotation (scripts/ci-test-failures.py): in a + # ~16k-line log it is otherwise buried far above the tail that log + # viewers and the log API return, and an intermittent failure + # can't be diagnosed once the re-run has passed. run: | + set -o pipefail cargo llvm-cov --workspace --no-fail-fast \ - --no-report + --no-report 2>&1 | tee "$RUNNER_TEMP/coverage-tests.log" || { + status=$? + python3 scripts/ci-test-failures.py "$RUNNER_TEMP/coverage-tests.log" || true + exit "$status" + } + set +o pipefail cargo llvm-cov report --lcov --output-path coverage-host.lcov python3 scripts/ci-lcov-summary.py coverage-host.lcov | tee coverage-summary.txt diff --git a/scripts/ci-test-failures.py b/scripts/ci-test-failures.py new file mode 100755 index 000000000..d62563015 --- /dev/null +++ b/scripts/ci-test-failures.py @@ -0,0 +1,138 @@ +#!/usr/bin/env python3 +"""Surface failing `cargo test` cases as GitHub annotations. + +A `cargo test --workspace --no-fail-fast` log runs to ~16k lines, and the +only annotation a failure leaves is "Process completed with exit code 101". +The panic of a failing test sits thousands of lines above the end, past +the tail that log viewers and log APIs return, so an intermittent failure +can't be diagnosed after the fact. This prints one `::error` per failing +test, titled with the test target and name and carrying its panic output, +and appends the same to the job summary when $GITHUB_STEP_SUMMARY is set. + +Usage: ci-test-failures.py LOG +""" + +import os +import re +import sys +from collections import deque + +# ` Running tests/foo.rs (target/debug/deps/foo-0123abcd)`; the binary +# name tells crates apart where the source path (`src/lib.rs`) doesn't. +# The path group is required so a child process's own "Running ..." line +# can't pass for a cargo header. +RUNNING = re.compile(r"^\s+Running (?:unittests )?\S+ \((\S+)\)$") +DOCTESTS = re.compile(r"^\s+Doc-tests (\S+)$") +SECTION = re.compile(r"^---- (.+) stdout ----$") +# A binary that dies (signal, abort, stack overflow) prints no section, only +# cargo's `error: test failed, to rerun pass ...` and the exit status. +RERUN = re.compile(r"^error: test failed, to rerun pass ") +# GitHub shows at most 10 error annotations per step. +MAX_ANNOTATIONS = 10 +MAX_LINES = 40 +MAX_LINE_CHARS = 500 +MAX_SUMMARY_CHARS = 512 * 1024 +CRASH_CONTEXT = 25 +CRASH_TAIL = 4 +# Log lines read back from the Actions API carry this prefix (7 fractional +# digits); tracing's own timestamps (6 digits) are left alone. +TIMESTAMP = re.compile(r"^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d{7}Z ?") + + +def failures(lines): + """Yield (target, test, body lines) for each failing test or dead binary.""" + target, test, body = "", None, [] + seen = False # a section was reported for the current binary + recent = deque(maxlen=CRASH_CONTEXT) + crash = None # (target, lines before, cargo's cause after) of a dead binary + for raw in lines: + line = TIMESTAMP.sub("", raw.rstrip("\r\n")) + if crash is not None: + # Keep cargo's `Caused by: ... (signal: 6, SIGABRT ...)` lines. + header = RUNNING.match(line) or DOCTESTS.match(line) or line.startswith("error: ") + if not header and len(crash[2]) < CRASH_TAIL: + crash[2].append(line) + continue + yield crash[0], "(test binary exited without a test report)", crash[1] + crash[2] + crash = None + if test is not None: + if SECTION.match(line) or line == "failures:": + yield target, test, body + test, body = None, [] + else: + body.append(line) + continue + running = RUNNING.match(line) + doctests = DOCTESTS.match(line) + if running or doctests: + if running: + target = re.sub(r"-[0-9a-f]+(\.exe)?$", "", os.path.basename(running.group(1))) + else: + target = f"{doctests.group(1)} doctests" + seen = False + recent.clear() + section = SECTION.match(line) + if section: + test, seen = section.group(1), True + elif RERUN.match(line) and not seen: + crash = (target, list(recent) + [line], []) + recent.append(line) + if test is not None: + yield target, test, body + if crash is not None: + yield crash[0], "(test binary exited without a test report)", crash[1] + crash[2] + + +def trim(body): + while body and not body[0].strip(): + body = body[1:] + while body and not body[-1].strip(): + body = body[:-1] + body = [ + line if len(line) <= MAX_LINE_CHARS else line[:MAX_LINE_CHARS] + " ...(cut)" + for line in body + ] + if len(body) > MAX_LINES: + body = body[:MAX_LINES] + [f"... ({len(body) - MAX_LINES} more lines in the log)"] + return body + + +def fence(body): + longest = max((len(run) for line in body for run in re.findall(r"`+", line)), default=0) + return "`" * max(3, longest + 1) + + +def escape(text, prop=False): + text = text.replace("%", "%25").replace("\r", "%0D").replace("\n", "%0A") + if prop: + text = text.replace(":", "%3A").replace(",", "%2C") + return text + + +def main(argv): + with open(argv[1], encoding="utf-8", errors="replace") as log: + found = [(t, n, trim(b)) for t, n, b in failures(log)] + for target, test, body in found[:MAX_ANNOTATIONS]: + title = f"{target} {test}" if target else test + print(f"::error title={escape(title, prop=True)}::{escape(chr(10).join(body))}") + if len(found) > MAX_ANNOTATIONS: + print(f"::error::{len(found) - MAX_ANNOTATIONS} more failing tests; see the job summary") + summary = os.environ.get("GITHUB_STEP_SUMMARY") + if summary and found: + parts = [f"## Failing tests ({len(found)})\n\n"] + size = len(parts[0]) + for i, (target, test, body) in enumerate(found): + f = fence(body) + part = f"### `{test}`\n\n{target}\n\n{f}\n" + "\n".join(body) + f"\n{f}\n\n" + if size + len(part) > MAX_SUMMARY_CHARS: + parts.append(f"... {len(found) - i} more failing tests are in the log.\n") + break + parts.append(part) + size += len(part) + with open(summary, "a", encoding="utf-8") as out: + out.write("".join(parts)) + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv)) diff --git a/scripts/tests/fixtures/cargo-test-failures.txt b/scripts/tests/fixtures/cargo-test-failures.txt new file mode 100644 index 000000000..a452a37b3 --- /dev/null +++ b/scripts/tests/fixtures/cargo-test-failures.txt @@ -0,0 +1,98 @@ + Compiling demo v0.1.0 (/work/demo) + Finished `test` profile [unoptimized + debuginfo] target(s) in 0.45s + Running unittests src/lib.rs (target/debug/deps/demo-88d774561b498750) + +running 1 test +test lib_ok ... ok + +test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s + + Running tests/a_crash.rs (target/debug/deps/a_crash-7c6e51f853f8ec2d) + +running 1 test +error: test failed, to rerun pass `--test a_crash` + +Caused by: + process didn't exit successfully: `/work/demo/target/debug/deps/a_crash-7c6e51f853f8ec2d` (signal: 6, SIGABRT: process abort signal) + Running tests/b_fail.rs (target/debug/deps/b_fail-88cf522839ce0d9a) + +running 1 test +test bad ... FAILED + +failures: + +---- bad stdout ---- +``` + +thread 'bad' (6319) panicked at tests/b_fail.rs:1:37: +assertion `left == right` failed + left: 1 + right: 2 +stack backtrace: + 0: __rustc::rust_begin_unwind + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/std/src/panicking.rs:689:5 + 1: core::panicking::panic_fmt + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:80:14 + 2: core::panicking::assert_failed_inner + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:439:17 + 3: core::panicking::assert_failed:: + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:394:5 + 4: b_fail::bad + at ./tests/b_fail.rs:1:37 + 5: b_fail::bad::{closure#0} + at ./tests/b_fail.rs:1:17 + 6: >::call_once + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/ops/function.rs:250:5 + 7: core::result::Result<(), alloc::string::String> as core::ops::function::FnOnce<()>>::call_once + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/ops/function.rs:250:5 +note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. + + +failures: + bad + +test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s + +error: test failed, to rerun pass `--test b_fail` + Doc-tests demo + +running 1 test +test src/lib.rs - one (line 1) ... FAILED + +failures: + +---- src/lib.rs - one (line 1) stdout ---- +Test executable failed (exit status: 101). + +stderr: + +thread 'main' (6338) panicked at src/lib.rs:5:1: +assertion `left == right` failed + left: 1 + right: 2 +stack backtrace: + 0: __rustc::rust_begin_unwind + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/std/src/panicking.rs:689:5 + 1: core::panicking::panic_fmt + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:80:14 + 2: core::panicking::assert_failed_inner + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:439:17 + 3: core::panicking::assert_failed:: + at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/panicking.rs:394:5 + 4: rust_out::main::_doctest_main_src_lib_rs_1_0 + 5: rust_out::main + 6: >::call_once +note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. + + + +failures: + src/lib.rs - one (line 1) + +test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.33s + +error: doctest failed, to rerun pass `--doc` +error: 3 targets failed: + `--test a_crash` + `--test b_fail` + `--doc` diff --git a/scripts/tests/test_ci_test_failures.py b/scripts/tests/test_ci_test_failures.py new file mode 100644 index 000000000..4f210be97 --- /dev/null +++ b/scripts/tests/test_ci_test_failures.py @@ -0,0 +1,126 @@ +"""Failing `cargo test` cases become annotations naming the binary and test.""" + +import contextlib +import importlib.util +import io +import os +import tempfile +import unittest +from pathlib import Path +from unittest import mock + +ROOT = Path(__file__).parents[2] +spec = importlib.util.spec_from_file_location("test_failures", ROOT / "scripts/ci-test-failures.py") +tf = importlib.util.module_from_spec(spec) +spec.loader.exec_module(tf) + +LOG = """\ +2026-10-12T16:01:00.0000000Z Running unittests src/lib.rs (target/llvm-cov-target/debug/deps/socket_patch_core-0123abcd) +2026-10-12T16:01:00.1000000Z test formats::ok ... ok +2026-10-12T16:01:00.2000000Z test formats::pure ... FAILED +2026-10-12T16:01:00.3000000Z +2026-10-12T16:01:00.4000000Z failures: +2026-10-12T16:01:00.5000000Z +2026-10-12T16:01:00.6000000Z ---- formats::pure stdout ---- +2026-10-12T16:01:00.7000000Z thread 'formats::pure' panicked at src/formats/mod.rs:95:13: +2026-10-12T16:01:00.8000000Z 100% impure, a: b +2026-10-12T16:01:00.9000000Z +2026-10-12T16:01:01.0000000Z +2026-10-12T16:01:01.1000000Z failures: +2026-10-12T16:01:01.2000000Z formats::pure +2026-10-12T16:01:01.3000000Z +2026-10-12T16:01:01.4000000Z test result: FAILED. 1 passed; 1 failed +2026-10-12T16:01:02.0000000Z Running tests/in_process_edge_cases.rs (target/llvm-cov-target/debug/deps/in_process_edge_cases-feedbeef) +2026-10-12T16:01:02.1000000Z ---- apply_one stdout ---- +2026-10-12T16:01:02.2000000Z assertion `left == right` failed +2026-10-12T16:01:02.3000000Z ---- apply_two stdout ---- +2026-10-12T16:01:02.4000000Z thread 'apply_two' panicked +""" + + +class Failures(unittest.TestCase): + def parse(self, text): + return [(t, n, tf.trim(b)) for t, n, b in tf.failures(io.StringIO(text))] + + def test_each_section_is_attributed_to_its_binary(self): + self.assertEqual( + self.parse(LOG), + [ + ( + "socket_patch_core", + "formats::pure", + [ + "thread 'formats::pure' panicked at src/formats/mod.rs:95:13:", + "100% impure, a: b", + ], + ), + ("in_process_edge_cases", "apply_one", ["assertion `left == right` failed"]), + ("in_process_edge_cases", "apply_two", ["thread 'apply_two' panicked"]), + ], + ) + + def test_real_cargo_log_covers_crashes_tests_and_doctests(self): + # `cargo test --no-fail-fast` over a crate whose lib test prints a + # child's " Running npm install", one test binary aborts, one test + # fails printing a ``` line, and one doctest fails. + found = self.parse((ROOT / "scripts/tests/fixtures/cargo-test-failures.txt").read_text()) + self.assertEqual( + [(t, n) for t, n, _ in found], + [ + ("a_crash", "(test binary exited without a test report)"), + ("b_fail", "bad"), + ("demo doctests", "src/lib.rs - one (line 1)"), + ], + ) + crash = "\n".join(found[0][2]) + self.assertIn("SIGABRT", crash) + self.assertNotIn("b_fail", crash) + self.assertIn("panicked at tests/b_fail.rs", "\n".join(found[1][2])) + self.assertEqual(tf.fence(found[1][2]), "````") + + def test_a_passing_log_has_no_failures(self): + self.assertEqual(self.parse(" Running tests/a.rs (target/debug/deps/a-1)\ntest x ... ok\n"), []) + + def test_long_bodies_are_capped(self): + body = tf.trim([str(i) for i in range(tf.MAX_LINES + 5)] + ["", ""]) + self.assertEqual(len(body), tf.MAX_LINES + 1) + self.assertIn("5 more lines", body[-1]) + + def test_overlong_lines_are_cut(self): + self.assertEqual(len(tf.trim(["x" * 10_000])[0]), tf.MAX_LINE_CHARS + len(" ...(cut)")) + + def test_annotations_past_the_cap_are_counted(self): + log = "".join(f"---- t{i} stdout ----\npanic {i}\n" for i in range(tf.MAX_ANNOTATIONS + 3)) + with tempfile.TemporaryDirectory() as tmp: + path = Path(tmp, "log") + path.write_text(log) + out = io.StringIO() + with mock.patch.dict(os.environ, {"GITHUB_STEP_SUMMARY": ""}): + with contextlib.redirect_stdout(out): + tf.main(["ci-test-failures.py", str(path)]) + lines = out.getvalue().splitlines() + self.assertEqual(len(lines), tf.MAX_ANNOTATIONS + 1) + self.assertEqual(lines[-1], "::error::3 more failing tests; see the job summary") + + def test_annotations_and_summary_are_escaped(self): + with tempfile.TemporaryDirectory() as tmp: + log = Path(tmp, "log") + log.write_text(LOG) + summary = Path(tmp, "summary.md") + out = io.StringIO() + with mock.patch.dict(os.environ, {"GITHUB_STEP_SUMMARY": str(summary)}): + with contextlib.redirect_stdout(out): + self.assertEqual(tf.main(["ci-test-failures.py", str(log)]), 0) + lines = out.getvalue().splitlines() + self.assertEqual(len(lines), 3) + self.assertEqual( + lines[0], + "::error title=socket_patch_core formats%3A%3Apure::" + "thread 'formats::pure' panicked at src/formats/mod.rs:95:13:%0A100%25 impure, a: b", + ) + self.assertIn("## Failing tests (3)", summary.read_text()) + self.assertIn("### `apply_two`", summary.read_text()) + + +if __name__ == "__main__": + unittest.main()