Skip to content

test: read every report before asserting on the stub - #26

Merged
omartelo merged 1 commit into
mainfrom
fix/hook-test-flake-under-load
Sep 13, 2026
Merged

omartelo merged 1 commit into
mainfrom
fix/hook-test-flake-under-load

Conversation

@omartelo

Copy link
Copy Markdown
Collaborator

Fixes the flake noted in #24: <script> posts an accepted payload failing with sent 0 requests, expected 1 under load. Test-only, for 0.13.1; no CHANGELOG entry, since no user of a released plugin felt it.

Cause

The harness, not the scripts. Instrumenting curl (-w timings) on a failing run:

curl connect=0.000129 pretransfer=0.000180 ttfb=0.000000 total=1.000234 code=000
rc=28

curl connected and sent the whole request in under a millisecond, then waited out its 1s for an answer. The kernel completes the handshake and buffers the body without the stub's process running, so the report did reach the stub's socket, and a real lich would have read it. What failed is the ordering in the test process: when it wakes, the child's exit and the pending connection are both ready, and runHook resolved on the exit before the stub had accepted the connection, let alone read it. The assertion then counted 0.

So the product behaviour is correct (the hook gave up rather than stall the turn, with its report delivered), and the scripts' --max-time 1 is unchanged.

Fix

startStub gets settle(), and runHook (plus the one test that spawns directly) calls settleStubs() after the child closes: one more connection to the stub drains its listen queue, which is FIFO, and every accepted socket closing means its request was read. No deadline and no expected count per call site, and a 0 requests assertion can no longer pass just because the report had not been read yet.

Measurements

Busy loops on every core did not reproduce it on this machine (kernel 7.2 CachyOS, 20 cores): 0 of 20 hooks.test.mjs runs with 60 loops, 0 of 10 full-suite runs with 60, 0 of 10 with 300, and none under CPUQuota down to 1%. The scheduler keeps short wakeups (sh, curl, an idle stub) well inside 1s there; the hook p99 reached ~816ms only at 200 loops.

The reliable reproduction starves exactly the process the stub lives in: node tests/hooks.test.mjs under a SIGSTOP 1.2s / SIGCONT 0.3s cycle, 20 runs of the whole file (124 cases) each side:

runs failed failing cases
before 19 of 20 58
after 1 of 20 1

Unloaded, the file's duration is unchanged (~1.8s both ways).

The one remaining case is session-title reported once per session stops scanning, and it is not this bug. report-title.sh latches only on a report lich answered (curl -sf), so when the stub cannot answer within 1s the script rightly does not latch and the second call reports again. That needs the stub starved past the whole budget during that one call, and making it pass would mean asserting a latch the product must not write.

Test plan

  • node --test tests/*.test.mjs: 198 pass
  • Before/after under the same freeze cycle, 20 runs each (table above)
  • 60 busy loops, 20 runs after: 0 failures

A hook exiting does not mean the stub has read its report. When the test
process is starved past curl's --max-time 1, curl gives up with the request
already sent, and the child's exit can reach the event loop before that
connection is accepted, so the test counted 0 requests.

runHook now settles the stub first: one more connection drains the FIFO
listen queue, then every accepted socket closing means its request was read.
@omartelo
omartelo merged commit 14ca8cd into main Sep 13, 2026
3 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant