From f5fbd1a82edc9362bb052d784c97294f94d21fae Mon Sep 17 00:00:00 2001 From: Xavier Roche Date: Sat, 8 Aug 2026 21:22:21 +0200 Subject: [PATCH] The suite watchdogs give up the first time a poll tick cannot start a process (#1081) * The suite watchdogs give up the first time a poll tick cannot start a process ci_suite_heartbeat read its clock through a command substitution, so the watchdog needed a fork to tell the time, and a sleep that returns without waiting either killed it under the caller's errexit or turned test-timeout.sh's wait loop into a fork storm. Both fail exactly when the box is short of processes, which is when the watchdog is the only thing still reporting. The clock now assigns hb_time instead of printing, the heartbeat's tick is guarded, and the wait loop gives up after ten ticks that never waited, naming the test in the progress log the off-box watchdog reads. References #1038. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Xavier Roche * Review fixes: dump the crawl logs before TMPDIR goes, and pin the guards with mutants The nofork exit skipped dump_crawl_logs, so the EXIT trap deleted the very logs that would explain the hang. reap_bounded stays out: it polls on the same broken tick. 250 now asserts the tenth tick by count, that the wedged child was killed, and that a tick failing every other call is never read as a wedge. 171's sleep stub returns 126 once, which is what catches the heartbeat guard being removed. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Xavier Roche --------- Signed-off-by: Xavier Roche Co-authored-by: Claude Opus 5 (1M context) --- tests/171_watchdog-heartbeat.test | 27 ++++++++- tests/250_timeout-poll-nofork.test | 94 ++++++++++++++++++++++++++++++ tests/ci-windows-suite.sh | 17 ++++-- tests/test-timeout.sh | 21 ++++++- 4 files changed, 149 insertions(+), 10 deletions(-) create mode 100755 tests/250_timeout-poll-nofork.test diff --git a/tests/171_watchdog-heartbeat.test b/tests/171_watchdog-heartbeat.test index f153507c..968c3262 100644 --- a/tests/171_watchdog-heartbeat.test +++ b/tests/171_watchdog-heartbeat.test @@ -24,9 +24,15 @@ fail() { } progress="$tmp/progress" -kill_tree() { echo "KILL $1 at $(hb_now)"; } +kill_tree() { + hb_now + echo "KILL $1 at $hb_time" +} # Stubbed too, or the legs below would send a real SIGKILL to pid 4242. -kill_pid() { echo "DIRECT $1 at $(hb_now)"; } +kill_pid() { + hb_now + echo "DIRECT $1 at $hb_time" +} # Twelve lines, against a bound of eight. list_stray_processes() { printf '%s\n' "$*" >"$tmp/strayargs" @@ -65,10 +71,21 @@ sleep() { printf 'RUN %ss%%a%%b.test\r at %ss\n' "$vnow" "$vnow" >>"$progress" echo "$vnow" >"$tmp/lastwrite" fi + # One tick reports what a sleep that cannot exec reports. Unguarded, errexit + # ends the watchdog here and every assertion below goes unanswered. + test "$ticks" -ne 3 || return 126 + return 0 +} +# A clock read through a command substitution runs one subshell deeper than the +# watchdog itself, and that is a fork it must not need. Marker, not fail: an exit +# here would only end that subshell. hb_depth is set at each call site below. +hb_now() { + test "$BASH_SUBSHELL" -eq "$hb_depth" || : >"$tmp/forked" + hb_time=$vnow } -hb_now() { echo "$vnow"; } printf 'RUN 98_earlier.test at 0s\n' >"$progress" +hb_depth=$BASH_SUBSHELL ci_suite_heartbeat 720 360 "$progress" 900 4242 >"$tmp/out" 2>&1 # Timed by the stub, not by the annotation. The kill is due one staticness window @@ -134,6 +151,7 @@ awk '/^::(notice|error) title=/ { if (prev != "") bad = 1 } { prev = $0 } END { vnow=9000 ticks=0 printf 'RUN 97_dead.test at 0s\n' >"$progress" +hb_depth=$BASH_SUBSHELL ci_suite_heartbeat 960 360 "$progress" 900 4242 >"$tmp/late" 2>&1 killed=$(sed -n 's/^KILL 4242 at \([0-9]*\)$/\1/p' "$tmp/late") test -n "$killed" || fail "a suite static from the start was never killed" @@ -157,6 +175,7 @@ rc=0 echo "TREE $1" >>"$rec" exit 9 } + hb_depth=$BASH_SUBSHELL ci_suite_heartbeat 960 360 "$progress" 900 4242 >"$tmp/hedge" 2>&1 ) || rc=$? test "$rc" -eq 9 || fail "the tree kill never fired: watchdog returned $rc" @@ -168,4 +187,6 @@ test "$(sed -n 3p "$rec")" = "TREE 4242" || fail "the tree was not killed after the direct signal: $(tr '\n' '/' <"$rec")" test "$(sed -n '$=' "$rec")" -eq 3 || fail "extra kills: $(tr '\n' '/' <"$rec")" +test ! -e "$tmp/forked" || fail "the clock was read through a subshell, a fork a starved box cannot spare" + echo "heartbeat OK" diff --git a/tests/250_timeout-poll-nofork.test b/tests/250_timeout-poll-nofork.test new file mode 100755 index 00000000..ae7a8779 --- /dev/null +++ b/tests/250_timeout-poll-nofork.test @@ -0,0 +1,94 @@ +#!/bin/bash +# +# A poll tick that returns without waiting must end test-timeout.sh's wait loop, +# not be re-forked every iteration on a box already out of processes (#1038). + +set -euo pipefail + +: "${top_srcdir:=..}" +testdir=$(cd "$(dirname "$0")" && pwd) +# shellcheck source=tests/testlib.sh +. "${testdir}/testlib.sh" + +tmp=$(mktemp -d "${TMPDIR:-/tmp}/httrack_nofork.XXXXXX") +trap 'set +e; rm -rf "$tmp"' EXIT +fail() { + echo "FAIL: $*" >&2 + exit 1 +} + +# A tick that cannot exec is what bash reports as 126/127, so a stub returning one +# models it exactly. The flaky stub fails every other call, which no counter that +# resets on a good tick can ever accumulate into a verdict. +mkdir -p "$tmp/dead" "$tmp/flaky" +cat >"$tmp/dead/sleep" <<'EOF' +#!/bin/sh +exit 126 +EOF +cat >"$tmp/flaky/sleep" <<'EOF' +#!/bin/sh +n=$(cat "$TICKFILE" 2>/dev/null || echo 0) +n=$((n + 1)) +echo "$n" >"$TICKFILE" +test $((n % 2)) -ne 0 || exit 126 +exit 0 +EOF +chmod +x "$tmp/dead/sleep" "$tmp/flaky/sleep" + +# Builtins only, and self-limiting: the stubbed sleep is on the child's PATH too, +# and a child that outlives the harness would leak when the kill is the thing broken. +cat >"$tmp/child.sh" <<'EOF' +#!/bin/bash +trap 'exit 0' TERM INT +echo "$$" >"$PIDFILE" +end=$((SECONDS + 5)) +while test "$SECONDS" -lt "$end"; do :; done +EOF + +# 60s, so a deadline firing in place of the guard shows up as a stall and a DUMP +# line rather than as the same 124. +run_timeout() { + local bin=$1 log=$2 + env PATH="$bin:$PATH" \ + TICKFILE="$tmp/ticks" PIDFILE="$tmp/childpid" \ + HTTRACK_POLL_SLEEP=1 \ + HTTRACK_TEST_TIMEOUT=60 \ + HTTRACK_PROGRESS_LOG="$tmp/progress" \ + "$BASH" "$testdir/test-timeout.sh" "$tmp/child.sh" >"$log" 2>&1 +} + +: >"$tmp/progress" +: >"$tmp/childpid" +began=$SECONDS +rc=0 +run_timeout "$tmp/dead" "$tmp/broken.log" || rc=$? +spent=$((SECONDS - began)) + +test "$rc" -eq 124 || fail "a tick that never waits exited $rc, not 124: $(cat "$tmp/broken.log")" +# With the count, or a guard tripping on the first tick reads the same. +grep -q 'poll tick ran 10 times' "$tmp/broken.log" || + fail "no verdict naming the tenth tick: $(cat "$tmp/broken.log")" +grep -q '^NOFORK child.sh$' "$tmp/progress" || + fail "the off-box watchdog got no marker: $(cat "$tmp/progress")" +# The deadline path writes DUMP and spends the whole 60s, so either says the guard +# is gone and the budget is what ended the loop. +grep -q '^DUMP ' "$tmp/progress" && fail "the loop ran to its 60s deadline, not the guard" +test "$spent" -lt 30 || fail "took ${spent}s to give up on a tick that returns at once" +childpid=$(cat "$tmp/childpid") +test -n "$childpid" || fail "the child never started" +kill -0 "$childpid" 2>/dev/null && fail "giving up left the wedged test running as $childpid" + +# A tick that fails intermittently is a healthy box, and must never reach the +# verdict: without the reset, any run long enough accumulates ten of them. +: >"$tmp/progress" +: >"$tmp/ticks" +run_timeout "$tmp/flaky" "$tmp/flaky.log" || fail "an intermittent tick failed the run: $(cat "$tmp/flaky.log")" +grep -q 'NOFORK' "$tmp/progress" && fail "ticks that fail every other call were read as a wedge" + +# Control: a working sleep must reach neither branch, or the assertions above would +# hold for any run at all. +: >"$tmp/progress" +run_timeout "" "$tmp/ok.log" || fail "a healthy run failed: $(cat "$tmp/ok.log")" +grep -q 'NOFORK' "$tmp/progress" && fail "a healthy poll tick was read as a broken one" + +echo "test-timeout poll guard OK" diff --git a/tests/ci-windows-suite.sh b/tests/ci-windows-suite.sh index e8e86ede..6b7e9492 100644 --- a/tests/ci-windows-suite.sh +++ b/tests/ci-windows-suite.sh @@ -25,9 +25,10 @@ ci_annotate() { # been static for $4s. Staticness, never elapsed time: a healthy test in flight and # a wedged one look identical by the clock, but every outcome writes a line, the # per-test timeout included, so $4 past that timeout means it never fired. -# Seconds since this shell started. Overridable, so the unit test can drive the -# schedule the workflow really passes off a virtual clock instead of waiting it out. -hb_now() { echo "$SECONDS"; } +# Assigns into hb_time rather than printing: reading the clock forks nothing, which +# matters when the box has none to spare. Overridable for the unit test virtual clock. +hb_time=0 +hb_now() { hb_time=$SECONDS; } # Start the off-box telemetry over the progress log $1, setting ci_watchdog_pid; # return 1 with no PowerShell available. Forks nothing and kills nothing, so it @@ -70,10 +71,14 @@ ci_suite_heartbeat() { # Measured, never accumulated: the starvation this watchdog exists to catch is # exactly what makes a sleep overshoot, and drift only ever delays the kill. test "$tick" -le 30 || tick=30 - begin=$(hb_now) said=$begin moved=$begin + hb_now + begin=$hb_time said=$begin moved=$begin while :; do - sleep "$tick" >/dev/null 2>&1 # holds no stdout: the caller's trap orphans it - now=$(hb_now) + # Guarded: a tick that cannot exec returns 127, and under the caller's errexit a + # bare failure would end the watchdog in silence (#1038). + sleep "$tick" >/dev/null 2>&1 || : # holds no stdout: the caller's trap orphans it + hb_now + now=$hb_time # Guarded: under the caller's errexit a bare substitution assignment would # end the watchdog in silence, which reads as protection and is not. line=$(tail -n 1 "$progress" 2>/dev/null || true) diff --git a/tests/test-timeout.sh b/tests/test-timeout.sh index 1da7fa52..7ff3dd62 100644 --- a/tests/test-timeout.sh +++ b/tests/test-timeout.sh @@ -67,6 +67,10 @@ fi # is floored: a reading of $budget can be a fraction under it, and firing early # kills a healthy test. start=$SECONDS +# A tick that never waits bounds nothing, and re-forking it each loop is a fork storm +# on a starved box (#1038). Counted, not tripped on the first tick. +nowait=0 +nowait_limit=10 while kill -0 "$pid" 2>/dev/null; do if test "$((SECONDS - start))" -gt "$budget"; then # The dump below can run for minutes. Say so where a suite watchdog is @@ -79,6 +83,21 @@ while kill -0 "$pid" 2>/dev/null; do dump_crawl_logs exit 124 fi - poll_wait "$tick" + if poll_wait "$tick"; then + nowait=0 + continue + fi + nowait=$((nowait + 1)) + test "$nowait" -ge "$nowait_limit" || continue + # So the off-box watchdog can still see it: a dead runner leaves only its last + # commit status behind (#795). + test -z "${HTTRACK_PROGRESS_LOG:-}" || echo "NOFORK $name" >>"$HTTRACK_PROGRESS_LOG" + echo "hang: the poll tick ran $nowait times without waiting; this box cannot start a process" + kill_tree "$pid" + # No reap_bounded here: it polls on the same broken tick, which is the spin + # this branch exists to end. + # The EXIT trap deletes TMPDIR, so a crawl log left undumped is a destroyed one. + dump_crawl_logs + exit 124 done wait "$pid"