perf(tests): stop an orphaned child holding the test's pipe open - #351
Conversation
test-pre-push-scan-timeout.sh took 197s of the suite's 234s. The cause was not oversized sleep margins -- the "roughly 30-40s of real sleeps" estimate recorded in #301 was correct, and the design accounts for ~33s. The other ~164s was a defect. Measured per case, from outside the command substitution: line 286 (IGNORER, 2s budget) GNU timeout: 4s fallback: 60s line 409 (IGNORER, grace=6) fallback: 60s line 428 (IGNORER, grace=bogus) fallback: 60s Three cases at 60s each is 180s. All three are the SIGTERM-ignoring fixture on the watchdog path, and the first shows the asymmetry plainly: identical input and assertion, 4s under GNU timeout and 60s under the fallback. run_bounded's fallback kills a pid, while GNU timeout kills a process group. SIGKILL to the IGNORER script therefore leaves its foreground `sleep` child running. Proven in isolation: after `kill -KILL <script-pid>`, the sleep is still alive. That orphan inherits the driver's stdout, so the enclosing command substitution blocks until it exits -- the command's full length -- even though run_bounded returned in ~4s. The driver now sends the command's output to /dev/null. Only the driver's own `rc elapsed` line is ever read, so this costs no coverage and fixes the whole class rather than one fixture. The test could not see this about itself. Every assertion read the elapsed count the driver measures INSIDE the pipe, which reported 4s while the caller blocked 60s. Each timing case now also asserts CASE_WALL, measured around the substitution, and names #350 when they disagree. That is the assertion that would have caught this. With the overrun gone the margins are scaled too, within two constraints found by reading run_bounded rather than guessing: the watchdog's wait loop polls in `sleep 1` steps, so a budget below 1s is not representable; and SEMGREP_TIMEOUT_KILL_GRACE is validated against ^[0-9]+$, so a fractional grace silently becomes the default. Budgets 3/2/30 -> 1/1/5, commands 60s -> 10s, raised grace 6 -> 4 (the smallest value still separable from the 2s default at SECONDS' 1-second granularity). Two assertions were added that the old file lacked: the non-numeric-grace case now checks it lands near the 2s default, not merely that it exits 124 -- a grace loop ignoring the value entirely would have satisfied the old check. The IGNORER comment claimed "killing this script tears it down with it... none left behind at the end." That is measurably false on the fallback path and is corrected in place. The child shape is kept deliberately: semgrep spawns workers, so a fixture whose children outlive it is the representative case, and #350's fix will need it. Verified: - this file 197s -> 20.6s; full suite 234s -> 60.7s, 31/31 pass - passes with PATH=/usr/bin:/bin, the stock-macOS path CI actually takes - known-bad A: removing the 137->124 normalization fails the expiry cases - known-bad B: deleting the `kill -KILL` escalation fails 6 assertions, including both new wall-clock ones -- the shortened 10s command is still long enough to expose an escalation that never lands The hook defect itself is #350, filed not fixed. Its known-bad gate is an assertion that a timed-out command's children are gone, which is red against current main, so it cannot ride along with a test-speed change. Advances #301. Claude-Session: https://claude.ai/code/session_011awg91UvzUos9YoXHJ2e8B
This comment has been minimized.
This comment has been minimized.
Review: PR #351The changes implement a fix for issue #350 (orphaned child processes holding pipes open in command substitution contexts) plus new test infrastructure to detect regressions. Fix mechanism: Redirecting Test improvements: New Parameter adjustments: Test timeouts reduced (3s→1s budget, 60s→10s commands) with explained rationale. Assertion thresholds adjusted accordingly; margins account for 1-second granularity of No bugs, reliability regressions, security issues, or data-loss risks detected. VERDICT: PASS |
Full suite 234s → 60.7s. This file 197s → 20.6s. All 31 files pass.
The diagnosis in #301 turned out to be right and my first measurement wrong. The margins were never the problem — the "roughly 30-40s of real sleeps" estimate recorded there is accurate, and the design accounts for ~33s. The other ~164s was a defect.
What was actually happening
Per-case wall clock, measured outside the command substitution:
timeoutThree cases × 60s = 180s, all the SIGTERM-ignoring fixture on the fallback path. The first row is the tell: identical input, identical assertion, 15× apart.
run_bounded's fallback kills a pid; GNUtimeoutkills a process group. So SIGKILL to the IGNORER script leaves its foregroundsleepchild alive. Proven in isolation:That orphan inherits the driver's stdout, so
$(run_case ...)blocks until it exits — the command's full length — even thoughrun_boundedreturned in ~4s.The test could not see this about itself
Every assertion read the
elapsedvalue the driver measures inside the pipe. It reported 4s while the caller blocked 60s, and the case passed. A test whose subject matter is "is this bounded?" had a 15× overrun in its own blind spot.Each timing case now also asserts
CASE_WALL, measured around the substitution, and names #350 when the two disagree. That is the assertion that would have caught this two months ago.Fix
The driver sends the command's output to
/dev/null. Only its ownrc elapsedline is ever read, so this costs no coverage and fixes the whole class rather than one fixture.Margins are then scaled, within two constraints found by reading
run_boundedrather than guessing:sleep 1steps → a budget below 1s is not representableSEMGREP_TIMEOUT_KILL_GRACEis validated against^[0-9]+$→ a fractional grace silently becomes the default, which would have made the grace case assert the default against itselfBudgets 3/2/30 → 1/1/5, commands 60s → 10s, raised grace 6 → 4 (smallest value still separable from the 2s default at
SECONDS' 1-second granularity).Two assertions were added: the non-numeric-grace case now checks it lands near the 2s default, not merely that it exits 124 — a grace loop ignoring the value entirely would have satisfied the old check.
The IGNORER comment claimed "killing this script tears it down with it… none left behind at the end." Measurably false on the fallback path; corrected in place. The child shape is kept deliberately — semgrep spawns workers, so a fixture whose children outlive it is the representative case, and #350's fix will need it.
Verification
PATH=/usr/bin:/bin— the stock-macOS path CI actually takes, since CI has no coreutilstimeout137→124normalization fails the expiry caseskill -KILLescalation fails 6 assertions including both new wall-clock ones — the shortened 10s command is still long enough to expose an escalation that never lands-S infoclean under canonical config, with its own known-bad gateNot in this PR
The hook defect is #350, filed not fixed. Its correct known-bad gate is an assertion that a timed-out command's children are gone — red against current main. A red test cannot merge, and gating it with a SKIP would reproduce #345's false-OK. It needs its own PR with a #258-style race analysis.
Advances #301.
https://claude.ai/code/session_011awg91UvzUos9YoXHJ2e8B