From 1727827692aef9251d67b788f8b0a3f09ac458db Mon Sep 17 00:00:00 2001 From: os-dev Date: Tue, 8 Sep 2026 19:08:31 +0000 Subject: [PATCH] docs(cli): name the writer that actually made the first failing stderr write `bin/run-dev.js` explained #14858's crash with "oclif's `displayWarnings()` makes the first write". Re-traced with a `--import` observer that wraps `process.stderr.write` and logs the call site of the first EPIPE-ing call: node's OWN default `warning` handler (`internal/process/warning.js`: `onWarning` -> `writeOut` -> `console.error`) makes write #1, and `displayWarnings()` makes writes #2 and #3 of the same warning. Every write on that path is a `console.error`, and the reason that is fatal here while `bin/run.js` measured it harmless is not payload size. Console's `ignoreErrors` keep-alive is installed by the write CALLBACK and only `if (stream.listenerCount('error') === 0)`. `tsx` registers an off-thread module-customization hook, so node pipes the hooks worker's stderr into `process.stderr` and `Stream.prototype.pipe` prepends an `onerror` there; the count is 1, the keep-alive never installs, `onerror` takes the first EPIPE and re-emits it with nothing listening. Controls, node 22.22.2, read end destroyed, one variable between the legs: `console.error` alone 0/3, `module.register()` of a no-op hook plus the same `console.error` 3/3, raw `process.stderr.write` 3/3. The shim as shipped is 0/3 (exit 2); with the #14858 listener ablated it is 3/3 (exit 1). Comment text only. No behaviour changes, the listener stays exactly as it is, and the three `displayWarnings()` sites that state listener TIMING rather than authorship are untouched. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015QE8qk46e5CHJxyQEUjbf8 --- .changeset/cli-epipe-writer-attribution.md | 14 +++++ packages/cli/bin/run-dev.js | 55 ++++++++++++++----- packages/cli/bin/run.js | 19 +++++-- .../run-dev-unbuilt-workspace.e2e.test.ts | 12 ++-- 4 files changed, 78 insertions(+), 22 deletions(-) create mode 100644 .changeset/cli-epipe-writer-attribution.md diff --git a/.changeset/cli-epipe-writer-attribution.md b/.changeset/cli-epipe-writer-attribution.md new file mode 100644 index 0000000000..7bf44f215e --- /dev/null +++ b/.changeset/cli-epipe-writer-attribution.md @@ -0,0 +1,14 @@ +--- +"@objectstack/cli": patch +--- + +`bin/run.js` no longer states Node's `console.error` protection as an unconditional fact — it is conditional, and the condition is a property of the process's listener census rather than of `console.error`. + +The docblock over that file's `process.stderr` `error` listener explained the last row of its measurement table with "`ignoreErrors` … parks a temporary `error` listener across the write — so oclif's warning blocks cannot crash this process at any size". Both halves needed correcting, and only the second one was visible: + +- The listener parked *across* the write is not what saves anything. `kWriteToConsole`'s `finally` removes it before the completion arrives. What keeps the process alive is Console's write CALLBACK re-attaching a `noop`, and it does that only `if (stream.listenerCount('error') === 0)`. +- That count is 0 on this entry point and is not universal. `bin/run-dev.js` runs under `tsx`, which registers an off-thread module-customization hook; node pipes that worker's stderr into `process.stderr` and `Stream.prototype.pipe` prepends its own `onerror` there. With the count at 1 the keep-alive is never installed, `onerror` takes the first EPIPE and re-emits it with nothing listening, and **one short `console.error` crashes the process 3/3** — no payload size involved. + +Measured on node 22.22.2 against a destroyed read end, one variable changed between the legs: `console.error` alone 0/3, `module.register()` of a no-op hook plus the same `console.error` 3/3, a raw `process.stderr.write` 3/3. + +Comment text only. No behaviour, no accepted arguments, no exported member and no runtime contract changes; the listener itself, its name and the pin that waits for it are untouched. It publishes because npm packs a `bin` target regardless of `files[]` (#14874) — measured: the tarball ships `bin/run.js` verbatim and the corrected prose is in it — which is why this is a `patch` rather than a `skip-changeset`. diff --git a/packages/cli/bin/run-dev.js b/packages/cli/bin/run-dev.js index 79570d698f..4cadd9dccf 100644 --- a/packages/cli/bin/run-dev.js +++ b/packages/cli/bin/run-dev.js @@ -63,11 +63,15 @@ const STDERR_DRAIN_POLL_MS = 50; * asynchronously and `process.exit` tears the process down with the buffer only * partly drained; `src/utils/format.ts` carries the whole argument for stdout * (`emitJson`). One thing makes it worse here: `settings.debug` is on, so - * oclif's `displayWarnings()` has already queued ~138 KB of `ModuleLoadError` - * blocks AHEAD of these lines. Measured on the #12964 repro with a reader that - * was not draining: the pipe delivered exactly one 64 KiB buffer and everything - * after it was lost — this diagnostic AND oclif's own `command … not found`, - * which `handle()` writes a moment later and which the same tear-down takes. + * ~143 KB of `ModuleLoadError` blocks is already queued AHEAD of these lines — + * three quarters of it from oclif's `displayWarnings()` and the rest from node's + * OWN default `warning` handler, which stays attached and prints every warning + * as well (#16691, drained run: 147 729 bytes over 179 writes, 111 751 of them + * from `config.js`, 35 133 from `internal/process/warning.js`). Measured on the + * #12964 repro with a reader that was not draining: the pipe delivered exactly + * one 64 KiB buffer and everything after it was lost — this diagnostic AND + * oclif's own `command … not found`, which `handle()` writes a moment later and + * which the same tear-down takes. * That is why the merge queue saw it and a developer's terminal never does: a * TTY is written synchronously, a captured pipe is not. * @@ -374,15 +378,18 @@ if (!process.env.TSX_TSCONFIG_PATH) { * * `process.stderr` is an `EventEmitter`, and an `error` event with nothing * listening IS an uncaught exception. With the parent's read end DESTROYED - * (`stdio: ['ignore', 'ignore', 'pipe']`, then `child.stderr.destroy()`) - * oclif's `displayWarnings()` makes the first write, the pipe is already gone, - * node raises `write EPIPE` on `process.stderr`, and this process died of an - * uncaught exception — 12 of 12 runs, 938-1174 ms in, well before `run()` - * settles and before `writeStderr()` above is ever called. Traced with a - * `--import` observer that installs NO listener on this stream and wraps no - * write (`uncaughtExceptionMonitor`, which observes without preventing the - * default crash — an `uncaughtException` handler would have changed the very - * thing being read): + * (`stdio: ['ignore', 'ignore', 'pipe']`, then `child.stderr.destroy()`) the + * first write comes from node's OWN default `warning` handler + * (`internal/process/warning.js`: `onWarning` → `writeOut` → `console.error`), + * and oclif's `displayWarnings()` makes writes 2 and 3 of the same warning + * (#16691 re-traced the order; #15558 named `displayWarnings()` for the first + * one). The pipe is already gone, node raises `write EPIPE` on + * `process.stderr`, and this process died of an uncaught exception — 12 of 12 + * runs, 938-1174 ms in, well before `run()` settles and before `writeStderr()` + * above is ever called. Traced with a `--import` observer that installs NO + * listener on this stream and wraps no write (`uncaughtExceptionMonitor`, which + * observes without preventing the default crash — an `uncaughtException` handler + * would have changed the very thing being read): * * uncaughtException code=EPIPE msg=write EPIPE * at afterWriteDispatched (node:internal/stream_base_commons:159:15) @@ -395,6 +402,26 @@ if (!process.env.TSX_TSCONFIG_PATH) { * tell "the command failed" from "the CLI crashed", on the only channel it had * left. * + * ⚠️ EVERY write on that path is a `console.error`, which is worth stating + * because it reads as if it should be survivable — `bin/run.js` records that + * Console's `ignoreErrors` keeps a warning block from crashing a process, and + * THERE it does. What saves a process is not the temporary listener + * `kWriteToConsole` parks across the write (its `finally` removes that one + * before the completion arrives) but Console's write CALLBACK, which re-attaches + * a `noop` when the completion reports an error — and only + * `if (stream.listenerCount('error') === 0)`. Under `tsx` that count is never 0: + * tsx registers an off-thread module-customization hook, so node pipes the hooks + * worker's stderr into `process.stderr` and `Stream.prototype.pipe` prepends its + * own `onerror` there (`node:internal/streams/legacy`). Console's keep-alive is + * therefore never installed; `onerror` takes the first EPIPE, tears the pipe's + * own listeners down including itself, finds no other `error` listener left and + * RE-EMITS on `process.stderr` — that second emit is the uncaught one. + * Ablated on plain node, one short line and nothing else changed: `console.error` + * alone 0/3, `module.register()` of a no-op hook plus the SAME `console.error` + * 3/3, a raw `process.stderr.write` 3/3 (#16691). ⇒ Payload size decides nothing + * here, and this listener is what covers the `console.error` sites too, not only + * `writeStderr()` above. + * * ⛔ Deliberately NOT narrowed to `error.code === 'EPIPE'`, even though EPIPE is * the only code this path was measured to raise (4 events per run, no other * code, observed with a listener installed on purpose for that one question). diff --git a/packages/cli/bin/run.js b/packages/cli/bin/run.js index 84b3f2b6ba..e522731ad6 100755 --- a/packages/cli/bin/run.js +++ b/packages/cli/bin/run.js @@ -102,10 +102,21 @@ try { * at one write 1 ms before exit, and at 59 warning blocks whose EPIPE * arrives synchronously inside the write. * • a RAW `process.stderr.write`. Node's `console.error` carries - * `ignoreErrors`, which parks a temporary `error` listener across the write - * — so oclif's warning blocks cannot crash this process at any size - * (measured: 1 MiB through `console.error` does not, one line through - * `process.stderr.write` does, 3/3 each). + * `ignoreErrors`: its write CALLBACK re-attaches a `noop` `error` listener + * when the completion reports one — so oclif's warning blocks cannot crash + * this process at any size (measured: 1 MiB through `console.error` does + * not, one line through `process.stderr.write` does, 3/3 each). + * + * ⚠️ That protection is CONDITIONAL, and the condition is a fact about THIS + * process rather than about `console.error`: the callback re-attaches only + * `if (stream.listenerCount('error') === 0)`. Here nothing else ever listens + * — measured, the only `error` listener on `process.stderr` for a whole run + * is this file's own, below. `bin/run-dev.js` runs under `tsx`, which + * registers an off-thread module-customization hook; node pipes that + * worker's stderr into `process.stderr`, `Stream.prototype.pipe` prepends an + * `onerror` there, the count is 1, the keep-alive is never installed, and + * ONE SHORT `console.error` crashes 3/3 (#16691). ⛔ So "a `console.error` + * site needs no guard" is never a general reading of this paragraph. * * `os serve` is both: `printDiagnostic` in `src/commands/serve.ts` writes * straight to stderr (#7915) and the boot around it is asynchronous, so the 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 16ec1c16e8..e1a844a5d2 100644 --- a/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts +++ b/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts @@ -461,10 +461,14 @@ describe('the mirror direction: a reader that is never coming back', () => { // anyone contracted — and #14858 is the card that changed the CLI. ⛔ This // was not a broken test and the flip is not a regression. // - // What the child USED TO DO with its read end destroyed: oclif's - // `displayWarnings()` makes the first stderr write, the pipe is already - // gone, node raises `write EPIPE` as an `error` event on `process.stderr`, - // NOTHING WAS LISTENING, and the process died of an uncaught exception — + // What the child USED TO DO with its read end destroyed: node's OWN default + // `warning` handler makes the first stderr write and oclif's + // `displayWarnings()` the next two (#16691 re-traced the order — and every + // write on this path is a `console.error`, which is NOT the guard here that + // it is on `bin/run.js`; the docblock over the listener in `bin/run-dev.js` + // carries why). The pipe is already gone, node raises `write EPIPE` as an + // `error` event on `process.stderr`, NOTHING WAS LISTENING, and the process + // died of an uncaught exception — // exit 1, 938-1174 ms in, 12 of 12 runs, traced with a `--import` observer // that installed no listener here and wrapped no write. `writeStderr()` was // never called at all, so the bound this case was once named after was