diff --git a/packages/cli/bin/run-dev.js b/packages/cli/bin/run-dev.js index cb6337ebf4..4f8d2ed04b 100644 --- a/packages/cli/bin/run-dev.js +++ b/packages/cli/bin/run-dev.js @@ -195,6 +195,65 @@ settings.debug = true; // why the re-assert has to sit on the write path rather than run once here. keepStderrNonBlocking(); +/** + * Make a FAILED stderr write non-fatal, so a caller whose read end is gone + * still gets this CLI's own exit status instead of a crash. #14858. + * + * `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): + * + * uncaughtException code=EPIPE msg=write EPIPE + * at afterWriteDispatched (node:internal/stream_base_commons:159:15) + * exit code=1 + * + * Every OTHER reader of the same child answers **2** — drained (1209-1217 ms, + * 147699 bytes delivered) and never-read (16178-16471 ms) both did, in the same + * conditions. 2 is what oclif's `handle()` produces, and #14715 pinned it for + * the never-read reader. So the closed reader was the one shape that could not + * tell "the command failed" from "the CLI crashed", on the only channel it had + * left. + * + * ⛔ 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). + * The reason to tolerate is not WHICH error it is: every event here means one + * thing — a write to stderr failed — the only channel it could be reported on + * is the stream that just failed, and there is no other action to take. A + * predicate would buy no decision and would keep exactly this crash for + * whatever code turns up next. + * + * ⚠️ What it costs, and it is not nothing. With the write no longer fatal the + * run continues into `writeStderr()`'s drain, which for this path had NEVER + * executed at all. Ablated 2x2 on this file, one contiguous run, shared box — + * so read the ratios, not the absolutes: + * + * this listener write callback exit elapsed + * ------------- --------------- ---- --------------- + * present kept (= HEAD) 2 1237-1312 ms + * present removed 2 16271-16294 ms the 15 s bound + * absent kept 1 983-1028 ms the defect + * absent removed 1 843-1031 ms + * + * Row 1 against row 3 is the whole change, and it is ~250 ms: the child now + * ends the way a drained reader's child ends instead of dying on its first + * write. (The two runs are comparable because their unfixed rows agree — 938- + * 1174 ms above, 983-1028 ms here.) Row 2 is what the drain costs when only the + * no-progress bound can end it — a cost that is REACHABLE now and was not + * before, because rows 3-4 never got there at all. + */ +process.stderr.on('error', () => { + // Nothing to report, and nowhere left to report it. +}); + 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/test/run-dev-unbuilt-workspace.e2e.test.ts b/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts index 8c7b8f5606..16ec1c16e8 100644 --- a/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts +++ b/packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts @@ -455,60 +455,57 @@ describe('the mirror direction: a reader that is never coming back', () => { expect(Number(String(declared).replaceAll('_', ''))).toBe(SHIM_DRAIN_STALL_MS); }); - it('a CLOSED read end ends the child on its own — by an uncaught EPIPE, never by the bound', () => { - // ⚠️ This case used to read `elapsedMs < STALL_MS`, and its name used to - // say "released at once … EPIPE reaches the callback". BOTH were wrong - // about this shape, and the trace that settles it is worth more than the - // assertion it replaces. + it('a CLOSED read end ends the child on its own, with the status every other reader gets', () => { + // ⚠️ THE NUMBER BELOW MOVED FROM 1 TO 2, and this case is why it could not + // move quietly. It pinned 1 on purpose — 1 was what the CLI DID, never what + // 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 ACTUALLY does with its read end destroyed: oclif's + // 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 IS LISTENING, and the process dies of an uncaught exception — - // exit 1, ~1.4 s in. `writeStderr()` is never called, so the bound this - // case was named after is never armed, let alone paid. Traced on one box - // with a `--import` observer: the shim's own 415-byte write is #175, at - // 9250 ms, behind 174 oclif writes that all EPIPE — 7.8 s after the - // unobserved child is already dead. + // 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 + // never armed, let alone paid. (An earlier version of this case read + // `elapsedMs < STALL_MS` and was named for that bound; the wall clock went + // because its whole measured term is child cold start, which is elastic, + // and because it stayed green through the very ablation it named.) // - // ⛔ So the wall-clock bound was not merely fragile, it was a PHANTOM: it - // could not fail for the reason it named. Ablated on `bin/run-dev.js`, - // same box, same probe, with the old bound's verdict in brackets: + // `bin/run-dev.js` now attaches a no-op `error` listener to + // `process.stderr` before `run()`. A failed stderr write stops being fatal, + // the run reaches the CLI's own exit path — oclif's `handle()`, status 2 — + // and the closed reader answers what the drained and never-read readers + // already answered (#14715 pinned 2 for the never-read one). Re-measured + // for that change, one contiguous 2x2 ablation of the shim on one box, the + // listener present/absent against the `write` callback kept/removed: // - // pristine exit 1, 1387-1711 ms [green] - // write callback REMOVED, so a closed path - // could only finish on the bound — the - // regression this case named exit 1, 1517-1633 ms [GREEN] - // EPIPE made non-fatal, callback kept exit 2, 8787-8979 ms [green, 1.2 s spare] - // both, so the path really pays the bound exit 2, 23601-23712 ms [red] + // listener present, callback kept (as shipped) exit 2, 1237-1312 ms + // listener present, callback removed exit 2, 16271-16294 ms + // listener absent, callback kept (the defect) exit 1, 983-1028 ms + // listener absent, callback removed exit 1, 843-1031 ms // - // The bound moved only on lines 3 and 4, which change the EXIT CODE too; - // against its own regression it stayed green. And its whole measured term - // is child cold start, which is elastic — 1.4 s here, 8.9 s the moment - // anything lets the child run further — judged against 10 s borrowed from - // case 4's parent stall, a number with no relationship to this case. + // ⭐ The exit status is still the observation, and it still carries no load + // term. 1 means the child died on its first write and never reached the + // drain; 2 means it got through to `handle()`, which on this run is only + // reachable THROUGH `writeStderr()` — bound paid or not. BOTH rows that + // remove the listener flip it back to 1, so this line pins the fix and not + // the weather. // - // ⭐ The exit status IS the observation the wall clock was standing in for, - // and it carries no load term at all. 1 means the child died on its first - // write and never reached the drain; 2 means it got through to `handle()`, - // which is only reachable THROUGH `writeStderr()` — bound paid or not. Every - // ablation above that reaches the drain flips it, including the one the old - // assertion could not see. - // - // ⚠️ 1 is what the CLI DOES, not what anyone contracted: a caller whose - // stderr is closed gets 1 where every other reader gets 2, and cannot tell a - // failed command from a crashed CLI. Filed as #14858. If that is fixed to - // exit 2 this case reds, which is the point — the fixing PR flips the number - // here and says why. ⛔ Do not "repair" a red by loosening this to - // `not.toBeNull()`; that is the phantom check all over again. + // ⛔ Do not "repair" a red here by loosening to `not.toBeNull()`; that is + // the phantom check the wall clock already was. A red means the child is + // dying on a stderr write again — the listener is gone, or something now + // writes to stderr ahead of where it is attached. const evidence = `closed-read-end child ran ${closedEnd.elapsedMs} ms (harness cap ${UNREAD_HARD_CAP_MS} ms); ` + `case 1 measured the same child at ${unbuilt.elapsedMs} ms on this runner minutes earlier`; expect(closedEnd.signal, `the harness SIGKILLed the child — it was still alive at the ceiling. ${evidence}`).toBeNull(); expect( closedEnd.code, - `the child did not die on its first stderr write — it reached the shim's drain, so something now ` + - `tolerates EPIPE on stderr (see #14858 and the ablation table above this assertion). ${evidence}`, - ).toBe(1); + `the child did not reach the CLI's own exit path — it died on a stderr write, so nothing is making ` + + `EPIPE non-fatal on \`process.stderr\` any more (see #14858 and the ablation table above this ` + + `assertion). ${evidence}`, + ).toBe(2); }); });