diff --git a/.github/workflows/_test.yml b/.github/workflows/_test.yml index 61ab9d0e0f..757f9ba72e 100644 --- a/.github/workflows/_test.yml +++ b/.github/workflows/_test.yml @@ -187,6 +187,23 @@ jobs: # shard-completeness job still gates the cross-shard union. if-no-files-found: warn + # The job log carries a red suite's SUMMARY; these are the complete logs + # behind it, so a failure can be read instead of re-run. The harness + # copies the log of every suite that did not end green, plus results.txt, + # into test-logs/failed/ (scripts/suite-failure-report.sh) — typically a + # few kilobytes for a red suite, not the ~25 MB of a whole run's logs. + # Runs only on a failed job. warn, not error: a job that failed OUTSIDE + # the suite wave (contract step, build, prod-binary guards) has no such + # directory, and a second error would only bury the first. + - name: Failing suite logs + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: suite-logs-${{ matrix.os }}-${{ matrix.cc }}-${{ strategy.job-index }} + path: build/c/test-logs/failed/ + retention-days: 7 + if-no-files-found: warn + - name: Compiler cache (save) if: always() && (matrix.shard == null || startsWith(matrix.shard, '1/')) uses: actions/cache/save@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 @@ -282,6 +299,17 @@ jobs: scripts/test.sh CC=clang-21 CXX=clang++-21 \ SANITIZE="-fsanitize=address,undefined -fno-omit-frame-pointer -fno-optimize-sibling-calls" + # Same step as in test-unix: the complete logs of the suites that did + # not end green, only when the job failed. + - name: Failing suite logs + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: suite-logs-diag + path: build/c/test-logs/failed/ + retention-days: 7 + if-no-files-found: warn + - name: Compiler cache (save) if: always() uses: actions/cache/save@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 @@ -364,6 +392,17 @@ jobs: LLVM_PREFIX="$(brew --prefix llvm@22)" scripts/test.sh CC="$LLVM_PREFIX/bin/clang" CXX="$LLVM_PREFIX/bin/clang++" + # Same step as in test-unix: the complete logs of the suites that did + # not end green, only when the job failed. + - name: Failing suite logs + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: suite-logs-lsan-macos + path: build/c/test-logs/failed/ + retention-days: 7 + if-no-files-found: warn + - name: Compiler cache (save) if: always() uses: actions/cache/save@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 @@ -531,6 +570,17 @@ jobs: # shard-completeness job still gates the cross-shard union. if-no-files-found: warn + # Same step as in test-unix: the complete logs of the suites that did + # not end green, only when the job failed. + - name: Failing suite logs + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: suite-logs-${{ matrix.os }}-${{ matrix.msystem }}-${{ strategy.job-index }} + path: build/c/test-logs/failed/ + retention-days: 7 + if-no-files-found: warn + # Shard 1 (or the unsharded job) saves the compiler cache; every shard # builds the identical runner, so one cache carries the full object set. - name: Compiler cache (save) diff --git a/scripts/README.md b/scripts/README.md index 619959ebe2..e09801df30 100644 --- a/scripts/README.md +++ b/scripts/README.md @@ -29,7 +29,10 @@ codes) and rejects unknown flags with exit 2 + `Please consult --help.` Internal harnesses — never called directly by a venue (the contract forbids it): `smoke-test.sh` (phases; wrappers provide fixture server + sandbox), `soak-test.sh` (one soak run; `soak-legs.sh` provides the sequence + guards), -`run-tests-parallel.sh` (reached through `test.sh`). +`run-tests-parallel.sh` (reached through `test.sh`), which sources +`suite-failure-report.sh` for its end-of-run failure summary (failure sites, +sanitizer report, running test, last lines) and for `test-logs/failed/`, the +logs of every suite that did not end green. ## Conventions diff --git a/scripts/run-test-wave.py b/scripts/run-test-wave.py index e47852ba13..d5e406414b 100755 --- a/scripts/run-test-wave.py +++ b/scripts/run-test-wave.py @@ -26,6 +26,9 @@ SUMMARY = re.compile(r"^ (?P[0-9]+) passed") FAILED = re.compile(r"(?:^|, )(?P[0-9]+) failed") SKIPPED = re.compile(r"(?:^|, )(?P[0-9]+) skipped") +# One finished test, as RUN_TEST prints it: "PASS" ending the test's own line, +# or alone on a line when the test wrote to stderr in between. +PASS_MARKER = re.compile(r"^(?: [A-Za-z_].*)?PASS\s*$") # Suites whose honest runtime does not fit the default per-suite budget, and so # get --slow-timeout instead. This is a statement about SIZE, never about # flakiness: every suite here is deterministic and simply long, and a racy suite @@ -393,6 +396,20 @@ def parse_summary(log_path: pathlib.Path) -> tuple[int, int, int] | None: return last_summary +def count_pass_markers(log_path: pathlib.Path) -> int: + """Tests that finished before a suite died without its completion summary. + + The framework flushes each test's name before running it, so every PASS + ahead of the point of death is already in the log. + """ + try: + stream = log_path.open(encoding="utf-8", errors="replace") + except OSError as exc: + raise RuntimeError(f"cannot read suite log {log_path}: {exc}") from exc + with stream: + return sum(1 for line in stream if PASS_MARKER.match(line) is not None) + + def record_result( active: ActiveSuite, returncode: int, @@ -416,7 +433,15 @@ def record_result( f" FAIL: suite {active.name!r} exited 0 without a completion summary " "(ran nothing?)", ) - passed, failed, skipped = summary or (0, 0, 0) + # WHY: a suite that aborts, is killed or times out never prints its summary + # line, and reporting it as pass=0 said "ran nothing" about a suite that + # had finished dozens of tests. Count what the log proves instead. Only + # passes: a death is not a counted test failure, and rc already makes the + # run red. A suite WITH a summary is never recounted, so green totals are + # exactly what they were. + if summary is None: + summary = (count_pass_markers(active.log_path), 0, 0) + passed, failed, skipped = summary result = ( f"{active.name} rc={returncode} pass={passed} fail={failed} " f"skip={skipped} secs={elapsed}" diff --git a/scripts/run-tests-parallel.sh b/scripts/run-tests-parallel.sh index d28829540c..b2f570f3ab 100644 --- a/scripts/run-tests-parallel.sh +++ b/scripts/run-tests-parallel.sh @@ -24,6 +24,11 @@ RUNNER="${1:?usage: run-tests-parallel.sh [jobs]}" JOBS="${2:-${CBM_TEST_PAR_JOBS:-}}" SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" SCHEDULER="$SCRIPT_DIR/run-test-wave.py" +# The end-of-run failure summary and the failing-log selection live in one +# sourced file so tests/test_failure_report_contract.sh can drive the real +# functions with fabricated logs. +# shellcheck source=suite-failure-report.sh +source "$SCRIPT_DIR/suite-failure-report.sh" if [ -z "$JOBS" ]; then if command -v nproc >/dev/null 2>&1; then @@ -251,6 +256,14 @@ NSHARD=$(wc -l < "$SHARD_EXPECT" | tr -d ' ') } > "$LOGDIR/shard-manifest.txt" echo "=== parallel test run: $NSHARD of $NSUITES suites (shard ${SHARD_INDEX}/${SHARD_TOTAL}, $(wc -l < "$SER_FILE" | tr -d ' ') serial-tail), $JOBS jobs ===" +# Leave the logs of every non-green suite in $LOGDIR/failed for CI to upload +# when the job fails. An EXIT trap rather than a call next to the summary +# below, because the run has three ways out — the scheduler giving up, the +# union guard, and the normal end — and the first two are exactly the runs +# whose logs are otherwise unrecoverable. The trap only copies files: it never +# calls exit, so the status this script ends with is untouched. +trap 'collect_failed_suite_logs "$LOGDIR" "$RESULTS_FILE" "$SHARD_EXPECT"' EXIT + # Per-suite wall-clock ceilings make a wedged child fail loudly. The # `incremental` suite legitimately re-indexes large fixtures (minutes), while # `daemon_runtime` measures ~610s solo on arm64 under ASan; those and @@ -337,10 +350,7 @@ echo "── 8 slowest suites ──" sort -t= -k6 -rn "$RESULTS_FILE" | head -8 grep -v ' rc=0 ' "$RESULTS_FILE" || true for f in $(grep -v ' rc=0 ' "$RESULTS_FILE" | awk '{print $1}'); do - echo "──── $f: every failure site ────" - grep -B2 -A8 "FAIL" "$LOGDIR/$f.log" | head -120 - echo "──── $f: last 15 lines ────" - tail -15 "$LOGDIR/$f.log" + suite_failure_summary "$f" "$LOGDIR/$f.log" done echo "────────────────────────────────────────────" diff --git a/scripts/suite-failure-report.sh b/scripts/suite-failure-report.sh new file mode 100755 index 0000000000..a175a76b04 --- /dev/null +++ b/scripts/suite-failure-report.sh @@ -0,0 +1,239 @@ +#!/usr/bin/env bash +# suite-failure-report.sh — what a red suite's log has to say, and which logs +# to keep. The ONE implementation behind the parallel harness's end-of-run +# failure summary (scripts/run-tests-parallel.sh sources this file), so every +# venue that reaches the harness through scripts/test.sh prints the same thing: +# hosted CI, the Linux container leg and the Windows VM leg. +# +# Why it is a file of its own: tests/test_failure_report_contract.sh drives +# these functions with fabricated suite logs. Inline in the harness they could +# only be exercised by a real red run, which is how the gap below went unseen. +# +# The gap: the summary used to grep a failing suite's log for "FAIL" and then +# show its last 15 lines. A sanitizer report contains no "FAIL", and its useful +# part (error kind, access size, top frames) is at the START of the report, +# while the last 15 lines of an AddressSanitizer abort are the shadow-byte +# legend. A Windows sanitizer job therefore went red with an empty "every +# failure site" section and a legend, and the cause had to be found by reading +# code. A trap-mode UBSan build (Windows on ARM) is worse still: it dies on an +# illegal instruction and prints nothing at all, so the only evidence in the +# log is which test was running. + +suite_failure_report_usage() { + cat <<'EOF' +Usage: scripts/suite-failure-report.sh summary + scripts/suite-failure-report.sh collect + +Internal helper of scripts/run-tests-parallel.sh (reached through +scripts/test.sh); the two modes exist so the contract test can drive the real +functions with fabricated logs. + + summary Print the failure summary of one suite log: + 1. every "FAIL" site with context (at most 120 lines); + 2. the sanitizer / crash report, only when the log holds one: + the test that was running, the first sanitizer report up to + its own SUMMARY line (at most 40 lines), every further + "runtime error:" / sanitizer header / SUMMARY line (at most + 10), and signal or timeout lines (at most 5); + 3. the last 15 lines. + collect Copy the log of every suite of that did not record + rc=0 in into /failed/, together with the + results file. Creates nothing when every suite is green. CI uploads + that directory when a test job fails. + +Exit codes: 0 success · 2 usage. +EOF +} + +# The sanitizer / crash section of the summary, header included. Prints +# NOTHING for a log that has no sanitizer report, no signal line and a +# completion summary, so an ordinary assertion failure reads exactly as it did +# before this section existed. +# +# awk rather than grep because three things have to be known together: where +# the first report starts, which test line precedes it, and where the report +# stops being useful. Portable awk only (BSD awk on macOS, mawk on Ubuntu, +# gawk under MSYS2): no interval expressions, no character classes, no gensub. +# +# The 40-line cap: a report normally ends before it, at its own SUMMARY line +# (error line, access line, the faulting stack, then what the address belongs +# to). The cap is for the report that does not end soon — a use-after-free +# carries three stacks, a recursion overflow hundreds of frames — and 40 lines +# keep the error line, the access line and the top of the faulting stack, which +# is the part that names the code. It is a third of the 120 lines the +# failure-site section may print, so one suite's whole summary stays under 200 +# lines. A SUMMARY line beyond the cut is still printed, under "further +# sanitizer lines". +suite_crash_report() { + local suite="$1" log="$2" + [ -r "$log" ] || return 0 + awk -v header="──── $suite: sanitizer / crash report ────" \ + -v block_max=40 -v other_max=10 -v signal_max=5 ' + # A test line is what RUN_TEST prints: two spaces, then the test name + # left-justified in 55 columns (" %-55s"), flushed BEFORE the test body + # runs. That flush is why the last test line ahead of a report names the + # test that was running: nothing the test itself buffers can precede it. + function test_name(s, head, rest) { + if (substr(s, 1, 2) != " ") return "" + head = substr(s, 3, 55) + if (length(head) < 55) return "" + if (head !~ /^[A-Za-z_][A-Za-z0-9_]* *$/) return "" + if (head ~ / $/) { + sub(/ +$/, "", head) + return head + } + # A name of 55 characters or more runs straight into what follows it. + rest = substr(s, 3) + match(rest, /^[A-Za-z_][A-Za-z0-9_]*/) + head = substr(rest, 1, RLENGTH) + sub(/(PASS|SKIP)$/, "", head) + return head + } + { + line = $0 + sub(/\r$/, "", line) # Windows suite logs are CRLF + if (line ~ /^ [0-9]+ passed/) has_summary = 1 + is_header = (line ~ /ERROR: (Address|Leak|Thread|Memory|UndefinedBehavior)Sanitizer/ || line ~ /WARNING: (Thread|Memory)Sanitizer/) + is_start = (is_header || line ~ /runtime error:/) + captured = 0 + + if (!started) { + name = test_name(line) + if (name != "") { + current = name + current_done = 0 + } + # The start line never finishes a test: a diagnostic appended to + # the name line is printed while that test is still running. + if (!is_start && current != "" && (line ~ /PASS$/ || line ~ /SKIP \(/ || line ~ /FAIL /)) + current_done = 1 + } + + if (is_start && !started) { + started = 1 + # A recoverable UBSan diagnostic is one line plus, at most, its + # stack; every other report runs to its own SUMMARY line. + ubsan_line = !is_header + block[++block_count] = line + captured = 1 + } else if (started && !closed) { + if (ubsan_line) { + if (line ~ /^[ \t]+#[0-9]+ / || line ~ /SUMMARY: UndefinedBehaviorSanitizer/) { + block[++block_count] = line + captured = 1 + } else { + closed = 1 + } + } else if (line ~ /^Shadow bytes around/ || line ~ /==ABORTING/) { + closed = 1 # the shadow dump and legend explain nothing + } else { + block[++block_count] = line + captured = 1 + if (line ~ /SUMMARY: [A-Za-z]*Sanitizer/) closed = 1 + } + if (!closed && block_count >= block_max) { + closed = 1 + cut = 1 + } + } + + if (!captured) { + if (is_start || line ~ /SUMMARY: [A-Za-z]*Sanitizer/) { + other_total++ + if (other_total <= other_max) other[other_total] = line + } else if (line ~ /Segmentation fault|Abort trap|killed by signal|timed out/ && line !~ /FAIL/) { + # FAIL lines are already shown by the failure-site section. + signal_total++ + if (signal_total <= signal_max) signals[signal_total] = line + } + } + } + END { + died_silently = (!started && !has_summary && current != "") + if (!started && other_total == 0 && signal_total == 0 && !died_silently) exit 0 + print header + if (started && current == "") + print "running test: none (the report precedes the first test line)" + else if (started && current_done) + print "last finished test: " current " (the report comes after it)" + else if (started) + print "running test: " current + else if (died_silently && current_done) + print "last finished test: " current " (the log ends without a completion summary)" + else if (died_silently) + print "running test: " current " (the log ends without a completion summary)" + for (i = 1; i <= block_count; i++) print block[i] + if (cut) print "[report cut at " block_max " lines; the suite log has the rest]" + if (other_total > 0) { + print "further sanitizer lines:" + for (i = 1; i <= other_total && i <= other_max; i++) print other[i] + if (other_total > other_max) print "[" (other_total - other_max) " more not shown]" + } + if (signal_total > 0) { + print "signal / timeout lines:" + for (i = 1; i <= signal_total && i <= signal_max; i++) print signals[i] + if (signal_total > signal_max) print "[" (signal_total - signal_max) " more not shown]" + } + }' "$log" +} + +# The failure summary of one suite. Sections 1 and 3 are byte-for-byte what +# the harness printed before; section 2 appears only when it has content. +suite_failure_summary() { + local suite="$1" log="$2" + echo "──── $suite: every failure site ────" + grep -B2 -A8 "FAIL" "$log" | head -120 + suite_crash_report "$suite" "$log" + echo "──── $suite: last 15 lines ────" + tail -15 "$log" + return 0 +} + +# Keep the logs a red run needs: every suite of this shard's slice that did +# not record rc=0 — failed, crashed, timed out, or still in flight when the +# scheduler itself gave up (a log but no result line). One awk decides the +# set, so a green run costs a single process and creates no directory. +collect_failed_suite_logs() { + local logdir="$1" results="$2" slice="$3" + local dest="$logdir/failed" suite kept=0 + # An existing directory only: an empty or wrong must never turn + # the rm below into a removal somewhere else. + [ -d "$logdir" ] || return 0 + rm -rf "$dest" + if [ ! -f "$results" ] || [ ! -f "$slice" ]; then + return 0 + fi + while IFS= read -r suite; do + [ -f "$logdir/$suite.log" ] || continue + mkdir -p "$dest" && cp "$logdir/$suite.log" "$dest/$suite.log" && kept=$((kept + 1)) + done < <(awk 'FILENAME == ARGV[1] { if ($2 == "rc=0") green[$1] = 1; next } + NF && !($1 in green) { print $1 }' "$results" "$slice") + if [ "$kept" -gt 0 ]; then + cp "$results" "$dest/results.txt" + echo "failing-suite logs kept in $dest ($kept suite log(s) + results.txt)" + fi + return 0 +} + +# Executed (not sourced): the contract test's entry. +if [ "${BASH_SOURCE[0]}" = "$0" ]; then + set -uo pipefail + case "${1:-}" in + -h | --help) + suite_failure_report_usage + exit 0 + ;; + summary) + [ $# -eq 3 ] || { echo "suite-failure-report: summary needs . Please consult --help." >&2; exit 2; } + suite_failure_summary "$2" "$3" + ;; + collect) + [ $# -eq 4 ] || { echo "suite-failure-report: collect needs . Please consult --help." >&2; exit 2; } + collect_failed_suite_logs "$2" "$3" "$4" + ;; + *) + echo "suite-failure-report: unknown mode '${1:-}'. Please consult --help." >&2 + exit 2 + ;; + esac +fi diff --git a/scripts/test.sh b/scripts/test.sh index cdc6d3e1d4..d352df4db5 100755 --- a/scripts/test.sh +++ b/scripts/test.sh @@ -282,6 +282,12 @@ bash "$ROOT/tests/test_smoke_fixture_contract.sh" echo "=== Step 0i: parallel suite scheduler contract ===" bash "$ROOT/tests/test_parallel_harness_contract.sh" +# Step 0i2: a red suite's summary must show the sanitizer report and the test +# that was running, not only "FAIL" lines and a shadow-byte legend. Drives the +# real summary functions with fabricated suite logs, so it runs everywhere. +echo "=== Step 0i2: suite failure-report contract ===" +bash "$ROOT/tests/test_failure_report_contract.sh" + echo "=== Step 0j: venue parity contract (one harness, every venue) ===" bash "$ROOT/tests/test_venue_parity_contract.sh" diff --git a/tests/test_failure_report_contract.sh b/tests/test_failure_report_contract.sh new file mode 100755 index 0000000000..6398f90dbd --- /dev/null +++ b/tests/test_failure_report_contract.sh @@ -0,0 +1,504 @@ +#!/usr/bin/env bash +# A red suite's summary must show WHY it is red, whatever killed it. +# +# Why: a Windows sanitizer job went red on one suite that aborted under +# AddressSanitizer, and the job log held nothing a reader could act on: +# +# ──── index_resilience: every failure site ──── +# ──── index_resilience: last 15 lines ──── +# (the AddressSanitizer shadow-byte legend) +# ==6636==ABORTING +# +# The summary grepped the suite log for "FAIL" only, and a sanitizer report +# never contains that word. Its useful part (error kind, access size, top +# frames) is at the START of the report, far above the last 15 lines. With no +# log artifact either, the cause had to be found by reading code a day later. +# +# This drives the REAL functions (scripts/suite-failure-report.sh, which the +# parallel harness sources) with fabricated suite logs written the way +# tests/test_framework.h writes them, so the contract cannot drift from the +# code it pins. No build, no network, no waiting: every case is a file in and +# text out. +# +# Usage: tests/test_failure_report_contract.sh [repo-root] (root override so +# the contract can be shown to FAIL against a tree without the change) + +set -uo pipefail + +ROOT="${1:-$(cd "$(dirname "$0")/.." && pwd)}" +HELPER="$ROOT/scripts/suite-failure-report.sh" +DRIVER="$ROOT/scripts/run-tests-parallel.sh" +SCHEDULER="$ROOT/scripts/run-test-wave.py" + +for required in "$HELPER" "$DRIVER" "$SCHEDULER"; do + if [ ! -f "$required" ]; then + echo "FAIL: $required not found" >&2 + exit 1 + fi +done + +WORK=$(mktemp -d "${TMPDIR:-/tmp}/cbm-failure-report.XXXXXX") || exit 1 +trap 'rm -rf "$WORK"' EXIT + +failures=0 +cases=0 +fail() { + echo "FAIL: $*" >&2 + failures=$((failures + 1)) +} +# Substring tests stay in the shell: piping into `grep -q` under pipefail can +# hand the writer EPIPE and report a satisfied match as status 141. +expect_has() { # description text needle + cases=$((cases + 1)) + case "$2" in + *"$3"*) ;; + *) fail "$1 — the summary lacks: $3" ;; + esac +} +expect_lacks() { # description text needle + cases=$((cases + 1)) + case "$2" in + *"$3"*) fail "$1 — the summary must not contain: $3" ;; + esac +} +expect_same() { # description actual expected + cases=$((cases + 1)) + if [ "$2" != "$3" ]; then + fail "$1 — output differs from the recorded one" + printf '%s\n' "$3" > "$WORK/expected.txt" + printf '%s\n' "$2" > "$WORK/actual.txt" + diff "$WORK/expected.txt" "$WORK/actual.txt" >&2 || true + fi +} + +summary_of() { # suite log-name + bash "$HELPER" summary "$1" "$WORK/$2" 2>&1 +} +# Only the sanitizer / crash section of a summary. +report_section() { + printf '%s\n' "$1" | awk ' + /: sanitizer \/ crash report / { on = 1; next } + /: last 15 lines / { on = 0 } + on' +} + +# The framework's own line shapes (tests/test_framework.h): RUN_TEST prints +# " %-55s" and flushes BEFORE the test body, then "PASS\n" after it. +running() { printf ' %-55s' "$1"; } +passed() { printf ' %-55sPASS\n' "$1"; } +banner() { printf '\n codebase-memory-mcp C test suite\n\n=== %s ===\n' "$1"; } +RULE="────────────────────────────────────────────" +totals() { printf '\n%s\n %s\n%s\n\n' "$RULE" "$1" "$RULE"; } + +# ── 1. AddressSanitizer abort: the incident ────────────────────────────────── +# The report starts on the running test's own line (the name was flushed with +# no newline) and ends in the shadow dump, the legend and ABORTING. +{ + banner index_resilience + passed resilience_reopens_after_clean_shutdown + passed resilience_recovers_truncated_journal + running resilience_rejects_oversized_header + cat <<'EOF' +================================================================= +==123==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x00a1b2c3d4e6 at pc 0x7ff6a1b2c3d4 bp 0x00a1b2c3d400 sp 0x00a1b2c3d3f8 +WRITE of size 22 at 0x00a1b2c3d4e6 thread T0 + #0 0x7ff6a1b2c3d3 in __asan_memcpy (test-runner+0x1402c3d3) + #1 0x7ff6a1b2d111 in fixture_copy_header src/fixture_header.c:88 + #2 0x7ff6a1b2e222 in test_resilience_rejects_oversized_header tests/test_fixture.c:141 + +Address 0x00a1b2c3d4e6 is located in stack of thread T0 at offset 54 in frame + #0 0x7ff6a1b2d000 in fixture_copy_header src/fixture_header.c:61 + + This frame has 1 object(s): + [32, 54) 'magic' (line 63) <== Memory access at offset 54 overflows this variable +HINT: this may be a false positive if your program uses some custom stack unwind mechanism, swapcontext or vfork +SUMMARY: AddressSanitizer: stack-buffer-overflow src/fixture_header.c:88 in fixture_copy_header +Shadow bytes around the buggy address: + 0x00a1b2c3d200: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 + 0x00a1b2c3d280: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 +=>0x00a1b2c3d480: f1 f1 f1 f1 00 00[06]f3 f3 f3 f3 f3 00 00 00 00 + 0x00a1b2c3d500: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 +Shadow byte legend (one shadow byte represents 8 application bytes): + Addressable: 00 + Partially addressable: 01 02 03 04 05 06 07 + Heap left redzone: fa + Freed heap region: fd + Stack left redzone: f1 + Stack mid redzone: f2 + Stack right redzone: f3 + Stack after return: f5 + Stack use after scope: f8 + Global redzone: f9 + Global init order: f6 + Poisoned by user: f7 + Container overflow: fc + Array cookie: ac + Intra object redzone: bb + ASan internal: fe + Left alloca redzone: ca + Right alloca redzone: cb +==123==ABORTING +EOF +} > "$WORK/asan_abort.log" + +out=$(summary_of index_resilience asan_abort.log) +section=$(report_section "$out") +expect_has "ASan abort: the error line" "$section" \ + "==123==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x00a1b2c3d4e6" +expect_has "ASan abort: the access line" "$section" "WRITE of size 22 at 0x00a1b2c3d4e6 thread T0" +expect_has "ASan abort: frame #0" "$section" "#0 0x7ff6a1b2c3d3 in __asan_memcpy" +expect_has "ASan abort: frame #1" "$section" "#1 0x7ff6a1b2d111 in fixture_copy_header src/fixture_header.c:88" +expect_has "ASan abort: frame #2" "$section" \ + "#2 0x7ff6a1b2e222 in test_resilience_rejects_oversized_header tests/test_fixture.c:141" +expect_has "ASan abort: the report's own summary line" "$section" \ + "SUMMARY: AddressSanitizer: stack-buffer-overflow src/fixture_header.c:88 in fixture_copy_header" +expect_has "ASan abort: the running test is named" "$section" \ + "running test: resilience_rejects_oversized_header" +expect_lacks "ASan abort: a finished test is not blamed" "$section" "resilience_recovers_truncated_journal" +expect_lacks "ASan abort: the shadow dump stays out of the report" "$section" "Shadow byte" +# The legend lines are two-space-indented words, the shape a short test line +# would have; none of them may be taken for a test. +expect_lacks "ASan abort: a legend line is not a test" "$section" "running test: Addressable" +expect_has "ASan abort: the older sections are still there" "$out" \ + "──── index_resilience: every failure site ────" +expect_has "ASan abort: the tail is still there" "$out" "──── index_resilience: last 15 lines ────" +expect_has "ASan abort: the tail still ends the log" "$out" "==123==ABORTING" + +# The same log as a Windows CRT writes it: CRLF line endings. +awk '{ printf "%s\r\n", $0 }' "$WORK/asan_abort.log" > "$WORK/asan_abort_crlf.log" +section=$(report_section "$(summary_of index_resilience asan_abort_crlf.log)") +expect_has "ASan abort (CRLF): the error line" "$section" "==123==ERROR: AddressSanitizer: stack-buffer-overflow" +expect_has "ASan abort (CRLF): frame #2" "$section" "#2 0x7ff6a1b2e222 in test_resilience_rejects_oversized_header" +expect_has "ASan abort (CRLF): the running test is named" "$section" \ + "running test: resilience_rejects_oversized_header" +expect_lacks "ASan abort (CRLF): the shadow dump stays out" "$section" "Shadow byte" + +# ── 2. UBSan diagnostic in a suite that otherwise passes ───────────────────── +# Recoverable UBSan prints one line to stderr and the test carries on, so its +# PASS lands on the next line. Nothing in the log says FAIL. +{ + banner arith + passed arith_adds_small_values + running arith_scales_offsets + printf "src/fixture_math.c:42:17: runtime error: signed integer overflow: 2147483647 + 1 cannot be represented in type 'int'\n" + printf 'PASS\n' + passed arith_clamps_ranges + totals "3 passed" +} > "$WORK/ubsan_recoverable.log" + +out=$(summary_of arith ubsan_recoverable.log) +section=$(report_section "$out") +expect_has "UBSan: the runtime error line" "$section" \ + "src/fixture_math.c:42:17: runtime error: signed integer overflow: 2147483647 + 1" +expect_has "UBSan: the running test is named" "$section" "running test: arith_scales_offsets" +expect_lacks "UBSan: the report does not swallow the tests after it" "$section" "arith_clamps_ranges" +expect_has "UBSan: the tail is still there" "$out" "──── arith: last 15 lines ────" + +# ── 3. Plain assertion failure: byte-for-byte what the harness printed before ─ +# Recorded from the harness at 96c3f41c (grep -B2 -A8 "FAIL" | head -120, then +# tail -15), written out here line by line rather than recomputed, so a change +# to either section shows up as a difference. +{ + banner plain_fail + for i in 01 02 03 04 05 06 07 08 09 10 11 12; do passed "parses_case_$i"; done + running parses_nested_blocks + printf ' FAIL tests/x.c:12: ASSERT(depth == 3)\n' + for i in 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30; do passed "parses_case_$i"; done + totals "30 passed, 1 failed" +} > "$WORK/plain_fail.log" + +expected=$( + echo "──── plain_fail: every failure site ────" + passed parses_case_11 + passed parses_case_12 + running parses_nested_blocks + printf ' FAIL tests/x.c:12: ASSERT(depth == 3)\n' + for i in 13 14 15 16 17 18 19 20; do passed "parses_case_$i"; done + echo "──── plain_fail: last 15 lines ────" + for i in 21 22 23 24 25 26 27 28 29 30; do passed "parses_case_$i"; done + totals "30 passed, 1 failed" +) +expect_same "plain FAIL: unchanged output" "$(summary_of plain_fail plain_fail.log)" "$expected" + +# ── 4. Neither a FAIL nor a report: the tail still appears, nothing is added ── +{ + banner quiet_exit + for i in 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20; do passed "holds_case_$i"; done + totals "20 passed" +} > "$WORK/quiet_exit.log" + +expected=$( + echo "──── quiet_exit: every failure site ────" + echo "──── quiet_exit: last 15 lines ────" + for i in 11 12 13 14 15 16 17 18 19 20; do passed "holds_case_$i"; done + totals "20 passed" +) +expect_same "no FAIL, no report: unchanged output" "$(summary_of quiet_exit quiet_exit.log)" "$expected" + +# ── 5. Silent death: no report, no FAIL, no completion summary ─────────────── +# Trap-mode UBSan (Windows on ARM) dies on an illegal instruction and prints +# nothing. The running test is then the ONLY evidence the log holds. +{ + banner shift_width + passed widens_before_shift + running shifts_within_width +} > "$WORK/silent_death.log" + +out=$(summary_of shift_width silent_death.log) +expect_has "silent death: the running test is named" "$out" \ + "running test: shifts_within_width (the log ends without a completion summary)" +expect_has "silent death: the tail is still there" "$out" "──── shift_width: last 15 lines ────" + +# ── 6. A report AFTER the last test finished: nothing is blamed as running ─── +{ + banner leaky + passed allocates_and_releases + passed keeps_one_buffer + totals "2 passed" + cat <<'EOF' +================================================================= +==77==ERROR: LeakSanitizer: detected memory leaks + +Direct leak of 64 byte(s) in 1 object(s) allocated from: + #0 0x5581aa in malloc (test-runner+0x5581aa) + #1 0x5592bb in fixture_keep_buffer src/fixture_buffer.c:19 + +SUMMARY: AddressSanitizer: 64 byte(s) leaked in 1 allocation(s). +EOF +} > "$WORK/lsan_at_exit.log" + +section=$(report_section "$(summary_of leaky lsan_at_exit.log)") +expect_has "leak at exit: the error line" "$section" "==77==ERROR: LeakSanitizer: detected memory leaks" +expect_has "leak at exit: the allocation frame" "$section" "#1 0x5592bb in fixture_keep_buffer src/fixture_buffer.c:19" +expect_has "leak at exit: the summary line" "$section" "SUMMARY: AddressSanitizer: 64 byte(s) leaked" +expect_has "leak at exit: the last test is reported as finished" "$section" \ + "last finished test: keeps_one_buffer (the report comes after it)" +expect_lacks "leak at exit: no test is blamed as running" "$section" "running test:" + +# ── 7. ThreadSanitizer and MemorySanitizer open with WARNING, not ERROR ────── +{ + banner racy + running counter_is_shared_safely + cat <<'EOF' +================== +WARNING: ThreadSanitizer: data race (pid=4242) + Write of size 4 at 0x7b0400000000 by thread T1: + #0 fixture_bump src/fixture_counter.c:9 (test-runner+0x4a1b2c) + + Previous read of size 4 at 0x7b0400000000 by main thread: + #0 fixture_read src/fixture_counter.c:14 (test-runner+0x4a1c3d) + +SUMMARY: ThreadSanitizer: data race src/fixture_counter.c:9 in fixture_bump +================== +EOF +} > "$WORK/tsan_race.log" +section=$(report_section "$(summary_of racy tsan_race.log)") +expect_has "TSan: the warning line" "$section" "WARNING: ThreadSanitizer: data race (pid=4242)" +expect_has "TSan: the second stack" "$section" "#0 fixture_read src/fixture_counter.c:14" +expect_has "TSan: the running test is named" "$section" "running test: counter_is_shared_safely" + +{ + banner uninit + running reads_only_initialized_fields + cat <<'EOF' +==55==WARNING: MemorySanitizer: use-of-uninitialized-value + #0 0x4c1d2e in fixture_sum src/fixture_sum.c:27:9 + +SUMMARY: MemorySanitizer: use-of-uninitialized-value src/fixture_sum.c:27:9 in fixture_sum +Exiting +EOF +} > "$WORK/msan_uninit.log" +section=$(report_section "$(summary_of uninit msan_uninit.log)") +expect_has "MSan: the warning line" "$section" "==55==WARNING: MemorySanitizer: use-of-uninitialized-value" +expect_has "MSan: the frame" "$section" "#0 0x4c1d2e in fixture_sum src/fixture_sum.c:27:9" +expect_lacks "MSan: the report stops at its summary line" "$section" "Exiting" + +# ── 8. A very deep stack is capped, and its summary line survives the cap ──── +{ + banner deep + running recurses_without_bound + printf '=================================================================\n' + printf '==9==ERROR: AddressSanitizer: stack-overflow on address 0x7ffc00000000\n' + i=0 + while [ "$i" -lt 100 ]; do + printf ' #%d 0x55aa00 in fixture_recurse src/fixture_recurse.c:7\n' "$i" + i=$((i + 1)) + done + printf '\nSUMMARY: AddressSanitizer: stack-overflow src/fixture_recurse.c:7 in fixture_recurse\n' + printf '==9==ABORTING\n' +} > "$WORK/deep_stack.log" +section=$(report_section "$(summary_of deep deep_stack.log)") +expect_has "deep stack: the top frame" "$section" "#0 0x55aa00 in fixture_recurse" +expect_lacks "deep stack: frame 60 is past the cap" "$section" "#60 0x55aa00" +expect_has "deep stack: the cut is announced" "$section" "[report cut at 40 lines; the suite log has the rest]" +expect_has "deep stack: the summary line survives" "$section" \ + "SUMMARY: AddressSanitizer: stack-overflow src/fixture_recurse.c:7 in fixture_recurse" +cases=$((cases + 1)) +section_lines=$(printf '%s\n' "$section" | wc -l | tr -d ' ') +if [ "$section_lines" -gt 60 ]; then + fail "deep stack: the report section is not bounded ($section_lines lines)" +fi + +# ── 9. Signal and timeout lines a suite's own output may carry ─────────────── +{ + banner spawns + running child_is_reaped + printf 'child 4711 killed by signal 11\n' + printf 'Segmentation fault: 11\n' +} > "$WORK/signal_lines.log" +section=$(report_section "$(summary_of spawns signal_lines.log)") +expect_has "signals: killed by signal" "$section" "child 4711 killed by signal 11" +expect_has "signals: segmentation fault" "$section" "Segmentation fault: 11" +expect_has "signals: the running test is named" "$section" "running test: child_is_reaped" + +# ── 10. Which logs a red run keeps for upload ──────────────────────────────── +# Kept: every suite of the slice that did not record rc=0, including one that +# was still in flight (a log but no result line). Not kept: green suites. +mkdir "$WORK/logs" +for suite in green_one red_assert red_abort in_flight never_started; do + echo "$suite" >> "$WORK/logs/suites-shard.txt" +done +for suite in green_one red_assert red_abort in_flight; do + echo "log of $suite" > "$WORK/logs/$suite.log" +done +{ + echo "green_one rc=0 pass=10 fail=0 skip=0 secs=1" + echo "red_assert rc=1 pass=9 fail=1 skip=0 secs=1" + echo "red_abort rc=-6 pass=4 fail=0 skip=0 secs=2" +} > "$WORK/logs/results.txt" +bash "$HELPER" collect "$WORK/logs" "$WORK/logs/results.txt" "$WORK/logs/suites-shard.txt" >/dev/null 2>&1 +kept="" +for path in "$WORK/logs/failed"/*; do + [ -e "$path" ] && kept="$kept${path##*/} " +done +cases=$((cases + 1)) +for wanted in in_flight.log red_abort.log red_assert.log results.txt; do + case " $kept" in + *" $wanted "*) ;; + *) fail "collect: $wanted was not kept (kept: $kept)" ;; + esac +done +for unwanted in green_one.log never_started.log; do + case " $kept" in + *" $unwanted "*) fail "collect: $unwanted must not be kept (kept: $kept)" ;; + esac +done +cases=$((cases + 1)) +if [ "$(cat "$WORK/logs/failed/red_abort.log" 2>/dev/null)" != "log of red_abort" ]; then + fail "collect: a kept log is not a copy of the suite log" +fi + +mkdir "$WORK/green" +echo "green_one" > "$WORK/green/suites-shard.txt" +echo "log of green_one" > "$WORK/green/green_one.log" +echo "green_one rc=0 pass=10 fail=0 skip=0 secs=1" > "$WORK/green/results.txt" +bash "$HELPER" collect "$WORK/green" "$WORK/green/results.txt" "$WORK/green/suites-shard.txt" >/dev/null 2>&1 +cases=$((cases + 1)) +if [ -e "$WORK/green/failed" ]; then + fail "collect: a green run must not create a failed/ directory" +fi + +# ── 11. The scheduler's result line for a suite that died mid-run ──────────── +# No completion summary is ever printed by an aborted suite, and the result +# line used to say pass=0 about a suite that had finished tests. The fixture +# exits on its own; the timeouts below are ceilings it never approaches. +cat > "$WORK/fake_runner.py" <<'PY' +import os +import sys + +suite = sys.argv[-1] +if suite == "prints_nothing": + os._exit(0) +sys.stdout.write("\n=== %s ===\n" % suite) +sys.stdout.write(" %-55sPASS\n" % "first_finishes") +if suite == "ends_with_summary": + # One PASS marker in the log, but the suite's own summary says otherwise: + # the summary is the count, the markers are never consulted. + sys.stdout.write("\n 5 passed, 1 failed, 2 skipped\n\n") + sys.stdout.flush() + os._exit(1) +sys.stdout.write(" %-55s" % "second_logs_then_finishes") +sys.stdout.flush() +sys.stderr.write("level=info msg=working\n") +sys.stderr.flush() +sys.stdout.write("PASS\n") +sys.stdout.write(" %-55s" % "third_never_returns") +sys.stdout.flush() +os._exit(3) +PY +printf 'dies_mid_suite\nends_with_summary\nprints_nothing\n' > "$WORK/wave-suites.txt" +: > "$WORK/wave-results.txt" +python3 "$SCHEDULER" \ + --suite-file "$WORK/wave-suites.txt" \ + --log-dir "$WORK/wave-logs" \ + --results-file "$WORK/wave-results.txt" \ + --jobs 1 \ + --timeout 60 \ + --slow-timeout 60 \ + --kill-grace 1 \ + "$(command -v python3)" "$WORK/fake_runner.py" >/dev/null 2>"$WORK/wave-stderr.txt" +wave_rc=$? +result_lines=$(cat "$WORK/wave-results.txt") +cases=$((cases + 1)) +case "$result_lines" in +"dies_mid_suite rc=3 pass=2 fail=0 skip=0 secs="*) ;; +*) + fail "scheduler: a suite that died after two finished tests reported '$result_lines' (wave rc=$wave_rc)" + cat "$WORK/wave-stderr.txt" >&2 + ;; +esac +expect_has "scheduler: a suite with a summary line is never recounted" "$result_lines" \ + "ends_with_summary rc=1 pass=5 fail=1 skip=2 secs=" +expect_has "scheduler: a suite that ran nothing still counts nothing" "$result_lines" \ + "prints_nothing rc=97 pass=0 fail=0 skip=0 secs=" +# ...and the log the scheduler wrote names the test that never returned. +cp "$WORK/wave-logs/dies_mid_suite.log" "$WORK/dies_mid_suite.log" 2>/dev/null +expect_has "scheduler log: the running test is named" "$(summary_of dies_mid_suite dies_mid_suite.log)" \ + "running test: third_never_returns (the log ends without a completion summary)" + +# ── 12. One implementation: the harness uses these functions, not a copy ───── +driver_text=$(cat "$DRIVER") +expect_has "harness: sources the shared file" "$driver_text" \ + "source \"\$SCRIPT_DIR/suite-failure-report.sh\"" +expect_has "harness: prints the summary through the shared function" "$driver_text" \ + "suite_failure_summary \"\$f\"" +expect_has "harness: keeps failing logs through the shared function" "$driver_text" \ + "collect_failed_suite_logs \"\$LOGDIR\"" +expect_lacks "harness: no second copy of the summary" "$driver_text" "every failure site" +expect_has "harness: keeps the logs on every way out" "$driver_text" \ + "trap 'collect_failed_suite_logs \"\$LOGDIR\" \"\$RESULTS_FILE\" \"\$SHARD_EXPECT\"' EXIT" + +# ── 13. As the harness uses them: sourced, its shell options, an EXIT trap ─── +# The trap must never change the status the harness ends with: a trap that +# turned exit 1 into exit 0 would report a red run as green. +cat > "$WORK/as_harness.sh" <<'EOF' +set -uo pipefail +source "$1" +LOGDIR="$2" +RESULTS_FILE="$LOGDIR/results.txt" +SHARD_EXPECT="$LOGDIR/suites-shard.txt" +trap 'collect_failed_suite_logs "$LOGDIR" "$RESULTS_FILE" "$SHARD_EXPECT"' EXIT +suite_failure_summary red_assert "$LOGDIR/red_assert.log" +exit "$3" +EOF +for status in 7 1 0; do + rm -rf "$WORK/logs/failed" + bash "$WORK/as_harness.sh" "$HELPER" "$WORK/logs" "$status" > "$WORK/as_harness.out" 2>&1 + got=$? + cases=$((cases + 1)) + if [ "$got" -ne "$status" ]; then + fail "EXIT trap: the harness status $status came back as $got" + fi + cases=$((cases + 1)) + if [ ! -f "$WORK/logs/failed/red_abort.log" ]; then + fail "EXIT trap: the failing logs were not kept on exit $status" + fi +done +expect_has "sourced: the summary prints as it does when executed" "$(cat "$WORK/as_harness.out")" \ + "──── red_assert: every failure site ────" + +if [ "$failures" -gt 0 ]; then + echo "suite failure-report contract VIOLATED: $failures of $cases check(s)" >&2 + exit 1 +fi +echo "suite failure-report contract passed ($cases checks: sanitizer reports, running test, unchanged FAIL output, kept logs, result line, exit status)"