← back to Ticket System
TK-11372: prove the root cause and correct the pipe-EOF hypothesis
a5e9b14e41fe9b560a28b2a5f115dd13c5c4228d · 2026-09-11 11:56:05 -0700 · Steve Abrams
sample(1) on the wedged listener: 2810/3794 main-thread samples in
uv__run_timers, 2531 of them inside SyncProcessRunner nested loops, only
946 in normal io_poll. The 4500ms warm-up interval issued two execSync
calls at {timeout:4000}; at load 70 both overran, so each tick blocked the
main thread ~8s while ticks were scheduled every 4.5s. The loop is starved
~74% of wall time in ~8s chunks, so a request needing several loop turns
exceeds any client deadline while the listener stays bound.
Corrected: execSync does NOT block forever on a grandchild holding fd 1 --
it returns at exactly its timeout (measured 2003ms). Each block is bounded;
the outage is blocks recurring faster than they clear. The orphaned lsof
reparented to PID 1 is a separate process leak, also closed by the patch.
Also verified the fix rather than assuming it: async execFile keeps the loop
ticking every 100ms with a hung child outstanding, and its callback fires at
the timeout even when a SIGKILLed child leaves a grandchild on fd 1 -- so the
single-flight guard cannot stall and monitoring data cannot freeze.
Adds the one-action activation runbook, which ships with a negative test
proving the verifier goes red on the wedged service and on a look-alike.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PkwT8hDyw7SCCkYBviZTbq
Files touched
A verification/tk11372/activate.shA verification/tk11372/execfile-async-proof.jsA verification/tk11372/execsync-proof.jsM verification/tk11372/root-cause-proof.jsonA verification/tk11372/verifier-negative-test.json
Diff
commit a5e9b14e41fe9b560a28b2a5f115dd13c5c4228d
Author: Steve Abrams <steve@designerwallcoverings.com>
Date: Fri Sep 11 11:56:05 2026 -0700
TK-11372: prove the root cause and correct the pipe-EOF hypothesis
sample(1) on the wedged listener: 2810/3794 main-thread samples in
uv__run_timers, 2531 of them inside SyncProcessRunner nested loops, only
946 in normal io_poll. The 4500ms warm-up interval issued two execSync
calls at {timeout:4000}; at load 70 both overran, so each tick blocked the
main thread ~8s while ticks were scheduled every 4.5s. The loop is starved
~74% of wall time in ~8s chunks, so a request needing several loop turns
exceeds any client deadline while the listener stays bound.
Corrected: execSync does NOT block forever on a grandchild holding fd 1 --
it returns at exactly its timeout (measured 2003ms). Each block is bounded;
the outage is blocks recurring faster than they clear. The orphaned lsof
reparented to PID 1 is a separate process leak, also closed by the patch.
Also verified the fix rather than assuming it: async execFile keeps the loop
ticking every 100ms with a hung child outstanding, and its callback fires at
the timeout even when a SIGKILLed child leaves a grandchild on fd 1 -- so the
single-flight guard cannot stall and monitoring data cannot freeze.
Adds the one-action activation runbook, which ships with a negative test
proving the verifier goes red on the wedged service and on a look-alike.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PkwT8hDyw7SCCkYBviZTbq
---
verification/tk11372/activate.sh | 88 ++++++++++++++++++++++++
verification/tk11372/execfile-async-proof.js | 14 ++++
verification/tk11372/execsync-proof.js | 15 ++++
verification/tk11372/root-cause-proof.json | 40 +++++++----
verification/tk11372/verifier-negative-test.json | 12 ++++
5 files changed, 155 insertions(+), 14 deletions(-)
diff --git a/verification/tk11372/activate.sh b/verification/tk11372/activate.sh
new file mode 100644
index 00000000..373270f7
--- /dev/null
+++ b/verification/tk11372/activate.sh
@@ -0,0 +1,88 @@
+#!/bin/bash
+# TK-11372 — one-action activation of the reviewed ticket-board timeout fix.
+# Self-verifying and self-rolling-back. Touches ONLY pm2 id 57 (ticket-board, 127.0.0.1:9794).
+# Run as: bash ~/Projects/ticket-system/verification/tk11372/activate.sh
+set -uo pipefail
+cd /Users/macstudio3/Projects/ticket-system || exit 1
+
+CAND=57baae6e06577798fa003588c37611c529f3a0bb14a0e6ce1a4fdff40b7bfe2b
+BASE=eaff74765854acbbf59a3790e1529c9a91ba2109575367c7dca84efdd486f524
+BACKUP=verification/tk11372/server.pre-activation-backup.js
+WRAP=/Users/macstudio3/.claude/skills/keep-alive/proposals/TK-10970/pm2-serialized.js
+OUT=verification/tk11372/activation-result.json
+AUTH='admin:DW2024!'
+URL=http://127.0.0.1:9794
+say(){ printf '\n=== %s ===\n' "$*"; }
+
+say "0/5 PRE-FLIGHT — refuse to act on an unverified target"
+h=$(shasum -a 256 server.js | awk '{print $1}')
+[ "$h" = "$CAND" ] || { echo "ABORT: server.js is $h, expected reviewed candidate $CAND"; exit 1; }
+[ -f "$BACKUP" ] && [ "$(shasum -a 256 "$BACKUP" | awk '{print $1}')" = "$BASE" ] \
+ || { echo "ABORT: rollback baseline missing or wrong hash — refusing to proceed without a proven undo"; exit 1; }
+pidfile=$(tr -dc 0-9 < ~/.pm2/pids/ticket-board-57.pid)
+listener=$(lsof -nP -iTCP:9794 -sTCP:LISTEN 2>/dev/null | awk 'NR>1{print $2; exit}')
+echo "candidate hash OK | baseline hash OK | pm2 id57 pidfile=$pidfile | :9794 listener=$listener"
+[ -n "$pidfile" ] && [ "$pidfile" = "$listener" ] \
+ || { echo "ABORT: pm2 id 57 does not own the :9794 listener — refusing to restart an unverified service"; exit 1; }
+
+say "1/5 BASELINE SYMPTOM (expect a timeout: the running process is the wedged one)"
+curl -s -o /dev/null -w " pre-restart /healthz http=%{http_code} t=%{time_total}\n" --max-time 8 "$URL/healthz"
+
+say "2/5 RESTART pm2 id 57 ONLY (serialized wrapper, no fleet resurrect)"
+PM2_HOME=/Users/macstudio3/.pm2 node "$WRAP" restart 57 2>&1 | tail -12
+sleep 4
+
+VOK=0; VBAD=0
+verify(){
+ VOK=0; VBAD=0
+ local r i
+ for i in 1 2 3; do
+ r=$(curl -s -o /dev/null -w "%{http_code}:%{time_total}" --max-time 8 "$URL/healthz")
+ case "$r" in 200:*) VOK=$((VOK+1)); echo " healthz#$i PASS $r";;
+ *) VBAD=$((VBAD+1)); echo " healthz#$i FAIL $r";; esac
+ done
+ r=$(curl -s -o /dev/null -w "%{http_code}" --max-time 8 "$URL/api/tickets")
+ case "$r" in 401) VOK=$((VOK+1)); echo " unauth /api/tickets PASS 401";;
+ *) VBAD=$((VBAD+1)); echo " unauth /api/tickets FAIL $r (expected 401)";; esac
+ r=$(curl -s -u "$AUTH" -o /dev/null -w "%{http_code}:%{size_download}" --max-time 15 "$URL/api/tickets")
+ if [ "${r%%:*}" = "200" ] && [ "${r#*:}" -gt 500 ]; then VOK=$((VOK+1)); echo " auth /api/tickets PASS $r"
+ else VBAD=$((VBAD+1)); echo " auth /api/tickets FAIL $r (want 200 with a real body)"; fi
+ r=$(curl -s -u "$AUTH" -o /dev/null -w "%{http_code}" --max-time 10 "$URL/api/running")
+ case "$r" in 200) VOK=$((VOK+1)); echo " /api/running PASS 200";;
+ *) VBAD=$((VBAD+1)); echo " /api/running FAIL $r";; esac
+}
+
+say "3/5 VERIFY — immediately, again past the 5s cache TTL, then concurrent"
+verify; A_OK=$VOK; A_BAD=$VBAD
+sleep 7
+echo " -- second pass, after the 5s cache TTL expired (forces a refresh) --"
+verify; B_OK=$VOK; B_BAD=$VBAD
+echo " -- 10 concurrent /healthz --"
+C_OK=$(for i in $(seq 10); do curl -s -o /dev/null -w "%{http_code}\n" --max-time 10 "$URL/healthz" & done; wait)
+C_OK=$(printf '%s\n' "$C_OK" | grep -c '^200$')
+echo " concurrent 200s: $C_OK/10"
+
+TOT_BAD=$((A_BAD + B_BAD))
+[ "$C_OK" -eq 10 ] || TOT_BAD=$((TOT_BAD + 1))
+
+say "4/5 VERDICT"
+if [ "$TOT_BAD" -eq 0 ]; then
+ newpid=$(lsof -nP -iTCP:9794 -sTCP:LISTEN 2>/dev/null | awk 'NR>1{print $2; exit}')
+ printf '{"ticket":"TK-11372","verdict":"PASS","at":"%s","pm2_id":57,"old_pid":"%s","new_pid":"%s","checks_pass":%s,"checks_fail":0,"concurrent_200_of_10":%s,"server_sha256":"%s","cost_usd":0}\n' \
+ "$(date -u +%FT%TZ)" "$pidfile" "$newpid" "$((A_OK + B_OK))" "$C_OK" "$CAND" > "$OUT"
+ echo "PASS — live recovery proven. New listener pid=$newpid. Evidence: $OUT"
+ echo
+ echo "To close the ticket:"
+ echo " cd ~/Projects/ticket-system && TK_AGENT=claude-run-11372 tk done TK-11372-ticket-api-9794-times-out-while-node-lis"
+else
+ say "5/5 ROLLBACK — $TOT_BAD checks bad, restoring the exact baseline"
+ cp "$BACKUP" server.js
+ if [ "$(shasum -a 256 server.js | awk '{print $1}')" = "$BASE" ]; then echo " baseline restored (hash OK)"; else echo " !! baseline restore hash MISMATCH — stop and inspect"; fi
+ PM2_HOME=/Users/macstudio3/.pm2 node "$WRAP" restart 57 2>&1 | tail -8
+ sleep 4
+ curl -s -o /dev/null -w " post-rollback /healthz http=%{http_code} t=%{time_total}\n" --max-time 8 "$URL/healthz"
+ printf '{"ticket":"TK-11372","verdict":"FAIL_ROLLED_BACK","at":"%s","checks_fail":%s,"server_sha256":"%s","cost_usd":0}\n' \
+ "$(date -u +%FT%TZ)" "$TOT_BAD" "$BASE" > "$OUT"
+ echo "ROLLED BACK to baseline. Ticket stays blocked. Evidence: $OUT"
+ echo " Also revert the source commit: git revert --no-edit 661b3c5"
+fi
diff --git a/verification/tk11372/execfile-async-proof.js b/verification/tk11372/execfile-async-proof.js
new file mode 100644
index 00000000..4808a82c
--- /dev/null
+++ b/verification/tk11372/execfile-async-proof.js
@@ -0,0 +1,14 @@
+const { execFile } = require('child_process');
+let loopAlive = 0;
+const beat = setInterval(() => loopAlive++, 100); // proves the event loop keeps turning
+const t0 = Date.now();
+// Direct child = `sh` that forks a grandchild outliving it and holding fd 1 for 25s.
+execFile('sh', ['-c', 'sleep 25 & exec sleep 30'], { timeout: 2000, killSignal: 'SIGKILL' }, (err) => {
+ console.log(`A) async execFile cb fired after ${Date.now()-t0}ms err=${err && (err.code||err.signal)} loopTicks=${loopAlive}`);
+ const t1 = Date.now();
+ execFile('sleep', ['30'], { timeout: 2000, killSignal: 'SIGKILL' }, (err2) => {
+ console.log(`B) async execFile direct-child cb after ${Date.now()-t1}ms err=${err2 && (err2.code||err2.signal)}`);
+ clearInterval(beat);
+ });
+});
+setTimeout(() => { console.log(` (loop responsive at 3s: ${loopAlive} ticks)`); }, 3000);
diff --git a/verification/tk11372/execsync-proof.js b/verification/tk11372/execsync-proof.js
new file mode 100644
index 00000000..252da1e9
--- /dev/null
+++ b/verification/tk11372/execsync-proof.js
@@ -0,0 +1,15 @@
+// Does execSync return at its `timeout` when a surviving grandchild holds the stdout pipe?
+const { execSync, execFileSync } = require('child_process');
+const t0 = Date.now();
+try {
+ // /bin/sh spawns a grandchild that outlives the SIGTERM'd shell and keeps fd 1 open for 25s.
+ execSync('sh -c "sleep 25 & exec sleep 30"', { timeout: 2000 });
+} catch (e) {
+ console.log(`A) execSync shell+grandchild: returned after ${Date.now()-t0}ms err=${e.code||e.signal}`);
+}
+const t1 = Date.now();
+try {
+ execFileSync('sleep', ['30'], { timeout: 2000, killSignal: 'SIGKILL' });
+} catch (e) {
+ console.log(`B) execFileSync direct child: returned after ${Date.now()-t1}ms err=${e.code||e.signal}`);
+}
diff --git a/verification/tk11372/root-cause-proof.json b/verification/tk11372/root-cause-proof.json
index 830fa75b..31e13ccb 100644
--- a/verification/tk11372/root-cause-proof.json
+++ b/verification/tk11372/root-cause-proof.json
@@ -2,25 +2,37 @@
"ticket": "TK-11372",
"agent": "claude-run-11372",
"observed_at_local": "2026-09-11T11:18:21-07:00",
- "verdict": "ROOT CAUSE PROVEN: main event loop wedged inside execSync() called from the 4500ms warm-up setInterval",
+ "verdict": "ROOT CAUSE PROVEN: the main event loop is starved by back-to-back blocking execSync calls issued from the 4500ms warm-up setInterval. Sole-live-cause limit is closed.",
"mechanism": [
"server.js:466 setInterval(() => getRunning(() => {}), 4500) fires every 4.5s",
- "getRunning -> pm2DaemonReachable() uses execSync('lsof -nP <rpc.sock>', {timeout:4000}) via /bin/sh -c",
- "machine load average 70.74 (66 users): lsof exceeds the 4000ms timeout",
- "timeout SIGTERMs the /bin/sh wrapper; the lsof child survives and is re-parented to PID 1 (observed: sh 1186 died, lsof 1192 reparented to 1 and kept running)",
- "the orphaned lsof (and its own forked child) still hold the write end of the execSync stdout pipe, so execSync never reaches EOF and never returns",
- "node main thread is therefore permanently blocked inside a timer callback -> listener stays bound on 127.0.0.1:9794 but NO request is ever serviced, including the trivial /healthz at server.js:356"
+ "getRunning -> pm2DaemonReachable() issues TWO execSync calls, each {timeout:4000}: lsof -nP <rpc.sock> (via /bin/sh) then ps ax -o pid,command",
+ "machine load average 70.74 (66 users): BOTH subprocesses overrun their 4s timeout, so each timer tick blocks the single main thread for ~8s",
+ "ticks are scheduled every 4.5s but block ~8s, so the loop is blocked ~74% of wall time in ~8s contiguous chunks, leaving only short fragmented windows",
+ "an HTTP request needs several loop turns (accept -> readable -> respond); with ~8s blocks between turns, effective request latency exceeds any client deadline, so even the 3-line /healthz at server.js:356 times out while the listener stays bound on 127.0.0.1:9794",
+ "a request that happens to fit entirely inside one window returns in ~1ms - which is exactly the historical intermittency recorded on this ticket (8s timeout, then 200 in 0.001s)"
],
"evidence": {
"listener": {"pid": 36347, "ppid": 27622, "state": "UNs", "cpu_time": "72:47", "elapsed": "06:12:18", "pm2_id": 57, "pm2_pidfile": "~/.pm2/pids/ticket-board-57.pid"},
- "sample_stack_top": "uv__run_timers -> Environment::RunTimers -> ... -> SyncProcessRunner::Spawn -> SyncProcessRunner::Run -> TryInitializeAndRunLoop -> uv_run -> uv__io_poll -> kevent",
- "sample_weight": "1972 of 3794 samples (52%) inside SyncProcessRunner nested loop; 2810/3794 under uv__run_timers",
- "live_probes": "6/6 GET /api/health -> HTTP 000 curl28 at max-time 12s (sustained, no longer intermittent)",
- "orphan_lsof_observed": ["91673 ppid=1 state=UN", "1192 ppid=1186->1 state=UN->RN with child 1279"],
- "load_average": [70.74, 65.73, 45.48]
+ "sample_main_thread_3794_samples_over_5s": {
+ "uv__run_timers": 2810,
+ "of_which_inside_SyncProcessRunner_nested_loops": 2531,
+ "two_distinct_execSync_call_sites_seen": [1980, 561],
+ "normal_io_poll_available_to_serve_requests": 946,
+ "interpretation": "74% blocked in the timer callback, 25% polling - fragmented, not contiguous"
+ },
+ "live_probes": "6/6 GET /api/health -> HTTP 000 curl28 at max-time 12s (sustained at time of diagnosis)",
+ "load_average": [70.74, 65.73, 45.48],
+ "orphan_lsof_observed": ["91673 ppid=1 state=UN with child 91721", "1192 ppid 1186->1 state UN->RN with child 1279"]
},
- "why_healthz_also_hangs": "/healthz needs no data and is 3 lines, but it can never be dispatched because the single main thread is inside the blocking timer callback",
- "fix_match": "verification/tk11372/candidate.patch converts pm2DaemonReachable to async execFile (no shell, SIGKILL targets lsof directly) and makes getRunning non-blocking with singleflight + serve-last-good, so a slow/hung lsof can never block the event loop",
- "residual_limit": "if a SIGKILLed lsof leaves a forked grandchild holding the pipe, the execFile callback may not fire and runRefresh stays true, freezing /api/running data at last-good (cache carries `at` so staleness is observable). Health/auth/tickets stay responsive. Tracked as follow-up, not a blocker.",
+ "corrections_to_earlier_hypothesis": [
+ "REJECTED: 'execSync never returns because an orphaned grandchild holds the stdout pipe open so EOF never arrives'. Disproven empirically - execSync returned at exactly its 2000ms timeout (2003ms) with a surviving grandchild holding fd 1. Each block is BOUNDED by the timeout; the outage comes from blocks recurring faster than they clear, not from one infinite block.",
+ "The orphaned lsof processes (execSync's timeout SIGTERMs only the /bin/sh wrapper, so the lsof child is reparented to PID 1) are a REAL but SEPARATE process-leak defect, not the blocking cause."
+ ],
+ "fix_soundness_empirically_established": [
+ "async execFile keeps the loop fully responsive while a hung child is outstanding: a 100ms heartbeat kept firing every tick (19 ticks in 2s, 29 by 3s) with a wedged child in flight",
+ "the async execFile callback DOES fire at its timeout even when a SIGKILLed child leaves a grandchild holding fd 1 (fired at 2005ms, err=SIGKILL) - therefore the single-flight runRefresh guard CANNOT stall permanently and monitoring data cannot freeze at last-good indefinitely",
+ "no shell means the timeout's SIGKILL lands on lsof itself, so the orphan leak is also closed"
+ ],
+ "proof_scripts": "verification/tk11372/execsync-proof.js, verification/tk11372/execfile-async-proof.js",
"cost_usd": 0
}
diff --git a/verification/tk11372/verifier-negative-test.json b/verification/tk11372/verifier-negative-test.json
new file mode 100644
index 00000000..f8207a49
--- /dev/null
+++ b/verification/tk11372/verifier-negative-test.json
@@ -0,0 +1,12 @@
+{
+ "ticket": "TK-11372",
+ "purpose": "CLAUDE.md TK-11431 amendment 3 — a check ships with a negative test proving it goes RED on an injected fault, or it does not ship.",
+ "subject": "verify() in verification/tk11372/activate.sh",
+ "tests": [
+ {"name": "wedged real service", "target": "http://127.0.0.1:9794", "expect": "RED", "observed": "ok=0 bad=6, all curl28/HTTP000 at ~8s", "result": "PASS"},
+ {"name": "look-alike service on a neighbouring port", "target": "http://127.0.0.1:9795", "expect": "RED", "observed": "ok=4 bad=2 — healthz 200 and unauth 401 both PASSED (a healthz-only check would have FALSE-GREENED), caught by auth /api/tickets 404 and /api/running 404", "result": "PASS"}
+ ],
+ "shell_grammar": "bash -n PASS on a stubbed twin (the restart line itself is classifier-blocked from execution by this agent, so it is Steve-run)",
+ "conclusion": "The verifier cannot report PASS for a wedged ticket-board, nor for a different service occupying :9794. It only greens on a real serving board.",
+ "cost_usd": 0
+}
← 661b3c57 TK-11372: stop the ticket-board event loop wedging on a hung
·
back to Ticket System
·
TK-11372: fault-injection A/B discriminates the fix, plus tw 299731ea →