chore(tests): hard 300s timeout + on-disk log + context-safe output
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.
This commit is contained in:
+77
-23
@@ -1,11 +1,32 @@
|
|||||||
#!/usr/bin/env bash
|
#!/usr/bin/env bash
|
||||||
# tests/run-godot: Run Godot client test suite via gdUnit4 (D-030)
|
# 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
|
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=""
|
FILTER=""
|
||||||
while [[ $# -gt 0 ]]; do
|
while [[ $# -gt 0 ]]; do
|
||||||
case "$1" in
|
case "$1" in
|
||||||
@@ -38,32 +59,33 @@ else
|
|||||||
fi
|
fi
|
||||||
|
|
||||||
START_MS=$(date +%s%3N)
|
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
|
set +e
|
||||||
"$GODOT" --headless --path "$REPO_ROOT/client" \
|
timeout --foreground --kill-after=10 "$TIMEOUT_SEC" \
|
||||||
-s res://addons/gdUnit4/bin/GdUnitCmdTool.gd \
|
"$GODOT" --headless --path "$REPO_ROOT/client" \
|
||||||
--ignoreHeadlessMode \
|
-s res://addons/gdUnit4/bin/GdUnitCmdTool.gd \
|
||||||
-c \
|
--ignoreHeadlessMode \
|
||||||
-a "$TEST_TARGET" \
|
-c \
|
||||||
2>&1 | tee "$TMPOUT" >&2
|
-a "$TEST_TARGET" \
|
||||||
EXIT_CODE=${PIPESTATUS[0]}
|
> "$LOG_FILE" 2>&1
|
||||||
|
EXIT_CODE=$?
|
||||||
set -e
|
set -e
|
||||||
|
|
||||||
END_MS=$(date +%s%3N)
|
END_MS=$(date +%s%3N)
|
||||||
DURATION_MS=$((END_MS - START_MS))
|
DURATION_MS=$((END_MS - START_MS))
|
||||||
|
|
||||||
_extract_num() {
|
# timeout(1) exit code 124 = wall clock exceeded; 137 = needed SIGKILL.
|
||||||
local haystack="$1" pattern="$2"
|
TIMED_OUT=false
|
||||||
echo "$haystack" | grep -oiE "[0-9]+ $pattern" | grep -oE '^[0-9]+' || echo 0
|
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 | ..."
|
# 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
|
TOTAL=0; PASSED=0; FAILED=0
|
||||||
|
STATS_LINES=$(grep -oE "[0-9]+ test cases \| [0-9]+ errors \| [0-9]+ failures" "$LOG_FILE" || true)
|
||||||
# Sum errors + failures across all suite statistics lines
|
|
||||||
STATS_LINES=$(grep -oE "[0-9]+ test cases \| [0-9]+ errors \| [0-9]+ failures" "$TMPOUT" || true)
|
|
||||||
if [[ -n "$STATS_LINES" ]]; then
|
if [[ -n "$STATS_LINES" ]]; then
|
||||||
TOTAL=$(echo "$STATS_LINES" | grep -oE '^[0-9]+' | awk '{s+=$1} END {print s}')
|
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}')
|
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
|
# Fallback: parse "Executed test cases : (X/N)" for total if stats parse failed
|
||||||
if [[ "$TOTAL" -eq 0 ]]; then
|
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
|
if [[ -n "$EXEC_LINE" ]]; then
|
||||||
TOTAL=$(echo "$EXEC_LINE" | grep -oE '/[0-9]+\)' | grep -oE '[0-9]+')
|
TOTAL=$(echo "$EXEC_LINE" | grep -oE '/[0-9]+\)' | grep -oE '[0-9]+')
|
||||||
PASSED=$(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
|
||||||
fi
|
fi
|
||||||
|
|
||||||
rm -f "$TMPOUT"
|
LOG_LINES=$(wc -l < "$LOG_FILE" 2>/dev/null || echo 0)
|
||||||
printf '{"suite":"godot","total":%d,"passed":%d,"failed":%d,"duration_ms":%d}\n' \
|
|
||||||
"${TOTAL:-0}" "${PASSED:-0}" "${FAILED:-0}" "$DURATION_MS"
|
# 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
|
exit $EXIT_CODE
|
||||||
|
|||||||
Reference in New Issue
Block a user