From 53fbce08fb7d7874acc43b686bc01a5eeaa3a100 Mon Sep 17 00:00:00 2001
From: Jeroen Schweitzer <jpmschweitzer@gmail.com>
Date: Tue, 21 Apr 2026 12:02:25 +0200
Subject: [PATCH] chore(tests): hard 300s timeout + on-disk log + context-safe
 output
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Makes tests/run-godot self-containing so neither humans nor LLM callers
have to remember to wrap it in a timeout or pipe it into a file. A hung
test now kills cleanly at 300s with a clear TEST_TIMEOUT marker and
bisection hint instead of silently burning an hour of wall clock (as
Sprint 36 learned).

- Godot+gdUnit4 output goes to /tmp/sr-run-godot.log (overwritten each
  run). Nothing streams to stdout/stderr — 20k+ lines of test log into
  a terminal or an LLM context is unworkable.
- Stdout: one-line JSON summary, with a "log" field pointing at the
  file. On timeout adds "timeout":true and "timeout_sec":300.
- Stderr: a short hint block. On pass: one line. On failure: three
  commands to inspect the log. On timeout: a bisection recipe.
- Single well-known path instead of an env var — worktrees each want
  their own value and the indirection makes the hint lines meaningless.
  Concurrent runs are the caller's problem.
- timeout(1) --foreground --kill-after=10 to escalate to SIGKILL if
  Godot ignores SIGTERM.
---
 tests/run-godot | 100 +++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 77 insertions(+), 23 deletions(-)

diff --git a/tests/run-godot b/tests/run-godot
index ee323e275..e09b91b26 100755
--- a/tests/run-godot
+++ b/tests/run-godot
@@ -1,11 +1,32 @@
 #!/usr/bin/env bash
 # tests/run-godot: Run Godot client test suite via gdUnit4 (D-030)
-# Exit: 0 = all pass, non-zero = failure
-# Stdout: {"suite":"godot","total":N,"passed":N,"failed":N,"duration_ms":N}
 #
-# --filter: accepts a test filename stem (e.g. "test_protocol" → runs test_protocol.gd only)
+# Exit: 0 = all pass, non-zero = failure.
+# Stdout: JSON summary on ONE line, plus a pointer to the full log.
+#   {"suite":"godot","total":N,"passed":N,"failed":N,"duration_ms":N,"log":"/tmp/sr-run-godot.log"}
+#   (on timeout: same JSON + "timeout":true, "timeout_sec":N; exit code 124)
+# Stderr: a short hint line pointing at the log. The Godot/gdUnit4 output
+#   does NOT stream to stdout or stderr — it is captured to the log file.
+#   This is intentional: streaming 20k+ lines of test log into an LLM
+#   caller's context is unworkable. Inspect the log with the commands the
+#   hint line suggests.
+#
+# --filter <stem|filename|res-path>: narrow the test run to a single file.
 set -euo pipefail
 
+# Hard wall-clock cap. Sprint 36 lost an hour to a hung test suite that
+# silently consumed CPU forever. 300s is generous for the full suite
+# (which currently runs in ~60s) and well above the slowest single suite
+# (~40s for the compositor build). If you need longer for an unusual
+# workload (fixture regen, etc.), prefer adding a dedicated script over
+# extending this cap — the cap is the point.
+TIMEOUT_SEC=300
+
+# Single well-known log path. Overwritten each run. No env var — worktrees
+# would each want their own value and the indirection makes the hint
+# line meaningless. Multiple concurrent runs are the caller's problem.
+LOG_FILE="/tmp/sr-run-godot.log"
+
 FILTER=""
 while [[ $# -gt 0 ]]; do
     case "$1" in
@@ -38,32 +59,33 @@ else
 fi
 
 START_MS=$(date +%s%3N)
-TMPOUT=$(mktemp)
 
+# Redirect Godot+gdUnit4 output to the log file. Nothing streams to the
+# caller — the summary JSON (stdout) and the hint line (stderr) are the
+# only things the caller ever sees. See header comment for rationale.
 set +e
-"$GODOT" --headless --path "$REPO_ROOT/client" \
-    -s res://addons/gdUnit4/bin/GdUnitCmdTool.gd \
-    --ignoreHeadlessMode \
-    -c \
-    -a "$TEST_TARGET" \
-    2>&1 | tee "$TMPOUT" >&2
-EXIT_CODE=${PIPESTATUS[0]}
+timeout --foreground --kill-after=10 "$TIMEOUT_SEC" \
+    "$GODOT" --headless --path "$REPO_ROOT/client" \
+        -s res://addons/gdUnit4/bin/GdUnitCmdTool.gd \
+        --ignoreHeadlessMode \
+        -c \
+        -a "$TEST_TARGET" \
+    > "$LOG_FILE" 2>&1
+EXIT_CODE=$?
 set -e
 
 END_MS=$(date +%s%3N)
 DURATION_MS=$((END_MS - START_MS))
 
-_extract_num() {
-    local haystack="$1" pattern="$2"
-    echo "$haystack" | grep -oiE "[0-9]+ $pattern" | grep -oE '^[0-9]+' || echo 0
-}
+# timeout(1) exit code 124 = wall clock exceeded; 137 = needed SIGKILL.
+TIMED_OUT=false
+if [[ "$EXIT_CODE" -eq 124 || "$EXIT_CODE" -eq 137 ]]; then
+    TIMED_OUT=true
+fi
 
 # gdUnit4 outputs per-suite statistics: "N test cases | X errors | Y failures | ..."
-# and a summary: "Executed test cases : (X/N)" or "Executed test cases : (X/N), Z skipped"
 TOTAL=0; PASSED=0; FAILED=0
-
-# Sum errors + failures across all suite statistics lines
-STATS_LINES=$(grep -oE "[0-9]+ test cases \| [0-9]+ errors \| [0-9]+ failures" "$TMPOUT" || true)
+STATS_LINES=$(grep -oE "[0-9]+ test cases \| [0-9]+ errors \| [0-9]+ failures" "$LOG_FILE" || true)
 if [[ -n "$STATS_LINES" ]]; then
     TOTAL=$(echo "$STATS_LINES" | grep -oE '^[0-9]+' | awk '{s+=$1} END {print s}')
     ERRORS=$(echo "$STATS_LINES" | grep -oE '[0-9]+ errors' | grep -oE '^[0-9]+' | awk '{s+=$1} END {print s}')
@@ -74,7 +96,7 @@ fi
 
 # Fallback: parse "Executed test cases : (X/N)" for total if stats parse failed
 if [[ "$TOTAL" -eq 0 ]]; then
-    EXEC_LINE=$(grep -oE "Executed test cases : \([0-9]+/[0-9]+\)" "$TMPOUT" | tail -1 || true)
+    EXEC_LINE=$(grep -oE "Executed test cases : \([0-9]+/[0-9]+\)" "$LOG_FILE" | tail -1 || true)
     if [[ -n "$EXEC_LINE" ]]; then
         TOTAL=$(echo "$EXEC_LINE" | grep -oE '/[0-9]+\)' | grep -oE '[0-9]+')
         PASSED=$(echo "$EXEC_LINE" | grep -oE '\([0-9]+/' | grep -oE '[0-9]+')
@@ -82,7 +104,39 @@ if [[ "$TOTAL" -eq 0 ]]; then
     fi
 fi
 
-rm -f "$TMPOUT"
-printf '{"suite":"godot","total":%d,"passed":%d,"failed":%d,"duration_ms":%d}\n' \
-    "${TOTAL:-0}" "${PASSED:-0}" "${FAILED:-0}" "$DURATION_MS"
+LOG_LINES=$(wc -l < "$LOG_FILE" 2>/dev/null || echo 0)
+
+# Single-line JSON summary on stdout — machine-parseable, small.
+if [[ "$TIMED_OUT" == "true" ]]; then
+    printf '{"suite":"godot","total":%d,"passed":%d,"failed":%d,"duration_ms":%d,"timeout":true,"timeout_sec":%d,"log":"%s"}\n' \
+        "${TOTAL:-0}" "${PASSED:-0}" "${FAILED:-0}" "$DURATION_MS" "$TIMEOUT_SEC" "$LOG_FILE"
+else
+    printf '{"suite":"godot","total":%d,"passed":%d,"failed":%d,"duration_ms":%d,"log":"%s"}\n' \
+        "${TOTAL:-0}" "${PASSED:-0}" "${FAILED:-0}" "$DURATION_MS" "$LOG_FILE"
+fi
+
+# Hint line on stderr. Stays short. LLM callers: read this literally.
+if [[ "$TIMED_OUT" == "true" ]]; then
+    cat >&2 <<EOF
+TEST_TIMEOUT: tests/run-godot exceeded ${TIMEOUT_SEC}s wall-clock cap (killed=${EXIT_CODE}).
+  filter=${FILTER:-<none>}  target=${TEST_TARGET}  log=${LOG_FILE} (${LOG_LINES} lines)
+  This is NOT a regular test failure — the process was force-terminated.
+  A hung test almost always means a cleanup hook froze (e.g. after_test
+  freeing GdUnit4 infrastructure) or an assertion waits on a signal that
+  never fires. Bisect:
+    grep -E 'STARTED|PASSED|FAILED' ${LOG_FILE} | tail -20
+  The last STARTED without a matching PASSED/FAILED is the hang site.
+EOF
+elif [[ "${FAILED:-0}" -gt 0 ]]; then
+    cat >&2 <<EOF
+Tests finished with failures. log=${LOG_FILE} (${LOG_LINES} lines)
+  Summarize failures per suite:
+    sed 's/\x1b\[[0-9;]*m//g' ${LOG_FILE} | grep -E 'FAILED [0-9]+ms\$' | awk -F'>' '{print \$1}' | sort | uniq -c | sort -rn
+  First failure block with context:
+    sed 's/\x1b\[[0-9;]*m//g' ${LOG_FILE} | grep -n 'FAILED\|Expecting\|Godot Runtime Error' | head -40
+EOF
+else
+    echo "Tests passed. log=${LOG_FILE} (${LOG_LINES} lines)" >&2
+fi
+
 exit $EXIT_CODE