Annotate failing tests in the coverage job

.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
 

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))

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::<i32, i32>
+             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: <b_fail::bad::{closure#0} as core::ops::function::FnOnce<()>>::call_once
+             at /rustc/2d8144b7880597b6e6d3dfd63a9a9efae3f533d3/library/core/src/ops/function.rs:250:5
+   7: <fn() -> 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::<u32, u32>
+             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: <fn() as core::ops::function::FnOnce<()>>::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`

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()