Attach gtest console output to unit-test failures

Signed-off-by: Bonnie Chan <bonniecv@amazon.com>

Author: BChan-0

scripts/test_failure_detector/gtest_log_parser.py

@@ -0,0 +1,105 @@
+"""Recover gtest failure output from a job's console log.
+
+gtest-parallel's JSON dump records only a per-test verdict (PASS, FAIL,
+TIMEOUT) and timings, so the extraction action can report no more than which
+test failed. The assertion that failed, its file and line, and the expected and
+actual values are printed to the console instead. This reads that block back out
+of the job log so an issue carries the diagnostic a maintainer needs.
+"""
+
+from __future__ import annotations
+
+import logging
+import re
+
+logger = logging.getLogger(__name__)
+
+# gtest-parallel brackets each test it runs with a progress line, and closes a
+# failing one by repeating the header with the exit code:
+#
+#   [6/298] DummyTest.IntentionalFailure (2 ms)
+#   ... the test's own gtest output ...
+#   [6/298] DummyTest.IntentionalFailure returned with exit code 1 (2 ms)
+#
+# Anchoring on the closing line rather than the next test's header keeps the
+# block intact when tests run in parallel and their output interleaves.
+_GTEST_BLOCK_START_RE = re.compile(
+    r"^\[\d+/\d+\]\s+(?P<test>[\w./:]+(?:\.[\w./:]+)?)\s+\([\d.]+\s*m?s\)\s*$"
+)
+_GTEST_BLOCK_END_RE = re.compile(
+    r"^\[\d+/\d+\]\s+(?P<test>[\w./:]+)\s+returned with exit code\s+(?P<code>\d+)"
+)
+
+# A GitHub Actions log line is prefixed with an ISO timestamp, and gtest colours
+# its output. Both are noise in an issue body, and the timestamp would also make
+# two runs of one failure compare unequal in the recurrence check.
+_LOG_TIMESTAMP_RE = re.compile(r"^\d{4}-\d{2}-\d{2}T[\d:.]+Z\s?")
+_ANSI_RE = re.compile(r"\033\[[0-9;]*m")
+
+# A block longer than this is not a test diagnostic: a test that logs in a loop
+# can print thousands of lines before failing. The head holds the assertion, so
+# the cap keeps that and drops the rest.
+_MAX_BLOCK_LINES = 200
+
+
+def _clean(line: str) -> str:
+    return _ANSI_RE.sub("", _LOG_TIMESTAMP_RE.sub("", line)).rstrip()
+
+
+def parse_gtest_failures_from_log(log_content: bytes) -> dict[str, str]:
+    """Map test name to its console output, for tests that failed in *log*.
+
+    Only tests whose block is closed by a non-zero exit code are returned, so a
+    test that passed on a retry contributes nothing. Returns an empty mapping
+    when the log holds no gtest blocks, which is the normal case for a job that
+    runs no unit tests.
+    """
+    try:
+        text = log_content.decode("utf-8", errors="replace")
+    except Exception:
+        logger.warning("Could not decode a job log while recovering gtest output")
+        return {}
+
+    failures: dict[str, str] = {}
+    # gtest-parallel buffers each test's output and prints it in one piece
+    # between that test's own progress lines, so an output line belongs to the
+    # most recently opened block. Appending to every open block instead would
+    # copy one test's output into another's issue.
+    open_blocks: dict[str, list[str]] = {}
+    current: str | None = None
+    for raw_line in text.split("\n"):
+        line = _clean(raw_line)
+
+        end = _GTEST_BLOCK_END_RE.match(line)
+        if end is not None:
+            test = end.group("test")
+            body = open_blocks.pop(test, None)
+            if end.group("code") == "0":
+                # The attempt passed. gtest-parallel reruns a failed test, so a
+                # zero close can follow a non-zero one for the same test; the
+                # retry passed and the run does not treat it as a failure, so
+                # any output recorded for the earlier attempt is discarded.
+                failures.pop(test, None)
+            elif body is not None:
+                failures[test] = "\n".join([*body, line]).strip()
+            if current == test:
+                current = None
+            continue
+
+        start = _GTEST_BLOCK_START_RE.match(line)
+        if start is not None:
+            current = start.group("test")
+            open_blocks[current] = [line]
+            continue
+
+        if current is None:
+            continue
+        body = open_blocks[current]
+        if len(body) < _MAX_BLOCK_LINES:
+            body.append(line)
+
+    if failures:
+        logger.info(
+            "Recovered console output for %d gtest failure(s)", len(failures)
+        )
+    return failures

scripts/test_failure_detector/timeout_recovery.py

@@ -5,9 +5,9 @@
 identifies failed jobs without a captured timeout, downloads their console logs,
 and extracts [TIMEOUT] failures that would otherwise be invisible.
 
-It also attaches the runner's clients-state report to timeouts, whose artifact
-entries carry only a verdict, for the same reason: the diagnostic exists only
-in the log.
+It also fills in failures whose artifact entry carries only a verdict, for the
+same reason: a timeout's clients-state report and a gtest failure's assertion
+output both exist only in the log.
 
 Orchestration is separated from parsing: :mod:`timeout_parser` and
 :mod:`gtest_log_parser` handle the regex extraction; this module decides which
@@ -22,6 +22,9 @@
 
 from scripts.common.workflow_artifacts import ArtifactClient
 from scripts.test_failure_detector.download import JobInfo
+from scripts.test_failure_detector.gtest_log_parser import (
+    parse_gtest_failures_from_log,
+)
 from scripts.test_failure_detector.parse_failures import FailureType, UniqueFailure
 from scripts.test_failure_detector.timeout_parser import (
     clients_state_report_from_log,
@@ -127,9 +130,11 @@ def enrich_log_only_errors(
 ) -> None:
     """Attach console output to failures the artifact records without detail.
 
+    Two types arrive with a placeholder instead of a diagnostic. A gtest failure
+    carries only a verdict, because gtest-parallel's JSON dump holds no output.
     A timeout carries only "Test timed out", because the runner has nothing to
-    report beyond the watchdog firing. The detail exists in the job log, so it
-    is read back and attached in place.
+    report beyond the watchdog firing. In both cases the detail exists in the
+    job log, so it is read back and attached in place.
 
     Best-effort, and mutates *failures* in place. A log that is expired,
     unavailable, or missing the failure's block leaves the placeholder as it
@@ -138,18 +143,29 @@ def enrich_log_only_errors(
     Shares its ``run_logs`` with timeout recovery, so the run's log zip is
     downloaded at most once per run.
     """
+    # The extraction action attaches gtest-parallel's per-test log when it finds
+    # one and falls back to a bare verdict when it does not. Only the fallback is
+    # enriched: the action's own text comes from the test's dedicated log file,
+    # while the run log interleaves every worker's output, so overwriting it
+    # replaced a full assertion with the two progress lines around it.
+    gtest_failures = [
+        f for f in failures
+        if f.failure_type == FailureType.UNITTEST
+        and f.test_name
+        and "\n" not in f.error.strip()
+    ]
     # A timeout recovered from a log already carries its report; only the
     # artifact-derived ones still hold the bare placeholder.
     timeout_failures = [
         f for f in failures
         if f.failure_type == FailureType.TIMEOUT and "\n" not in f.error.strip()
     ]
-    if not timeout_failures:
+    if not gtest_failures and not timeout_failures:
         return
 
     jobs_to_scan = {
         job_ref.job
-        for f in timeout_failures
+        for f in (*gtest_failures, *timeout_failures)
         for job_ref in f.jobs
     } & set(job_info.failed)
     if not jobs_to_scan:
@@ -162,16 +178,25 @@ def enrich_log_only_errors(
 
     # One failure can appear on several jobs. Scan in a stable order so the
     # attached output does not depend on set iteration order.
+    gtest_outputs: dict[str, str] = {}
     timeout_reports: dict[str, str] = {}
     for job_name in sorted(jobs_to_scan):
         log_content = find_job_log(logs, job_name)
         if log_content is None:
             continue
+        for test_name, body in parse_gtest_failures_from_log(log_content).items():
+            gtest_outputs.setdefault(test_name, body)
         report = clients_state_report_from_log(log_content)
         if report:
             timeout_reports.setdefault(job_name, report)
 
     enriched = 0
+    for failure in gtest_failures:
+        recovered_output = gtest_outputs.get(failure.test_name)
+        if recovered_output:
+            failure.error = recovered_output
+            enriched += 1
+
     for failure in timeout_failures:
         for job_ref in failure.jobs:
             job_report = timeout_reports.get(job_ref.job)

tests/test_testfailuredetector_gtest_log_parser.py

@@ -0,0 +1,112 @@
+"""Tests for recovering gtest failure output from a job's console log."""
+
+from __future__ import annotations
+
+from scripts.test_failure_detector.gtest_log_parser import (
+    parse_gtest_failures_from_log,
+)
+
+# A real block as GitHub stores it: an ISO timestamp on every line and gtest's
+# colour codes around its status tags.
+_REAL_LOG = (
+    "2026-07-29T23:29:31.7910142Z [6/298] DictTest.BasicOps (2 ms)\n"
+    "2026-07-29T23:29:31.7912499Z \x1b[0;33mNote: Google Test filter = DictTest.BasicOps\n"
+    "2026-07-29T23:29:31.7914000Z [==========] Running 1 test from 1 test suite.\n"
+    "2026-07-29T23:29:31.7916184Z \x1b[0;32m[ RUN      ] \x1b[mDictTest.BasicOps\n"
+    "2026-07-29T23:29:31.7916693Z test_dict.cpp:34: Failure\n"
+    "2026-07-29T23:29:31.7917000Z Expected equality of these values:\n"
+    "2026-07-29T23:29:31.7917500Z   got\n"
+    "2026-07-29T23:29:31.7918000Z     Which is: \"myvalue\"\n"
+    "2026-07-29T23:29:31.7918500Z   \"wrongvalue\"\n"
+    "2026-07-29T23:29:31.7919098Z \x1b[0;31m[  FAILED  ] \x1b[mDictTest.BasicOps (0 ms)\n"
+    "2026-07-29T23:29:31.7923059Z  1 FAILED TEST\n"
+    "2026-07-29T23:29:31.7923540Z [6/298] DictTest.BasicOps returned with exit code 1 (2 ms)\n"
+)
+
+
+class TestParseGtestFailuresFromLog:
+    def test_recovers_the_failing_tests_output(self) -> None:
+        out = parse_gtest_failures_from_log(_REAL_LOG.encode())
+        assert list(out) == ["DictTest.BasicOps"]
+        body = out["DictTest.BasicOps"]
+        assert "test_dict.cpp:34: Failure" in body
+        assert "Expected equality of these values:" in body
+        assert '"wrongvalue"' in body
+
+    def test_strips_timestamps_and_colour_codes(self) -> None:
+        """Both are log transport, not diagnostic. The timestamp also has to go
+        or two runs of one failure would never compare equal in the recurrence
+        check."""
+        body = parse_gtest_failures_from_log(_REAL_LOG.encode())["DictTest.BasicOps"]
+        assert "2026-07-29T23:29:31" not in body
+        assert "\x1b[" not in body
+        assert "[ RUN      ] DictTest.BasicOps" in body
+
+    def test_a_passing_test_is_not_reported(self) -> None:
+        """Only a block closed by a non-zero exit code is a failure, so a test
+        that passed on a retry contributes nothing."""
+        log = (
+            "[1/2] DictTest.Passing (1 ms)\n"
+            "[  OK  ] DictTest.Passing\n"
+            "[2/2] DictTest.Other (1 ms)\n"
+            "[2/2] DictTest.Other returned with exit code 1 (1 ms)\n"
+        )
+        assert list(parse_gtest_failures_from_log(log.encode())) == ["DictTest.Other"]
+
+    def test_interleaved_blocks_stay_separate(self) -> None:
+        """gtest-parallel runs tests concurrently, so one test's output can
+        appear between another's start and end."""
+        log = (
+            "[1/2] SuiteA.One (1 ms)\n"
+            "a-first-line\n"
+            "[2/2] SuiteB.Two (1 ms)\n"
+            "b-first-line\n"
+            "[1/2] SuiteA.One returned with exit code 1 (1 ms)\n"
+            "[2/2] SuiteB.Two returned with exit code 1 (1 ms)\n"
+        )
+        out = parse_gtest_failures_from_log(log.encode())
+        assert set(out) == {"SuiteA.One", "SuiteB.Two"}
+        assert "a-first-line" in out["SuiteA.One"]
+        assert "b-first-line" in out["SuiteB.Two"]
+        assert "b-first-line" not in out["SuiteA.One"]
+
+    def test_a_log_with_no_gtest_blocks_yields_nothing(self) -> None:
+        """The normal case for a job that runs no unit tests."""
+        assert parse_gtest_failures_from_log(b"make: *** [all] Error 1\n") == {}
+
+    def test_an_unterminated_block_is_not_reported(self) -> None:
+        """A job killed mid-test leaves an open block, which says nothing about
+        whether the test failed."""
+        log = "[1/2] SuiteA.One (1 ms)\nsome output\n"
+        assert parse_gtest_failures_from_log(log.encode()) == {}
+
+    def test_a_runaway_block_is_capped(self) -> None:
+        """A test that logs in a loop must not put thousands of lines in an
+        issue body. The head holds the assertion."""
+        noise = "".join(f"line {i}\n" for i in range(5000))
+        log = (
+            "[1/1] SuiteA.One (1 ms)\n"
+            f"{noise}"
+            "[1/1] SuiteA.One returned with exit code 1 (1 ms)\n"
+        )
+        body = parse_gtest_failures_from_log(log.encode())["SuiteA.One"]
+        assert body.count("\n") < 250
+        assert "line 0" in body
+
+    def test_invalid_utf8_does_not_raise(self) -> None:
+        log = b"[1/1] SuiteA.One (1 ms)\n\xff\xfe bad bytes\n[1/1] SuiteA.One returned with exit code 1 (1 ms)\n"
+        assert "SuiteA.One" in parse_gtest_failures_from_log(log)
+
+    def test_a_retry_that_passed_is_not_reported(self) -> None:
+        """gtest-parallel reruns a failed test and closes the retry with exit
+        code 0. Only the non-zero close is a failure, so a test that passed on
+        retry contributes no output."""
+        log = (
+            "[1/1] SuiteA.One (1 ms)\n"
+            "first attempt failed\n"
+            "[1/1] SuiteA.One returned with exit code 1 (1 ms)\n"
+            "[1/1] SuiteA.One (1 ms)\n"
+            "second attempt passed\n"
+            "[1/1] SuiteA.One returned with exit code 0 (1 ms)\n"
+        )
+        assert parse_gtest_failures_from_log(log.encode()) == {}