diff --git a/.changeset/run-dev-stderr-blocking-write-hang.md b/.changeset/run-dev-stderr-blocking-write-hang.md new file mode 100644 index 0000000000..e8174fd4c7 --- /dev/null +++ b/.changeset/run-dev-stderr-blocking-write-hang.md @@ -0,0 +1,37 @@ +--- +"@objectstack/cli": patch +--- + +fix(cli): `run-dev.js` can no longer freeze in the kernel when its stderr reader stops reading + +Over an unbuilt workspace with the read end of its output alive but not being +drained, the dev entry point is contracted to give up and exit 2 rather than +wait. Intermittently it did neither: it stayed alive past every ceiling and +ended only when something killed it — 27 of 30 runs on a cold `tsx` transform +cache, against 1 of 90 on a warm one. + +The bound that was supposed to stop it (`STDERR_DRAIN_STALL_MS`, polled by a +50 ms `setInterval`) was not late; it was unreachable. Sampled from outside the +process, the main thread was parked inside `write(2)` on fd 2 with `O_NONBLOCK` +clear on that file description, so the event loop was not running and no timer, +callback or promise in the file could fire. No ceiling of any size separates +that from a wait, which is why raising and re-deriving one never helped. + +The flag is not stable and nothing in this repo clears it: node sets +`O_NONBLOCK` when it opens the pipe, and libuv clears it again in the pre-exec +of any child spawned with inherited stdio — and because inheriting is `dup2`, +the flag lives on an open file description the spawner shares, so the spawner +loses it too. Under `tsx` that child is the esbuild service, started when a +module has to be transformed, which is why a fresh CI checkout hits this and a +warm developer box almost never does. Measured on one run: `O_NONBLOCK` true at +102 ms, false at 1132 ms in the same sample the esbuild service appears in, main +thread in `write(2)` from 2730 ms and never out of it. + +`bin/run-dev.js` now re-asserts non-blocking mode on the write path before each +stderr write, which cannot be outrun by a later spawn the way a one-shot at +startup can. This is the inverse of the `setBlocking(true)` both this file and +`src/utils/format.ts` refuse: it is what keeps their shared premise — that a +write to a pipe gets buffered rather than parking the thread — true. + +`bin/` is not named in this package's `files`, so only `bin/run.js` (the `bin` +target) is packed: no published byte changes here. diff --git a/packages/cli/bin/run-dev.js b/packages/cli/bin/run-dev.js index a4fd1001a4..147b8b952d 100644 --- a/packages/cli/bin/run-dev.js +++ b/packages/cli/bin/run-dev.js @@ -13,6 +13,8 @@ // exactly as it did. import { flush, handle, run, settings } from '@oclif/core'; +import { keepStderrNonBlocking } from './stderr-nonblocking.mjs'; + /** * How long stderr may make NO PROGRESS before this shim stops waiting for it. * @@ -74,6 +76,15 @@ const STDERR_DRAIN_POLL_MS = 50; * ⛔ Deliberately NOT `process.stderr._handle.setBlocking(true)`: `format.ts` * records why — the same binary runs `os serve` / `os dev`, and a blocking * write to a pipe with a slow reader stalls the event loop. + * + * ⚠️ That last sentence is also this function's own PREMISE, not just a reason + * to avoid a call: a bound enforced by a `setInterval` is worth nothing if a + * write can park the thread. The premise is not free — libuv clears + * `O_NONBLOCK` on fd 2's shared description in the pre-exec of any child + * spawned with inherited stdio, and this shim runs under `tsx`, which spawns + * the esbuild service on a cold transform cache. `keepStderrNonBlocking()`, + * installed above `run()`, is what holds the premise true; without it this + * bound is unreachable rather than late, which is a HANG and not a long wait. */ function writeStderr(text) { return new Promise((resolve) => { @@ -169,6 +180,21 @@ async function announceUnbuiltWorkspace(error) { process.env.NODE_ENV = 'development'; settings.debug = true; +// ⚠️ BEFORE `run()`, and that order is the whole point rather than tidiness. +// The bound in `writeStderr` is a `setInterval`, so it can only fire while this +// process's event loop is running — and every byte oclif is about to put on +// stderr is written by `Config.load()`, long before this file gets control +// back. If one of those writes parks the main thread inside `write(2)`, no +// bound in this file has run yet or ever will: the process is frozen in the +// kernel with the diagnostic still unwritten, and only a reader or a kill ends +// it. Measured that way on an unbuilt workspace with the reader gone — 27 of 30 +// cold-cache runs, main thread in `write(2)` on fd 2 at `sock_alloc_send_pskb`, +// still alive at a 90 s ceiling. `stderr-nonblocking.mjs` carries the whole +// derivation, including who clears the flag (a child spawned with inherited +// stdio — libuv clears `O_NONBLOCK` on the SHARED open file description) and +// why the re-assert has to sit on the write path rather than run once here. +keepStderrNonBlocking(); + const running = run(process.argv.slice(2), import.meta.url); // ⚠️ ATTACHED AFTER `run()`, and that order is load-bearing rather than style. diff --git a/packages/cli/bin/stderr-nonblocking.mjs b/packages/cli/bin/stderr-nonblocking.mjs new file mode 100644 index 0000000000..e6c8ab2938 --- /dev/null +++ b/packages/cli/bin/stderr-nonblocking.mjs @@ -0,0 +1,109 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * Keep this process's stderr writes off the BLOCKING path for the whole run. + * + * `bin/run-dev.js` bounds how long it waits for stderr to drain, and the bound + * is enforced by a 50 ms `setInterval`. That instrument — and every other + * timer, callback and promise in the process — only exists while the event loop + * is running, so the bound is worth exactly as much as the premise underneath + * it: that a write to a pipe nobody is reading gets BUFFERED rather than + * parking the thread inside `write(2)`. + * + * ## The premise is not free, and it was measured false + * + * Node makes that premise true when it opens the pipe: `uv_pipe_open()` sets + * `O_NONBLOCK` on fd 2 the moment `process.stderr` is first touched. What is + * easy to miss is that libuv CLEARS it again in the pre-exec of every child + * spawned with inherited stdio (`uv__process_child_init` does exactly that for + * fds 0-2, deliberately, because a child expects blocking stdio) — and since + * inheriting is `dup2`, the child shares the parent's OPEN FILE DESCRIPTION. + * The flag lives on the description, not on the fd number, so clearing it for + * the child clears it for the SPAWNER TOO. + * + * Measured on one `os dev`-shaped run over an unbuilt workspace, sampling + * `/proc/PID/fdinfo/2` from outside the process every 50 ms: + * + * ``` + * 102ms pid=19236 O_NONBLOCK=true (process.stderr materialised) + * 1132ms pid=19236 O_NONBLOCK=false (esbuild service spawned; same sample) + * 1132ms pid=19248 …/@esbuild/linux-x64/bin/esbuild --service=… + * 2730ms pid=19236 O_NONBLOCK=false inWrite=true + * ``` + * + * and from there the main thread never left `write(2)`: + * + * ``` + * pid=19236 state=S syscall=1(write) args=0x2,…,0x244 wchan=sock_alloc_send_pskb + * tid=19236 (node) syscall=1(write) ← the MAIN thread + * ``` + * + * With the loop parked in the kernel there is no late timer to catch up: the + * no-progress bound is not slow, it is UNREACHABLE, and no ceiling of any size + * distinguishes that from a wait. The process ends only when someone reads the + * pipe or kills it. That is the hang. + * + * ⚠️ Nothing in the spawn is ours. The service is esbuild's, spawned by `tsx` + * when it has to transform a module, which is why this reproduces on a COLD + * transform cache (a fresh CI checkout) and almost never on a warm developer + * box: measured 27 of 30 cold against 1 of 90 warm. + * + * ## Why the re-assert is on the WRITE path and not done once at startup + * + * Because the clearing happens at 1132 ms and is caused by a spawn this process + * does not control or even know about. 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 it was meant to prevent. Re-asserting + * immediately before each write costs one `fcntl` and cannot be outrun by a + * later spawn, whoever makes it. + * + * ## ⛔ This is not the prohibited call, it is its inverse + * + * `run-dev.js` and `src/utils/format.ts` both refuse + * `_handle.setBlocking(TRUE)`, and that refusal stands: forcing blocking writes + * process-wide is what stalls `os serve` / `os dev` on its own logs. This + * function forces the other direction — it is the thing that KEEPS those two + * docblocks true when something else has quietly flipped the flag. + * + * ⛔ It does not touch a TTY. A terminal is written synchronously on POSIX by + * design, has no unread-reader failure mode (the reader is a human's terminal), + * and prompt-adjacent output would change behaviour for no benefit. + */ + +/** Marks the stream so a second install cannot stack wrappers. */ +const INSTALLED = Symbol.for('objectstack.stderr-nonblocking'); + +/** + * @param {NodeJS.WriteStream} [stream] The stream to guard; defaults to + * `process.stderr`. Parameterised for the pin, which drives the guard against + * a manufactured blocking pipe rather than waiting for a cold cache. + * @returns {boolean} `true` when this process's writes are now guarded, + * `false` when there was nothing to guard (a TTY, a file, a stream with no + * libuv handle). The boolean is returned rather than logged: a reporter that + * announces itself on the very stream it is repairing is the one thing this + * file must not do. + */ +export function keepStderrNonBlocking(stream = process.stderr) { + if (!stream || stream.isTTY === true) return false; + const handle = stream._handle; + if (!handle || typeof handle.setBlocking !== 'function') return false; + if (stream[INSTALLED]) return true; + + const write = stream.write; + if (typeof write !== 'function') return false; + + stream[INSTALLED] = true; + stream.write = function guardedWrite(...args) { + // One `fcntl`, immediately ahead of the syscall that would otherwise park + // this thread. Wrapped because a stream that lost its handle mid-run must + // still take the write — a repair that throws is worse than the defect. + try { + handle.setBlocking(false); + } catch { + // Nothing to say and nowhere safe to say it. + } + return write.apply(this, args); + }; + return true; +} diff --git a/packages/cli/test/fixtures/stderr-nonblocking-probe.mjs b/packages/cli/test/fixtures/stderr-nonblocking-probe.mjs new file mode 100644 index 0000000000..923b1ba134 --- /dev/null +++ b/packages/cli/test/fixtures/stderr-nonblocking-probe.mjs @@ -0,0 +1,107 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * The hazard `bin/stderr-nonblocking.mjs` exists for, MANUFACTURED rather than + * waited for — driven by `run-dev-stderr-nonblocking.e2e.test.ts`. + * + * ⚠️ The reason this fixture exists at all is that the real occurrence is + * INTERMITTENT: over the real CLI it reproduced 27 of 30 runs on a cold `tsx` + * transform cache and 1 of 90 on a warm one. A pin that drove the real child + * would therefore be green most of the time on a developer box while the defect + * was fully present — a test that only fails intermittently is not a pin. So + * this fixture reproduces the CONDITION deterministically and in ~200 ms: + * + * 1. materialise `process.stderr`, which is when node opens the pipe and sets + * `O_NONBLOCK` on it — the state every healthy run starts in; + * 2. spawn a trivial child with INHERITED stdio. libuv clears `O_NONBLOCK` on + * fds 0-2 in the child's pre-exec, and inheriting is `dup2`, so the flag — + * which lives on the shared open file description — is cleared for THIS + * process too. In the real defect this spawn is the esbuild service that + * `tsx` starts when it has to transform a module; nothing about the + * mechanism needs it to be esbuild; + * 3. write far past every buffer on the path (2 MiB, against ~128 KiB of + * kernel pipe plus the parent's own readable buffer) to a reader that is + * never coming back. + * + * With the flag cleared, step 3 parks the MAIN THREAD inside `write(2)` and the + * event loop stops: no timer, no callback, no bound of any kind can run, and the + * process ends only when someone reads the pipe or kills it. With the guard + * installed, the same writes queue in userland and the process exits on its own. + * + * Every step announces itself into a MARKER FILE rather than onto stderr — + * stderr is the thing under test and, in the failing arm, the thing that is + * blocked. The markers are what let the harness tell "froze at the write" from + * "was still booting", so its verdict never rests on wall clock alone. + * + * argv: ` guarded|unguarded` + */ + +import { spawnSync } from 'node:child_process'; +import { appendFileSync, readFileSync } from 'node:fs'; + +import { keepStderrNonBlocking } from '../../bin/stderr-nonblocking.mjs'; + +const [, , MARKS, ARM] = process.argv; +const mark = (line) => appendFileSync(MARKS, `${line}\n`); + +/** + * The flag itself, read from the kernel rather than inferred. + * + * Linux-only. `unreadable` elsewhere, and the harness treats that as "cannot + * confirm" instead of quietly assuming the hazard was armed — the one reading + * that would make the control vacuous is `true`, and only that one is refused. + */ +function nonBlocking() { + try { + const flags = /flags:\s*(\d+)/.exec(readFileSync('/proc/self/fdinfo/2', 'utf8'))?.[1]; + return flags === undefined ? 'unreadable' : String((parseInt(flags, 8) & 0o4000) !== 0); + } catch { + return 'unreadable'; + } +} + +// Touching the stream is what materialises it; `writableLength` is the cheapest +// touch that cannot itself write anything. +void process.stderr.writableLength; +mark(`START O_NONBLOCK=${nonBlocking()}`); + +spawnSync(process.execPath, ['-e', '0'], { stdio: 'inherit' }); +mark(`HAZARD O_NONBLOCK=${nonBlocking()}`); + +if (ARM === 'guarded') mark(`GUARD ${keepStderrNonBlocking()}`); + +mark('WRITING'); +const chunk = 'x'.repeat(8 * 1024); +// ⚠️ 2 MiB, and the size is a MEASUREMENT rather than a round number. A reader +// that is merely paused is not the only absorber: the kernel pipe holds 64 KiB +// and node's own readable buffer in the parent holds about another 64 KiB, so +// ~128 KiB can disappear before the writer ever meets backpressure. 192 KiB was +// tried first and the unguarded arm reached the end of its loop unblocked on +// one run in two — a control that green-lights the very hazard it exists to +// prove. 2 MiB is 16x that headroom, so no absorber on this path can swallow it. +let backpressured = 0; +for (let i = 0; i < 256; i++) { + if (process.stderr.write(chunk) === false) backpressured += 1; + // Progress, so a frozen arm shows WHERE it stopped rather than only that it + // never finished — the difference between evidence and an empty timeout. + // + // ⚠️ Every 4 chunks (32 KiB), not every 32. The block lands around chunk 16 — + // one kernel pipe plus one reader-side buffer in — so a coarser interval puts + // the FIRST marker after the freeze, and the control then reads "froze before + // any write landed" on a perfectly good reproduction. Measured that way. + if ((i + 1) % 4 === 0) mark(`WROTE ${(i + 1) * 8} KiB`); +} +// ⚠️ `pending` is reported but deliberately NOT the evidence that the bytes +// were kept. Measured: it reads 0 here even on a perfectly healthy guarded run, +// because libuv has taken every chunk into its own write queue and +// `writableLength` only counts what the STREAM still holds above the handle. +// `bytesWritten` and `destroyed` are the readings that separate "buffered" from +// "thrown away", so those are what the harness asserts on. +mark( + `WRITES RETURNED pending=${process.stderr.writableLength} bytesWritten=${process.stderr.bytesWritten} ` + + `destroyed=${process.stderr.destroyed} backpressured=${backpressured}`, +); + +// A distinctive status, so "exited on its own" is evidence about THIS file +// rather than about any process that happens to end in 0 or 1. +process.exit(7); diff --git a/packages/cli/test/run-dev-stderr-nonblocking.e2e.test.ts b/packages/cli/test/run-dev-stderr-nonblocking.e2e.test.ts new file mode 100644 index 0000000000..aa74e9d8ee --- /dev/null +++ b/packages/cli/test/run-dev-stderr-nonblocking.e2e.test.ts @@ -0,0 +1,256 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * `bin/run-dev.js` must not be able to freeze in the kernel with its diagnostic + * unwritten — the hang behind a merge queue that ejected 13 PRs and burned 22 + * queue builds before anyone could see what it was. + * + * ## What was actually wrong, and why no ceiling could have found it + * + * The shim bounds how long it waits for stderr to drain (`writeStderr`'s + * `STDERR_DRAIN_STALL_MS`, polled by a 50 ms `setInterval`). That bound — like + * every timer, callback and promise — only exists while the event loop runs. + * Measured on the failing runs, from OUTSIDE the process so the instrument + * could not perturb it: + * + * ``` + * pid=19236 state=S syscall=1(write) args=0x2,…,0x244 wchan=sock_alloc_send_pskb + * tid=19236 (node) syscall=1(write) ← the MAIN thread + * fd2 flags=02000002 O_NONBLOCK=false + * ``` + * + * There is no pending JS handle to find: the loop is parked in `write(2)` on + * fd 2 and the bound is not late, it is UNREACHABLE. That is why raising or + * re-deriving a ceiling never helped — a ceiling separates slow from stuck, and + * this was stuck at a point where nothing in the file had run yet. + * + * `bin/stderr-nonblocking.mjs` carries the mechanism in full: node sets + * `O_NONBLOCK` on fd 2 when it opens the pipe, libuv clears it again in the + * pre-exec of any child spawned with inherited stdio, and the flag lives on the + * SHARED open file description — so the spawner loses it too. Under `tsx` that + * child is the esbuild service, spawned when a module has to be transformed, + * which is why this is a cold-transform-cache defect: **27 of 30** runs of the + * real child hung on a cold cache against **1 of 90** on a warm one. + * + * ## Why this file drives a fixture and not the real CLI + * + * ⭐ Because a 27-in-30 reproduction is still not a pin. The neighbouring + * `run-dev-unbuilt-workspace.e2e.test.ts` already drives the real child, and + * its own comments record what that costs: an oracle over this hazard can come + * back green because the backlog happened to fit in what the kernel absorbed. + * A pin whose subject is intermittent is a pin that reports "fixed" on the runs + * where the defect simply did not fire. + * + * So the fixture MANUFACTURES the condition — materialise stderr, spawn a child + * with inherited stdio, write past one pipe buffer at a reader that is gone — + * and the two arms differ in exactly one thing: whether the guard is installed. + * Both arms are deterministic and cost about a second. + * + * ⛔ This file deliberately does not touch, mirror or re-assert anything in + * `run-dev-unbuilt-workspace.e2e.test.ts`. That file owns the unbuilt-workspace + * cases; this one owns the write path underneath them. + */ + +import { spawn } from 'node:child_process'; +import { mkdtempSync, readFileSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join, resolve } from 'node:path'; +import { fileURLToPath } from 'node:url'; + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; + +import { maskComments } from '../../../scripts/js-comment-mask.mjs'; +import { childEnv } from './helpers/serve-process.js'; + +const HERE = resolve(fileURLToPath(import.meta.url), '..'); +const FIXTURE = resolve(HERE, 'fixtures/stderr-nonblocking-probe.mjs'); +const SHIM = resolve(HERE, '../bin/run-dev.js'); +const GUARD = resolve(HERE, '../bin/stderr-nonblocking.mjs'); + +/** + * The one ceiling here, and it is a CONSTANT on purpose. + * + * The lesson this file is downstream of is that a ceiling derived from a + * calibration is a prediction about contention taken from a sample of the past, + * and a shared runner will not honour it — two such ceilings were beaten here + * before the last one became a constant. This one detects the same thing any + * finite ceiling detects (a process that will never end) and is far above + * anything either arm legitimately needs: the fixture is a bare `node` process + * with no dependencies beyond node builtins and one 90-line module, and its + * writes return in about a millisecond when they are not blocked. + */ +const HARD_CAP_MS = 60_000; + +/** + * How long the control arm is given AFTER it announces it is about to write. + * + * ⚠️ Read the direction of this one carefully. It is not an oracle over the + * FIX — it only decides when to stop waiting for a child that is expected to be + * frozen, and it starts counting from the child's own `WRITING` marker rather + * than from spawn, so a slow boot cannot shorten it. If it were ever too short, + * the control would call a healthy child frozen: a false GREEN in a positive + * control, never a false red in the queue. And it cannot even do that quietly, + * because an unblocked child reaches `WRITES RETURNED` in about a millisecond + * and the control asserts that marker's ABSENCE. + */ +const FREEZE_GRACE_MS = 2_000; + +interface Probe { + code: number | null; + signal: NodeJS.Signals | null; + elapsedMs: number; + marks: string; +} + +let dir: string; +let guarded: Probe; +let unguarded: Probe; + +/** + * Run the fixture against a pipe nobody reads, and report only how it ended + * plus what it managed to say through the marker file. + * + * `killAfterWriting` is what makes the frozen arm cheap: it is armed only once + * the child has said it reached the hazard. + */ +function runProbe(arm: 'guarded' | 'unguarded', killAfterWriting: boolean): Promise { + const marks = join(dir, `${arm}.marks`); + writeFileSync(marks, ''); + const readMarks = (): string => { + try { + return readFileSync(marks, 'utf8'); + } catch { + return ''; + } + }; + return new Promise((resolvePromise) => { + const child = spawn(process.execPath, [FIXTURE, marks, arm], { + env: childEnv({ NO_COLOR: '1' }), + stdio: ['ignore', 'ignore', 'pipe'], + }); + // Nothing ever reads it. ⚠️ `pause()` alone does NOT starve the child: the + // kernel pipe holds 64 KiB and node's readable buffer here absorbs about + // another 64 KiB, and a fixture writing less than that reaches its own end + // unblocked — measured, on the 192 KiB this was first written with. The + // fixture now writes 2 MiB, which is past every absorber on the path. + child.stderr?.pause(); + + const started = Date.now(); + const cap = setTimeout(() => child.kill('SIGKILL'), HARD_CAP_MS); + let grace: NodeJS.Timeout | undefined; + const poll = killAfterWriting + ? setInterval(() => { + if (!grace && readMarks().includes('WRITING')) { + grace = setTimeout(() => child.kill('SIGKILL'), FREEZE_GRACE_MS); + } + }, 50) + : undefined; + + child.once('exit', (code, signal) => { + clearTimeout(cap); + if (grace) clearTimeout(grace); + if (poll) clearInterval(poll); + resolvePromise({ code, signal, elapsedMs: Date.now() - started, marks: readMarks() }); + }); + }); +} + +beforeAll(async () => { + dir = mkdtempSync(join(tmpdir(), 'os-stderr-nonblocking-')); + unguarded = await runProbe('unguarded', true); + guarded = await runProbe('guarded', false); +}, HARD_CAP_MS * 3); + +afterAll(() => { + rmSync(dir, { recursive: true, force: true }); +}); + +describe('a stderr write must never park the event loop', () => { + it('POSITIVE CONTROL: without the guard, the same child freezes and has to be killed', () => { + // Not "it was killed" alone — that is also what a child too slow to have + // started would look like. The markers say which: it reached the hazard, + // armed it, announced the writes, and then said nothing more. + expect( + unguarded.marks, + `the control never reached the hazard, so it measured NOTHING — this is a zero reading, not a pass. Markers:\n${unguarded.marks}`, + ).toContain('WRITING'); + expect( + unguarded.marks, + `the hazard was not armed: fd 2 still had O_NONBLOCK after a spawn with inherited stdio, so this arm proves nothing about the guard. Markers:\n${unguarded.marks}`, + ).not.toContain('HAZARD O_NONBLOCK=true'); + expect( + unguarded.marks, + `the unguarded child got PAST the blocking write, so this fixture no longer discriminates and the pin below is worthless. Markers:\n${unguarded.marks}`, + ).not.toContain('WRITES RETURNED'); + expect( + unguarded.signal, + `the unguarded child ended on its own — the hazard did not bite, so the pin below has no control. Markers:\n${unguarded.marks}`, + ).toBe('SIGKILL'); + // It stopped mid-loop rather than before it: the last progress marker is + // where the main thread went into `write(2)` and did not come back. + expect( + unguarded.marks, + `the control froze BEFORE any write landed, so it is not measuring the write path. Markers:\n${unguarded.marks}`, + ).toContain('WROTE '); + }); + + it('THE PIN: with the guard, the same child issues every write and exits on its own', () => { + const evidence = `ceiling ${HARD_CAP_MS} ms (constant, load-independent by design); this child ran ${guarded.elapsedMs} ms. Markers:\n${guarded.marks}`; + // The guard reports what it did rather than being assumed to have run: on a + // TTY or a plain file there is nothing to guard and it says so, and a + // `false` here would make everything below a green over nothing. + expect(guarded.marks, `the guard declined to install itself. ${evidence}`).toContain('GUARD true'); + expect(guarded.marks, `the guarded child never finished its writes. ${evidence}`).toContain('WRITES RETURNED'); + expect(guarded.signal, `the guarded child had to be killed — it was still alive at the ceiling. ${evidence}`).toBeNull(); + expect(guarded.code, `the guarded child did not exit with its own status. ${evidence}`).toBe(7); + }); + + it('the bytes are HELD by a live stream, not thrown away to buy the exit', () => { + // ⚠️ The cheap way to make a blocking write stop blocking is to stop caring + // about the bytes — destroy the stream, or swap it for a sink — and that + // would pass every assertion above while deleting what `writeStderr` exists + // to do. So the guarded arm has to show the writes were ACCEPTED and the + // stream is intact. + // + // ⛔ Deliberately NOT asserted on `writableLength`, and the reason is a + // measurement rather than taste: it reads **0** here on a healthy guarded + // run, because libuv has taken all 192 KiB into its own write queue and + // that counter only sees what the stream still holds above the handle. An + // assertion that it is large would red on correct code — it was written + // that way first and measured wrong before this comment existed. + const written = Number(/bytesWritten=(\d+)/.exec(guarded.marks)?.[1]); + expect(written, `no bytesWritten in the markers, so this reads nothing:\n${guarded.marks}`).not.toBeNaN(); + expect(written, `the guard did not accept the writes. Markers:\n${guarded.marks}`).toBeGreaterThanOrEqual(2 * 1024 * 1024); + expect(guarded.marks, `the guard reached its exit by destroying stderr. Markers:\n${guarded.marks}`).toContain( + 'destroyed=false', + ); + }); +}); + +describe('the shim installs the guard, and installs it in time', () => { + it('calls it BEFORE run(), which is the whole of why it works', () => { + // Comments are masked first, and that is not ceremony: this file's own + // prose names the function, and `run-dev.js` names it twice in docblocks — + // an unmasked search would find those and stay green with the call deleted. + const shim = maskComments(readFileSync(SHIM, 'utf8')); + const installed = shim.indexOf('keepStderrNonBlocking('); + const started = shim.indexOf('run(process.argv.slice(2)'); + expect(shim, 'run-dev.js no longer imports the guard').toContain('./stderr-nonblocking.mjs'); + expect(installed, 'run-dev.js no longer calls keepStderrNonBlocking()').toBeGreaterThan(-1); + expect(started, 'run-dev.js no longer calls run() — this parity case is reading the wrong file').toBeGreaterThan(-1); + // oclif writes every one of its ~138 KB of warning blocks inside + // `Config.load()`, i.e. inside `run()`. A guard installed after it is a + // guard installed after the freeze. + expect( + installed, + 'the guard is installed AFTER run(), so oclif writes its warnings on the unguarded path and the hang comes back', + ).toBeLessThan(started); + }); + + it('keeps the guard where the shim can reach it without a build', () => { + // `bin/run-dev.js` exists to run from source in an UNBUILT tree; a guard + // that lived behind `dist/` would be missing in exactly the tree this whole + // suite is about. + expect(readFileSync(GUARD, 'utf8')).toContain('export function keepStderrNonBlocking'); + }); +}); diff --git a/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts b/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts index 4d94015111..131331ed37 100644 --- a/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts +++ b/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts @@ -291,13 +291,7 @@ let unbuilt: Run; let built: Run; let genuinelyMissing: Run; let stalled: Run; -// Definite-assignment assertion for the duration of the QUARANTINE below: the -// `'never-read'` spawn in `beforeAll` is commented out, so nothing assigns this -// and `strict` reports TS2454 at each of the three reads inside the skipped -// case. Restoring that spawn makes the `!` redundant again, so it goes when the -// quarantine is lifted. (Measured: the package's own `typecheck` is -// `include: ["src"]`, so it never compiles this file and would not have said.) -let unread!: Lifetime; +let unread: Lifetime; let closedEnd: Lifetime; beforeAll(async () => { @@ -306,18 +300,10 @@ beforeAll(async () => { built = await runCli(REAL_COMMAND, dir, undefined); genuinelyMissing = await runCli(['definitely-not-a-command'], dir, undefined); stalled = await runCliWhileParentStalls(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`); - // ⛔ QUARANTINED — the `'never-read'` child is NOT spawned while the case it - // feeds is skipped. See the quarantine note on - // `it.skip('gives up and exits instead of waiting forever')` further down: - // this spawn is where the 180 s `UNREAD_HARD_CAP_MS` is paid under CI load, - // and that one case is its ONLY consumer — `unread` is read nowhere else in - // this file. The PR that fixes the hang in `bin/run-dev.js` un-skips that case - // and restores these four lines verbatim, in the same change: - // - // // ⛔ Nothing measured above is consulted here. Case 1's wall clock is read by - // // the failure message below, as evidence; the ceiling is a constant, so a - // // slow sample can no longer size the instrument that judges the next run. - // unread = await runCliAgainstDeadReader(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`, 'never-read', UNREAD_HARD_CAP_MS); + // ⛔ Nothing measured above is consulted here. Case 1's wall clock is read by + // the failure message below, as evidence; the ceiling is a constant, so a + // slow sample can no longer size the instrument that judges the next run. + unread = await runCliAgainstDeadReader(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`, 'never-read', UNREAD_HARD_CAP_MS); closedEnd = await runCliAgainstDeadReader(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`, 'destroy-read-end', UNREAD_HARD_CAP_MS); }, RUN_TIMEOUT_MS * 6); @@ -406,23 +392,7 @@ describe('the mirror direction: a reader that is never coming back', () => { * this replaces armed no bound at all (`write()` returned true, so an early * return skipped it) and read as correct in every stalled-reader test. */ - // ⛔ QUARANTINED under the maintainer's ruling A of 2026-09-03 on - // objectstack#14832 — do not un-skip it on its own. - // - // WHY. The `'never-read'` child this case reads HANGS under CI load. The - // defect is in the product — `bin/run-dev.js`, the other half of #14832 — - // and NOT a cap that is set too low, so raising `UNREAD_HARD_CAP_MS` would buy - // nothing and would only make each failure slower. On `Test Core (1/6)` the - // harness SIGKILLed the child at the 180 s cap and this assertion red, and - // every occurrence EJECTED A WHOLE MERGE-QUEUE BATCH: `main` could not advance - // for hours behind this one case, which is what the ruling weighed. - // - // RE-ENABLE CONDITION. The PR that fixes the hang in `bin/run-dev.js` un-skips - // this case in the SAME change, and restores the `'never-read'` spawn in - // `beforeAll` (kept there verbatim, commented). The body below and all of its - // comments are untouched, so lifting the quarantine is `it.skip` -> `it` plus - // that one spawn line — nothing here has to be reconstructed. - it.skip('gives up and exits instead of waiting forever', () => { + it('gives up and exits instead of waiting forever', () => { // A child still alive at the cap was SIGKILLed: signal set, code null. // That is the hang, and it is the whole point of this case. //