ci: fix the hunt's fatal shell bug and retract a wrong root-cause story

Review found two HIGH defects. Both confirmed independently before fixing.

1. The Classify step would have failed on EVERY run and produced no summary.

I wrote `set -uo pipefail  # NOT -e`. GitHub's default shell is `bash -e {0}`, and
that line does not turn errexit OFF — it only ADDS pipefail. So any category counting
zero makes grep exit 1, pipefail propagates it through the pipeline, the command
substitution inherits it, and errexit kills the step. The all-clean case — the result
this workflow most wants to report — dies on the FIRST counter.

    bash -e -c 'set -uo pipefail; x=$(echo hi | grep -c nomatch); echo REACHED'
      -> exit=1, "REACHED" never printed
    bash -e -c 'set +e -u -o pipefail; ...; echo REACHED'
      -> REACHED, x=0

Now `set +e -u -o pipefail`, with the reason in the file so nobody "tidies" it back.
Verified by EXECUTING the extracted step under `bash -e` against real logs:
exit=0, 2836 bytes of summary. My stated verification was `bash -n`, which is a pure
syntax check and structurally cannot catch this. And because workflow_dispatch requires
the file on the default branch, the workflow could not have been run end-to-end before
merge — so nothing else would have caught it either.

2. The Node 22 story was a misattribution, and I had propagated it four places.

I claimed Node 22's `node:sqlite` ExperimentalWarning was read by the boot gate as
"server did not start", invalidating an earlier Linux run. The warning is real; the
causal claim is false. The predicate is

    ltWait(() => buf.out.includes("listening on") || buf.exit != null)

stdout only. `buf.err` appears in the assertion MESSAGE, never in the condition, so a
stderr warning cannot fail it. Review also ran the full suite on Node 22.23.1: 462
passed, 0 failed, with the warning present in the logs.

What actually produced that noise floor is something I had already measured and then
failed to connect: pre-#204 fixed ports gave 246 EADDRINUSE and only 42/200 clean runs
on unmodified main. The warning was merely VISIBLE in the failure text — via
buf.err.slice(0,200) — and I read presence in the error message as causation. That is
the same error I have been correcting in others' findings all week.

The cost was not cosmetic: the input description told the next person that Node 22 was
confounded, which would have made them discard a perfectly usable arm. Node 22 is now
offered plainly, and the file states the correction so the wrong story does not survive
in the artifact that outlives this PR.

Also from review:

- `ref` input (MED-1): a null result on current main is uninterpretable, because #204
  may already have fixed #203. Hunting `7f15921^` is the positive control.
- inputs go through `env:` (MED-2): free-text inputs were interpolated straight into the
  script body. GitHub documents `inputs.*` as untrusted. Added `type: number`.
- #203's SIGNATURE, not its test name (MED-3): a CPU-starved runner blows the 9s ltWait
  and emits the same "✗ boot gate REFUSES" line. #203 is closed=true + non-zero exit +
  EMPTY stderr. Both counters are reported; the difference is contention. Demonstrated
  live — a gate-mutation run scored gate=1, sig=0.
- full histogram instead of a hand-maintained category table: an enumerated list silently
  drops the failure nobody thought of, which on a hunt is the interesting one. Bucketed on
  a 72-char name prefix, NOT `sed 's/:.*//'` as suggested — test names contain colons, so
  that collapses every `localToolsSafetyError: <case>` into one bucket (verified).
- per-run `timeout 300` and step-level timeout (MED-4), `permissions: contents: read`,
  a `concurrency:` group, Node 25 in the choices.
- "15 concurrent server.mjs children" was wrong: 15 is TOTAL spawns; peak is 11-12
  (review measured 11 x3, I measured 12) because the gate test's 3 cases and the 2 epoch
  boots are awaited serially. Corrected.
- dropped the ephemeral-port note: after #204 ports come from ltFreePort(), so it is
  stale and the inference now runs backwards.

server.mjs: unchanged (CI-only; ALIGNMENT.md requires no cli.js citation).

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8
This commit is contained in:
2026-07-27 21:09:31 +10:00
co-authored by Claude Opus 5
parent 553c53621a
commit be7c545c21
+101 -69
View File
@@ -1,45 +1,69 @@
name: flake hunt (#203) name: flake hunt (#203)
# Manual only. This never runs on push or PR — it exists to reproduce a flake that has # Manual only. This never runs on push or pull_request, so it costs nothing until asked for.
# been seen FOUR times, always on Linux CI, and never once on macOS (0/1000+ across two
# independent experiments). The suspected variables are the platform and the Node version,
# so both are inputs.
# #
# Background: an attempt to run this on a Linux VM was invalidated because Node 22 emits a # #203 has been seen four times, always on Linux CI, never on macOS. This is the instrument
# `node:sqlite` ExperimentalWarning on stderr, which the boot gate read as "server did not # for reproducing it deliberately instead of by chance on someone else's PR.
# start" — ~23 of 50 runs failed spuriously. That is exactly why `node` is an input here
# rather than pinned: 22-vs-24 is a comparison worth running deliberately, not an accident
# to stumble into. Interpret any 22 result against that known confound.
# #
# Concurrency is the load-bearing knob, not round count. test-features.mjs makes test() # WHAT IS AND IS NOT KNOWN ABOUT THE NOISE FLOOR — read before interpreting any result.
# fire-and-forget for async bodies, so one suite run already spawns 15 concurrent # An earlier Linux VM attempt was reported as invalidated by Node 22's `node:sqlite`
# `server.mjs` children across 11 ltBoot tests; running several suites at once is what # ExperimentalWarning. That attribution was WRONG and is corrected here so nobody acts on it:
# multiplies cross-process contention. See AGENTS.md § "Testing: reaching faults inside # the boot predicate is `buf.out.includes("listening on") || buf.exit != null` — stdout only.
# server.mjs". # `buf.err` appears in the assertion MESSAGE, never in the condition, so a stderr warning
# cannot fail that assertion. It was visible in the failure text and mistaken for the cause.
# The real noise floor was pre-#204 fixed ports: that branch's control arm measured 246
# EADDRINUSE and only 42/200 clean runs on unmodified main. #204 removed it. Node 22 is
# therefore a PERFECTLY USABLE arm — the suite passes 462/0 under it — and is offered below.
#
# Concurrency is the knob, not round count: test() is fire-and-forget for async bodies, so one
# suite run peaks at ~11-12 concurrent server.mjs children (15 total spawns; the gate test's
# 3 cases and the 2 epoch boots are awaited serially, so they never overlap). Several suites
# at once is what multiplies cross-process contention. See AGENTS.md § "Testing: reaching
# faults inside server.mjs".
on: on:
workflow_dispatch: workflow_dispatch:
inputs: inputs:
ref:
description: 'Commit/branch to hunt on. Use 7f15921^ for the PRE-#204 tree — see the note below.'
default: ''
node: node:
description: 'Node major version (24 = what CI and released OCP run; 22 has the SQLite stderr confound)' description: 'Node major version'
default: '24' default: '24'
type: choice type: choice
options: ['24', '22', '26'] options: ['24', '22', '25', '26']
rounds: rounds:
description: 'Rounds; each round runs <concurrency> suites at once and waits' description: 'Rounds; each round runs <concurrency> suites at once and waits'
default: '25' default: '50'
type: number
concurrency: concurrency:
description: 'Concurrent suite processes per round (this is the knob that reproduces)' description: 'Concurrent suite processes per round (this is the knob that reproduces)'
default: '4' default: '4'
type: number
# `ref` exists because a null result on current main is UNINTERPRETABLE. #204 may already have
# fixed #203 — if it did, 0/200 on main cannot be told apart from "didn't hunt hard enough" or
# "wrong configuration". Running 7f15921^ (pre-#204) is the positive control: reproducing there
# and not on main establishes both the mechanism and the fix. Hunt the control first.
permissions:
contents: read
# Two dispatches of this would otherwise run concurrently and contend with each other, which is
# the one variable the experiment is trying to control.
concurrency:
group: flake-hunt-${{ github.ref }}
cancel-in-progress: false
jobs: jobs:
hunt: hunt:
name: 'hunt: node ${{ inputs.node }} x ${{ inputs.rounds }} rounds x ${{ inputs.concurrency }}' name: 'hunt: node ${{ inputs.node }} x ${{ inputs.rounds }} x ${{ inputs.concurrency }}'
runs-on: ubuntu-latest runs-on: ubuntu-latest
timeout-minutes: 60
steps: steps:
- uses: actions/checkout@v4 - uses: actions/checkout@v4
with:
ref: ${{ inputs.ref }}
- uses: actions/setup-node@v4 - uses: actions/setup-node@v4
with: with:
@@ -47,26 +71,30 @@ jobs:
- name: Record the environment - name: Record the environment
run: | run: |
set -euo pipefail set +e -u -o pipefail
{ {
echo "ref $(git rev-parse HEAD) ($(git log -1 --format=%s | cut -c1-60))"
echo "node $(node --version)" echo "node $(node --version)"
echo "kernel $(uname -srm)" echo "kernel $(uname -srm)"
echo "cpus $(nproc)" echo "cpus $(nproc)"
echo "ephemeral $(cat /proc/sys/net/ipv4/ip_local_port_range)" echo "ephemeral $(cat /proc/sys/net/ipv4/ip_local_port_range)"
} | tee env.txt } | tee env.txt
# The ephemeral range matters: the fixed ports this suite used before #204
# (39321-39364) sit INSIDE Linux's default 32768-60999 but OUTSIDE macOS's
# 49152-65535, which is independent support for "CI is more exposed than a Mac".
- name: Hunt - name: Hunt
timeout-minutes: 50
env:
# Inputs go through env, never interpolated into the script body: GitHub documents
# `inputs.*` as untrusted, and a free-text field spliced into shell is injectable.
ROUNDS: ${{ inputs.rounds }}
CONC: ${{ inputs.concurrency }}
run: | run: |
set -uo pipefail # NOT -e: a failing suite run is the DATA, not an error set +e -u -o pipefail # a failing suite run is the DATA, not a step failure
mkdir -p logs mkdir -p logs
R=${{ inputs.rounds }} for r in $(seq 1 "$ROUNDS"); do
C=${{ inputs.concurrency }} for c in $(seq 1 "$CONC"); do
for r in $(seq 1 "$R"); do # Per-run timeout: without it a single hung child blocks `wait` until the step
for c in $(seq 1 "$C"); do # timeout and the whole hunt yields nothing.
npm test > "logs/r${r}c${c}.log" 2>&1 & timeout 300 npm test > "logs/r${r}c${c}.log" 2>&1 &
done done
wait wait
printf '.' printf '.'
@@ -76,70 +104,74 @@ jobs:
- name: Classify - name: Classify
if: always() if: always()
run: | run: |
set -uo pipefail # `set +e` is load-bearing, NOT decoration. GitHub's default shell is `bash -e {0}`,
# and `set -uo pipefail` does not turn errexit off — it only ADDS pipefail. Every
# category that counts ZERO makes grep exit 1, pipefail propagates it, and errexit
# kills the step before it writes any summary. The all-clean case — the one this
# workflow most wants to report — dies first. Verified: identical script exits 1 with
# 0 bytes of summary under `bash -e`, and 0 with a full summary under `set +e`.
set +e -u -o pipefail
# EVERY pattern is anchored on the failure marker AND on the test's name, because total=$(ls logs/*.log 2>/dev/null | wc -l | tr -d ' ')
# the categories cross-contaminate otherwise. ltDiag samples the first 900B of the
# child's stdout (PR #204), which is the boot banner — so a log where only the GATE
# test failed still contains the string "Local tools: ON", and an unanchored
# `grep -l 'Local tools'` scores it as an announcement failure too. Verified against
# real logs: 3 clean runs + 1 gate-mutation run gave
# unanchored 'Local tools' -> 1 hit, attributed to the WRONG category
# anchored -> gate=1, announce=0 (correct)
# A diagnostic that quotes the program's own output makes substring classification
# unsound; anchor on what the runner prints, not on what the child printed.
n() { grep -l "✗.*$1" logs/*.log 2>/dev/null | wc -l | tr -d ' '; }
total=$(ls logs/*.log | wc -l | tr -d ' ')
clean=$(grep -l ', 0 failed ===' logs/*.log 2>/dev/null | wc -l | tr -d ' ') clean=$(grep -l ', 0 failed ===' logs/*.log 2>/dev/null | wc -l | tr -d ' ')
# A category scoring 0 has NOT been proven absent — it may simply not fire in this # #203's SIGNATURE, not just its test name. A CPU-starved runner (4 vCPU carrying
# configuration. Only a non-zero count is evidence. # ~44 node processes at concurrency 4) can blow the 9s ltWait and produce the same
gate=$(n 'boot gate REFUSES') # "✗ boot gate REFUSES" line with closed=false / (still open). That is contention,
tui=$(n 'announced INERT') # not #203. The real one is: the child CLOSED, exited non-zero, and stderr was EMPTY.
announce=$(n 'BOOTS past the gate') sig=$(grep -l '✗.*boot gate REFUSES.*closed=true.*stderr(0B)' logs/*.log 2>/dev/null | wc -l | tr -d ' ')
# These two are runtime errors rather than named tests, so they are matched on the gate=$(grep -l '✗.*boot gate REFUSES' logs/*.log 2>/dev/null | wc -l | tr -d ' ')
# error string anywhere in the log, not on a ✗ line.
eaddr=$(grep -l 'EADDRINUSE' logs/*.log 2>/dev/null | wc -l | tr -d ' ')
enotempty=$(grep -l 'ENOTEMPTY' logs/*.log 2>/dev/null | wc -l | tr -d ' ')
{ {
echo "## flake hunt — node ${{ inputs.node }}" echo "## flake hunt — node ${{ inputs.node }}"
echo echo
echo '```' echo '```'
cat env.txt cat env.txt 2>/dev/null || echo "(env.txt missing — the Record step did not run)"
echo '```' echo '```'
echo echo
echo "| category | runs affected |" echo "| | runs |"
echo "|---|---|" echo "|---|---|"
echo "| **clean (0 failed)** | **$clean / $total** |" echo "| **clean (0 failed)** | **$clean / $total** |"
echo "| #203 boot gate | $gate |" echo "| #203 **signature** (gate + closed=true + stderr 0B) | **$sig** |"
echo "| #199 TUI inert warning | $tui |" echo "| gate test failed, any cause (includes contention) | $gate |"
echo "| \`Local tools\` announce | $announce |"
echo "| EADDRINUSE | $eaddr |"
echo "| ENOTEMPTY teardown | $enotempty |"
echo echo
echo "\`sig\` is the number that answers #203. \`gate\` minus \`sig\` is runner contention."
echo "A zero is not proof of absence — only a non-zero count is evidence." echo "A zero is not proof of absence — only a non-zero count is evidence."
echo
# Full histogram instead of a hand-maintained category list: a category table
# silently drops every failure nobody thought to enumerate, and on a hunt the
# unenumerated failure is exactly the interesting one.
# Bucket on a fixed-width prefix of the test NAME, not on `sed 's/:.*//'` — test
# names contain colons, so cutting at the first one collapses every
# `localToolsSafetyError: <case>` into one useless bucket. 72 chars keeps the
# cases apart while still stripping the per-run assertion detail.
echo "### every failing assertion, by test"
echo '```'
grep -h '✗' logs/*.log 2>/dev/null | sed 's/^ *✗ //' | cut -c1-72 | sort | uniq -c | sort -rn | head -25
echo '```'
} >> "$GITHUB_STEP_SUMMARY" } >> "$GITHUB_STEP_SUMMARY"
# Surface the diagnostics inline so a repro is readable without downloading. # Prefer a log carrying the actual signature; fall back to any failing log.
# ltDiag prints exit/signal/closed/closeMs/node plus both streams (PR #204). first=$(grep -l '✗.*boot gate REFUSES.*closed=true.*stderr(0B)' logs/*.log 2>/dev/null | head -1)
if [ "$clean" -lt "$total" ]; then [ -z "$first" ] && first=$(grep -L ', 0 failed ===' logs/*.log 2>/dev/null | head -1)
echo "### first failing run" >> "$GITHUB_STEP_SUMMARY" if [ -n "$first" ]; then
echo '```' >> "$GITHUB_STEP_SUMMARY" {
grep -h '✗' $(grep -L ', 0 failed ===' logs/*.log | head -1) | head -20 >> "$GITHUB_STEP_SUMMARY" echo "### $first"
echo '```' >> "$GITHUB_STEP_SUMMARY" echo '```'
grep -h '✗' "$first" | head -20
echo '```'
} >> "$GITHUB_STEP_SUMMARY"
fi fi
- name: Upload logs - name: Upload logs
if: always() if: always()
uses: actions/upload-artifact@v4 uses: actions/upload-artifact@v4
with: with:
name: flake-hunt-node${{ inputs.node }} name: flake-hunt-node${{ inputs.node }}-${{ github.run_attempt }}
path: | path: |
logs/ logs/
env.txt env.txt
retention-days: 14 retention-days: 14
# This job does NOT fail on a reproduction. Reproducing is the goal, and a red X # This job does NOT fail on a reproduction. Reproducing is the goal, and a red X would
# would read as "the hunt is broken" rather than "the flake was caught". # read as "the hunt is broken" rather than "the flake was caught".