Skip to content

fix(cli): stop run-dev.js freezing in write(2) when its stderr reader stops reading - #14875

Merged
os-trump merged 6 commits into
mainfrom
claude/issue-14832-run-dev-unread-reader-hang
Sep 3, 2026
Merged

fix(cli): stop run-dev.js freezing in write(2) when its stderr reader stops reading#14875
os-trump merged 6 commits into
mainfrom
claude/issue-14832-run-dev-unread-reader-hang

Conversation

@os-trump

@os-trump os-trump commented Sep 3, 2026

Copy link
Copy Markdown
Collaborator

Fixes #14832

The named blocking handle — there isn't one, and that is the finding

The card asked for the pending handle rather than a theory. Sampled from outside the process, at 20 s, 35 s and 50 s of a hung run, so the instrument could not perturb it:

pid=9659 state=S (sleeping) syscall=1(write) args=0x2,0x7ffec4c48a60,0x244
         wchan=sock_alloc_send_pskb   fd2 flags=02000002 O_NONBLOCK=false
  cmd=/opt/node22/bin/node --require .../tsx/dist/preflight.cjs
    tid=9659 (node) syscall=1(write) args=0x2,…,0x244      ← the MAIN thread

There is no pending JS handle. The main thread is parked inside write(2) on fd 2 — 580 bytes, in the kernel's pipe-send path — so the event loop is not running at all. writeStderr's 50 ms setInterval never ticks and STDERR_DRAIN_STALL_MS can never trip: the bound is not late, it is unreachable. That is why no ceiling ever helped. A ceiling separates slow from stuck, and this is stuck at a point where nothing in the file has run yet — the frozen child had written 138459 bytes (oclif's warning blocks alone) against 138868 for a clean one, so it never reached the shim's own diagnostic.

A handle dump from inside a hung child agrees: it logged nothing for 60 s, then flushed everything and exited 2 within 136 ms of node's flushStdio() resuming the parent's paused stream on child exit — released by the reader draining, which is exactly what a blocked write(2) waits for.

Why the flag is clear, and why it is intermittent

Node sets O_NONBLOCK on fd 2 when it opens the pipe. libuv clears it again in the pre-exec of every child spawned with inherited stdio (deliberately — a child expects blocking stdio), and inheriting is dup2, so the flag lives on an open file description the spawner shares: clearing it for the child clears it for the spawner. Under tsx that child is the esbuild service, started when a module has to be transformed.

Timeline of one run, /proc/PID/fdinfo/2 sampled every 50 ms:

  53ms pid=19220 O_NONBLOCK=false            tsx cli
 102ms pid=19220 O_NONBLOCK=true             (stderr materialised)
 260ms pid=19236 O_NONBLOCK=true             the CLI process
1132ms pid=19220 O_NONBLOCK=false        ┐
1132ms pid=19236 O_NONBLOCK=false        ├─ same sample: the esbuild service appears
1132ms pid=19248 …/esbuild --service=…   ┘
2730ms pid=19236 O_NONBLOCK=false inWrite=true      … and never leaves
ENDED 45005ms code=null signal=SIGKILL

⭐ That is also why it is intermittent, and the variable is not load: it is whether tsx had to transform anything.

Reproduction rate (out of band — the fenced test file was never run for this)

Driven by spawn of the same child (tsx bin/run-dev.js i18n extract nope.ts under the unbuilt-spec resolve hook), stderr piped and never read:

arm hung at the ceiling lifetimes
warm tsx cache, 6 concurrent 1 of 90 the single hit was the container's first-ever run
cold tsx cache (private TMPDIR per run), 6 concurrent 27 of 30 still alive at a 90 s ceiling; the 3 non-hits ended at 3.8 s, 10.4 s, 10.9 s
cold cache, WITH this fix 0 of 30 2.7-20.7 s, every one code=2 signal=null

Same driver, same box, same concurrency, same cold-cache condition — only the tree differs. A merge-queue runner is a fresh checkout with a cold transform cache, which is why CI hits this and a warm developer box almost never does.

The fix

packages/cli/bin/stderr-nonblocking.mjs (new) re-asserts non-blocking mode on fd 2 immediately before each stderr write; bin/run-dev.js installs it above run().

⭐ On the write path rather than once at startup, and that is measured rather than stylistic: the clearing happens at 1132 ms, caused by a spawn this process does not control and cannot see. A one-shot at module top is undone by the next spawn(…, { stdio: 'inherit' }) anywhere in the process — including from a module-hooks worker thread, which shares the same descriptions — and it fails silently, back into the hang. Re-asserting per write costs one fcntl and cannot be outrun by a later spawn, whoever makes it.

⛔ This is not the call both run-dev.js and src/utils/format.ts refuse; it is its inverse. Their refusal of setBlocking(TRUE) stands untouched. What this adds is the thing that keeps their shared premise — a write to a pipe is buffered, not blocking — actually true when something else has quietly flipped the flag.

The pin, and why it holds on a run where the hang does not reproduce

test/run-dev-stderr-nonblocking.e2e.test.ts + test/fixtures/stderr-nonblocking-probe.mjs.

A 27-in-30 reproduction is still not a pin — it reports "fixed" on the runs where the defect simply did not fire. So the fixture manufactures the condition deterministically in about a second: materialise stderr, spawn a trivial child with inherited stdio (the same clearing, without needing esbuild), then write 2 MiB at a reader that is gone. The two arms differ in exactly one thing — whether the guard is installed — and both are deterministic.

Five cases: a positive control (unguarded ⇒ freezes and must be killed), the pin (guarded ⇒ issues every write and exits 7 on its own), a substitution guard (the bytes were accepted and the stream is not destroyed — so "fixing" it by discarding output cannot pass), and two wiring cases holding that the shim still installs the guard and installs it before run(), read through maskComments so the prose naming the function cannot stand in for the call.

Two sizes in that fixture are measurements, not round numbers, and both are recorded where the next person will hit them: 192 KiB let the unguarded arm finish unblocked on one run in two (the kernel pipe plus the parent's own readable buffer absorb ~128 KiB), and a progress marker every 32 chunks landed its first mark after the freeze, so the control read "froze before any write landed" on a perfectly good reproduction.

Ablation, red-first, on the final tree — mutation proven on disk before each run (anchor 1 -> 0, marker 0 -> 1, blob moved), restored under trap … EXIT INT TERM on absolute paths and proven back by blob identity plus an empty git diff HEAD:

  • neuter the guard's re-assert ⇒ the pin reds, the guarded arm killed at the 60 s ceiling (lock held 66 s), control and wiring cases stay green;
  • delete the install call from run-dev.jsonly the wiring case reds.

No build leg is owed and that is shown, not assumed: the fixture and the guard are plain .mjs run from source by a bare node, with no dist anywhere in the path.

File face

bin/run-dev.js, a new sibling module beside it, a new test file and its fixture, and a changeset. ⛔ packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts is not touched — it is #14716's face (PR #14863). It was run against this tree as a regression check: 11 passed (11), 59.87 s.

⛔ Not done, per the card: no timeout raised, no cap re-derived, nothing skipped, quarantined or retried.

#14858 is untouched, and that is measured

#14858 is the same file with the reader closed rather than paused — an uncaught write EPIPE, exit 1 at ~1.4 s. This PR adds no error listener, so it neither fixes nor hides it. Measured on this branch after the fix: the closed-reader arm ends code=1 signal=null at 1362, 1412, 1439, 1446, 1471, 1482 ms, 6 of 6 — inside the 1387-1711 ms range #14716 measured before it. Its own card and its own PR.

Verification, on 47e92775ee (origin/main merged in)

Heavy runs through scripts/pm/os-verify-lock.sh; verdicts quoted from its VERDICT line; every exit captured by redirecting to a file first, never after a pipe.

  • Pin, 5 consecutive runs: Tests 5 passed (5), VERDICT command-exit 0 each time.
  • Neighbouring suite run-dev-unbuilt-workspace.e2e.test.ts: 11 passed (11), VERDICT command-exit 0.
  • Dependency closure built first (pnpm --filter '@objectstack/cli^...' build --concurrency=2): VERDICT command-exit 0, 443 s.
  • Gate union, re-derived on the merged tree (node scripts/pm/dispatch-gates.mjs --repo objectstack-ai/objectstack --commands — identical list before and after the merge): 35 derived, 35 run, 32 exit 0.
  • 3 of 35 are NOT MEASURED in the gates' own words — neither pass nor red: check-test-completeness.mjs exit 3 ("PREREQUISITE NOT MET — this gate grades a saved turbo run test log, and no log was named"; CI tees one); check-half-states.mjs exit 3 ("the transport authenticates but repo-scoped reads are refused" — this container gets HTTP 403 on GET /repos/…, which my own REST probe hit independently); check:dual-build-cjs-loads exit 3 ("Run pnpm build first. ⛔ This is NOT a pass: nothing was measured" — I built only the CLI's closure, not the repo).
  • Whole-repo pnpm lint (eslint . --no-inline-config): VERDICT command-exit 0, 110 s. Not narrowed.
  • pnpm check:nul-bytes: exit 0, 8076 files, 0 raw control bytes; plus a direct grep -naP control-byte scan of all five changed files (no hits).
  • Typecheck, stated honestly: packages/cli/tsconfig.json is include: ['src'], so the package's own green says nothing about a test/ file and nothing at all about bin/. The new test file was checked explicitly — tsc --ignoreConfig --noEmit --strict --module nodenext --moduleResolution nodenext --types node --listFilesexit 0, with --listFiles confirming the file is one of the 243 in that program rather than a green over nothing.

Changeset

patch on @objectstack/cli. The measurement behind the fork, since the dispatch asked: files is ['dist', 'README.md', 'CHANGELOG.md'] and does not name bin/, so npm packs only ./bin/run.js (the bin target) — bin/run-dev.js and the new module beside it are not in the tarball, and this diff changes no published bytes. patch is the conservative fork rather than an argued skip-changeset exemption; the changeset text says so, and downgrading it is a one-file edit if a reviewer prefers that.

Residue filed, not ridden

#14874 — the same mechanism on the published path: os dev (src/commands/dev.ts:221, 470, 582), os start and os environments bind all spawn with inherited stdio, so the long-lived parent puts its OWN stdout and stderr on the blocking path for the rest of the run. format.ts already names that hazard as a reason to refuse setBlocking(true) — the premise it protects is the one the CLI breaks on itself, with nothing saying so. Filed unassigned with the two measurements that would settle it, and deliberately not fixed here: it changes shipped behaviour and needs its own review, pin and changeset, which should not ride inside a p1 hang fix.


🤖 Generated with Claude Code

https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza


Generated by Claude Code

@github-actions github-actions Bot added the size/l label Sep 3, 2026
@github-actions

github-actions Bot commented Sep 3, 2026

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

This PR changes 1 package(s): @objectstack/cli, touching 2 documentable anchor(s). ⚠️ 1 changed file(s) yielded no anchor (packages/cli/bin/run-dev.js), so the pages documenting them are NOT COVERED by this run — this is not a clean bill of health for those files.

1 hand-written doc(s) NAME something this change touched and may need an implementation-accuracy re-verification:

  • content/docs/protocol/kernel/lifecycle.mdx (via INSTALLED (symbol, a top-level const object))
What this run could not see
  • 1 changed file(s) yielded no anchor (packages/cli/bin/run-dev.js) — pages documenting those are invisible to this run
  • the SDK route bridge reached 47 of 219 client-bound route-ledger rows — the other 172 have no registrar path: tail to select them, so pages documenting THEIR client methods cannot appear above, on this or any run. Of those 172: 14 are remediable by widening that discovery convention (an in-repo file declares the path; the convention did not scan it); 56 are structural — on a ledger where NOT ONE row is declared in-repo, so no discovery change reaches them at any price; 102 are undecided (no in-repo declaration, on a ledger that has other in-repo registrars — absence and an unreadable spelling are not distinguishable here). The rows themselves: node scripts/docs-audit/affected-docs.mjs --bridge-coverage
  • a page that states a rule by its inputs shares no identifier with the emitter that implements the rule, so an emitter-only diff cannot list it — not on this run and not on any run. Measured on fix(driver-sql): emit varchar(maxLength) for a text field a declared index keys on #11430: content/docs/protocol/objectql/types.mdx documents the text-family column mapping by the ObjectQL type names it maps FROM (text / textarea / html) while the diff changed createColumn; it went unlisted, and it was the page that diff falsified, in four places. No shared token exists to detect this on, so a rule your change carries has to be re-read by hand in the pages that restate it.

Coarse fallback — 22 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): node scripts/docs-audit/affected-docs.mjs --json f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8packageMentionDocs.

Which tree this was computed on

This run read content/docs from 09836a126ea99ec527a6d0adb2e328a324ea050a — the merge of head 10635c040a91c7c8878cf51cb9a7fe759bf9fac8 into base f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8, which is what actions/checkout gives a pull_request run. Not the PR head.

A worktree cut from an older main holds a different content/docs, so re-deriving there can legitimately return a different list — that is a different tree, not a wrong row. To answer on the same tree:

# while this PR is open — GitHub drops the merge commit once it closes
git fetch origin 09836a126ea99ec527a6d0adb2e328a324ea050a && git checkout 09836a126ea99ec527a6d0adb2e328a324ea050a
# afterwards, rebuild it from the two parents, which stay fetchable
git fetch origin f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8 10635c040a91c7c8878cf51cb9a7fe759bf9fac8 && git checkout -B drift-repro f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8 && git merge --no-ff 10635c040a91c7c8878cf51cb9a7fe759bf9fac8

node scripts/docs-audit/affected-docs.mjs --json f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8

⚠️ That checkout carried uncommitted changes, so the commit above does not fully identify what was read.

Advisory only, and a precision-first one (#9192): a page is listed because it names a
symbol, wire route or SDK method this diff touched — not because it mentions a changed
package. Each row says which anchor put it there, so a wrong row is reportable rather than
merely annoying. To re-verify, run the docs-accuracy-audit workflow scoped to these files:
node scripts/docs-audit/affected-docs.mjs f116b8f8d1b43ec2bfd64fbf0ebb0cf3c301b1c8 → pass the list as
args.docs, on the commit named under Which tree this was computed on.

…ng is fixed

Reverses 392f410 exactly: the `'never-read'` spawn in `beforeAll` and the
case it feeds are live again, and the definite-assignment assertion the
quarantine needed is gone with it. The file is byte-for-byte its pre-quarantine
shape (blob 131331e) — nothing else has touched it since.

Per the maintainer's ruling A (2026-09-03): the quarantine is not a resting
state, and the PR that fixes the hang re-enables the case in the same change.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza

os-trump commented Sep 3, 2026

Copy link
Copy Markdown
Collaborator Author

Round 2 — the quarantine is lifted in this PR, as maintainer ruling A requires

Head 10635c040a (was 47e92775ee). The quarantine landed on main as 392f41089b after this PR was opened, so the ruling — "the PR that fixes the hang re-enables the case in the same change" — became satisfiable, and it is now satisfied here.

origin/main merged in (⛔ merge, never rebase or force-push): merge commit 2919b74790, no conflicts anywhere, and none in run-dev-unbuilt-workspace.e2e.test.ts — nothing to stop on and hand back.

The revert is exact, and that is checked rather than asserted

392f41089b is the only commit that has touched that file since this branch's base (git log 2263ca4d67..origin/main -- <path> lists it alone), so the pre-quarantine shape is well defined. The lift is its reverse applied verbatim:

PRE-QUARANTINE blob (392f41089b^):  131331ed372a95cac88d21f80bb56762b12076e0
in my tree before the revert:       4d940151117b5150e0c4ae49ce167df6e93ca2c4
after the reverse-apply:            131331ed372a95cac88d21f80bb56762b12076e0   ← identical

byte-for-byte the pre-quarantine file. git diff origin/main on it is 6 insertions(+), 36 deletions(-) — the exact mirror of the quarantine's 36 insertions(+), 6 deletions(-). it.skip count in the file: 0.

Both halves came back, not just the assertion: the skipped case and the never-read spawn in beforeAll that only it consumes — which the quarantine comment correctly identified as where the 180 s is actually paid. The definite-assignment ! on let unread went with it, since the spawn assigns it again; that is exactly what the quarantine's own commit message said should happen when it is lifted.

⛔ Nothing else in that file was touched: no other case, no timeout, no bound, no cap.

The re-enabled case passes LIVE on the merged tree

✓ the mirror direction: a reader that is never coming back > gives up and exits instead of waiting forever
Test Files  1 passed (1)
     Tests  11 passed (11)          ← 11 of 11, zero skipped
  Duration  53.39s
VERDICT command-exit 0

53 s for the whole file. The hang it was quarantined for costs 180 s in that one case alone, so the duration is itself evidence the case is being run and not paid for.

Both readings the seat asked for, side by side: 11 of 11 on 47e92775ee (a tree that never carried the quarantine) and 11 of 11 on 10635c040a (quarantine landed, then lifted here).

Refreshed reproduction rate, same driver and same cold-cache condition

tree hung at a 90 s ceiling
unfixed 27 of 30
fixed, 47e92775ee 0 of 30
fixed, 10635c040a 0 of 30, every one code=2 signal=null

Lifetimes 5.5-28.1 s, a little wider than the earlier 2.7-20.7 s on a busier box — the number did not move, the spread did, and both are an order of magnitude inside the ceiling.

Re-verified on 10635c040a

  • Pin, 5 consecutive runs: Tests 5 passed (5), VERDICT command-exit 0 each time.
  • Dependency closure rebuilt first (the worktree was recreated for this round): VERDICT command-exit 0, 401 s.
  • Gate union re-derived — 6 paths now, the change set having grown by the reverted file; the derived list is identical to the previous 35. 35 derived, 35 run, 32 exit 0, and the same 3 NOT MEASURED in the gates' own words (check-test-completeness and check-half-states and check:dual-build-cjs-loads, all PREREQUISITE NOT MET). ⚠️ One honest note: check:type-check-debt first came back 124, which was my own timeout 250 killing it and not a verdict — re-run with room it is exit 0 (21 ledger entries re-measured in 175.3s, none above its recorded number). A 124 is NOT MEASURED, never a red.
  • Whole-repo pnpm lint: VERDICT command-exit 0, 76 s. Not narrowed.
  • pnpm check:nul-bytes: exit 0, 8078 files, 0 raw control bytes.
  • Strict typecheck of the un-quarantined file, which is the reading its quarantine commit flagged: tsc --ignoreConfig --noEmit --strict … --listFiles over both test files ⇒ exit 0, both files confirmed in the 243-file program. With the spawn restored, unread is definitely assigned again and the ! is correctly gone — the quarantine measured the pristine file at 0 errors and it is back at 0.

⛔ Unchanged: no timeout raised, no cap re-derived, nothing skipped or retried, no EPIPE listener (#14858 stays neither fixed nor hidden), and #14874 does not ride along. Still draft, auto-merge not armed.


Generated by Claude Code

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

documentation Improvements or additions to documentation size/l tests tooling

Projects

None yet

2 participants