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) <noreply@anthropic.com>
Signed-off-by: Xavier Roche <roche@httrack.com>

* 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) <noreply@anthropic.com>
Signed-off-by: Xavier Roche <roche@httrack.com>

---------

Signed-off-by: Xavier Roche <roche@httrack.com>
Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>

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"

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"

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)

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"