fix(cli): drain run-dev.js stderr before oclif exits on top of the unbuilt-workspace diagnostic (#14051)

* wip(cli): drain stderr before the failure path exits

* wip(cli): case 4 reproduces the stalled-parent truncation

* chore(cli): changeset for the stderr drain fix

* fix(cli): bound the stderr drain by progress, not by a deadline that never armed

* fix(cli): derive the drain bound from measured runtime; pin the mirror case

* chore(cli): changeset reflects the progress bound

---------

Co-authored-by: Claude <noreply@anthropic.com>

Author: claude[bot]

.changeset/run-dev-stderr-drain-before-exit.md

@@ -0,0 +1,31 @@
+---
+'@objectstack/cli': patch
+---
+
+`bin/run-dev.js` now waits for its stderr writes to reach the pipe before oclif's
+`handle()` exits on top of them, and bounds that wait by PROGRESS rather than by a
+deadline.
+
+The unbuilt-workspace diagnostic (`objectstack: NOT A MISSING COMMAND` plus the one
+build command that fixes it) is written after ~138 KB of oclif `ModuleLoadError`
+blocks, because `settings.debug` is on for this entry point. A pipe holds 64 KiB and
+`handle()` ends in `process.exit()`, which drops whatever has not drained — so a
+parent that is slow to read got exactly one buffer and lost the diagnostic *and*
+oclif's own `command … not found`. Measured against a stalled reader: 64721 bytes
+captured, both lines gone. Interactively it never reproduced, because a TTY is
+written synchronously. This is the #6531 defect (`src/utils/format.ts`, `emitJson`)
+on stderr instead of stdout, fixed the way that module prescribes — at the write,
+since there is no hook between `handle()`'s `console.error` and its `process.exit`.
+
+⚠️ Waiting is only safe if something bounds the wait. The bound is a NO-PROGRESS
+window, not a deadline: a deadline cannot tell a reader that is merely slow from one
+that is absent, and those want opposite answers. A live reader keeps draining however
+slowly (measured worst case: a vitest worker's event loop never stalled beyond 61 ms
+under real suite load); an absent one drains nothing, ever. Exceeding the bound
+degrades to the prompt-but-lossy behaviour this file had before the drain existed —
+never to a hang.
+
+Scope: `bin/run-dev.js` is the repo's SOURCE entry point, used by gates and e2e
+suites; it is not published (`files` names only `dist`, and the `bin` target is
+`bin/run.js`). The shipped binary's failure path writes one short line with no
+backlog ahead of it and is not affected.

packages/cli/bin/run-dev.js

@@ -13,12 +13,115 @@
 // exactly as it did.
 import { flush, handle, run, settings } from '@oclif/core';
 
+/**
+ * How long stderr may make NO PROGRESS before this shim stops waiting for it.
+ *
+ * A wall-clock deadline is the wrong instrument: it cannot tell a reader that
+ * is merely SLOW from one that is ABSENT, and those two want opposite answers —
+ * the slow one must be waited for (it is the whole point of this file), the
+ * absent one must never be (nobody is reading, so the bytes are worthless).
+ * Progress separates them exactly: a live reader keeps draining however slowly,
+ * an absent one drains nothing, ever.
+ *
+ * ## Where the number comes from — re-derive it, do not bump it
+ *
+ *   • A live reader under real load never stalled longer than **61 ms**: two
+ *     samples of a vitest worker's event loop while this package's e2e suite
+ *     ran beside it (12 680 and 9 663 samples of a 10 ms timer; p999 = 24/25 ms,
+ *     max = 61/57 ms).
+ *   • The stall that actually loses these bytes has to span the CLI's WHOLE
+ *     RUN, not just an instant: the bulk (~138 KB of oclif warnings) is emitted
+ *     during `Config.load()`, the diagnostic ~3 s later, and the bytes are only
+ *     lost if the child exits while the reader is away. So the bound must
+ *     outlast a whole run. Measured child runtime: **1.0 s idle, 6.9 s on a
+ *     contended box** (same container, other agents building).
+ *
+ * 15 s is ~2.2x that worst measured runtime, so a stall long enough to cause
+ * the bug is still waited out, and ~245x the worst measured live-reader stall,
+ * so a merely slow reader is never cut off.
+ *
+ * ⚠️ Exceeding the bound degrades to the behaviour this file had BEFORE the
+ * drain existed — lossy, but prompt. It can never degrade to a hang, which is
+ * the property that matters: the failure this replaced was unbounded.
+ */
+const STDERR_DRAIN_STALL_MS = 15_000;
+
+/** How often progress is sampled — comfortably under the 61 ms above. */
+const STDERR_DRAIN_POLL_MS = 50;
+
+/**
+ * Write to stderr and WAIT for the bytes to reach it.
+ *
+ * ⚠️ `process.stderr.write(x)` followed by an exit is the #6531 defect, and
+ * this shim had it. When stderr is a **pipe** node buffers the write
+ * 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.
+ * 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.
+ *
+ * The `write` callback fires only once this chunk **and everything queued ahead
+ * of it** has been handed to the pipe, so awaiting it drains that backlog too —
+ * which is what leaves an empty buffer for `handle()`'s own write. The fix
+ * belongs at the write rather than at the exit because there is no hook between
+ * `handle()`'s `console.error` and its `process.exit`.
+ *
+ * ⛔ 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.
+ */
+function writeStderr(text) {
+  return new Promise((resolve) => {
+    let poll;
+    let settled = false;
+    const finish = () => {
+      if (settled) return;
+      settled = true;
+      clearInterval(poll);
+      resolve();
+    };
+
+    // ⛔ The return value is deliberately NOT consulted. `write()` returns true
+    // when the internal buffer sits below the highWaterMark, which is NOT the
+    // same as the bytes having reached the pipe — and an earlier version of this
+    // shim read it as "already flushed" and returned early. Measured: it
+    // returned TRUE with writableLength = 7621, so the bound meant to cap the
+    // wait was never armed at all and a reader that never drained hung the
+    // process indefinitely (observed alive at 25 s, 30 s and 60 s). The
+    // callback is the only thing that means "flushed"; it also fires on EPIPE,
+    // which is what releases the closed-reader paths promptly.
+    process.stderr.write(text, finish);
+
+    let fewestPending = process.stderr.writableLength;
+    let lastProgressAt = Date.now();
+    poll = setInterval(() => {
+      const pending = process.stderr.writableLength;
+      if (pending < fewestPending) {
+        fewestPending = pending;
+        lastProgressAt = Date.now();
+        return;
+      }
+      if (Date.now() - lastProgressAt >= STDERR_DRAIN_STALL_MS) finish();
+    }, STDERR_DRAIN_POLL_MS);
+
+    // ⛔ NOT unref'd, on purpose. `finish()` always clears it, so it cannot
+    // outlive the wait — and an unref'd detector is exactly the silent no-op
+    // this function already shipped once: a bound that never runs is
+    // indistinguishable from one that never trips.
+  });
+}
+
 /** See `bin/run.js` — the same lazy import, against `src/` instead of `dist/`. */
 async function announceInvocationFailure(error) {
   try {
     const { invocationFailureLine } = await import('../src/utils/invocation.ts');
     const line = invocationFailureLine(error, process.argv.slice(2));
-    if (line) process.stderr.write(`${line}\n`);
+    if (line) await writeStderr(`${line}\n`);
   } catch {
     // Stay quiet rather than replacing oclif's report with an error about the
     // reporter itself.
@@ -53,9 +156,10 @@ async function announceUnbuiltWorkspace(error) {
       import('../../../scripts/cli-unbuilt-workspace-lead.mjs'),
       import('../src/utils/invocation.ts'),
     ]);
-    for (const line of unbuiltWorkspaceLines(error, moduleLoadFailures, INVOCATION_PREFIX) ?? []) {
-      process.stderr.write(`${line}\n`);
-    }
+    // One write, so the drain that matters happens once, immediately before
+    // `handle()` gets its turn at the same pipe.
+    const lines = unbuiltWorkspaceLines(error, moduleLoadFailures, INVOCATION_PREFIX) ?? [];
+    if (lines.length) await writeStderr(`${lines.join('\n')}\n`);
   } catch {
     // Stay quiet rather than replacing oclif's report with an error about the
     // reporter itself.

packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts

@@ -42,10 +42,34 @@
  * (1) without (2) would pass in a tree where every run happens to be diagnosed;
  * (2) and (3) without (1) are two zero readings. Together they say the branch is
  * reachable, is not always taken, and is taken for the right reason.
+ *
+ * ## (4) — the same run, read by a parent that is not draining
+ *
+ * Cases 1-3 read the child through an `execFile` whose event loop is free, and
+ * that is the one reader for which this diagnostic was never at risk. The merge
+ * queue is not that reader: it runs the full suite sharded, and a worker whose
+ * loop is starved stops draining its children for seconds at a time.
+ *
+ * What that costs is measurable and was measured. `settings.debug` puts ~138 KB
+ * of oclif `ModuleLoadError` blocks on stderr AHEAD of the lead lines; a pipe
+ * holds 64 KiB; and `handle()` ends in `process.exit()`, which Node documents as
+ * dropping whatever has not drained. With the parent's loop blocked, an unfixed
+ * `run-dev.js` delivers exactly one buffer — 64764 bytes measured — and loses
+ * BOTH the lead lines and oclif's own `command … not found`, which is the pair
+ * of assertions that reds in the queue. It is the #6531 defect
+ * (`src/utils/format.ts`, `emitJson`) on stderr instead of stdout, and it is
+ * invisible interactively, where stderr is a TTY and written synchronously.
+ *
+ * ⚠️ The stall has to block the LOOP, not merely pause the stream. A paused
+ * `child.stderr` still lets node fill its own 64 KiB readable buffer, so the
+ * kernel's buffer stops being the only absorber, ~128 KiB of headroom swallows
+ * the whole run and the case passes against unfixed code — measured, and the
+ * reason this is written the way it is. `Atomics.wait` blocks without spinning,
+ * so the stall costs no CPU on a shared runner.
  */
 
 import { describe, it, expect, beforeAll, afterAll } from 'vitest';
-import { execFile } from 'node:child_process';
+import { execFile, spawn } from 'node:child_process';
 import { mkdtempSync, rmSync } from 'node:fs';
 import { tmpdir } from 'node:os';
 import { join, resolve } from 'node:path';
@@ -94,6 +118,92 @@ function runCli(args: string[], cwd: string, nodeOptions: string | undefined): P
   });
 }
 
+/**
+ * One pipe buffer on Linux — what a truncated capture comes out at, and the
+ * floor case 4 has to clear for its reading to mean anything.
+ */
+const PIPE_BUFFER_BYTES = 65_536;
+
+/**
+ * How long case 4 refuses to drain. Two constraints pin it, and the ORDER is
+ * the whole design:
+ *
+ *   worst measured child runtime (6.9 s)  <  STALL_MS  <  the shim's
+ *   no-progress bound (`STDERR_DRAIN_STALL_MS`, 15 s in `bin/run-dev.js`)
+ *
+ * Below the child's runtime the control cannot bite: the bulk of stderr is
+ * emitted during `Config.load()` and the diagnostic ~3 s later, so a stall that
+ * ends first lets the tail out and the case passes against unfixed code.
+ * Above the shim's bound the fixed child correctly gives up, and the case would
+ * red against a WORKING fix.
+ *
+ * ⚠️ Both failure directions have actually happened here. 4 s was tried and the
+ * ablation against base came back GREEN — the case had silently stopped
+ * discriminating once a contended box pushed child runtime past it. A slow
+ * continuous reader was tried instead and failed the other way: it drains the
+ * bulk long before the tail is written, so the tail meets an EMPTY pipe and
+ * nothing is ever lost. Only a stall spanning the whole run reproduces this.
+ */
+const STALL_MS = 10_000;
+
+/**
+ * Ceiling for case 5: comfortably above the worst child runtime plus the shim's
+ * 15 s bound (~22 s measured), so reaching it means a HANG rather than a wait.
+ */
+const UNREAD_HARD_CAP_MS = 40_000;
+
+interface Lifetime {
+  code: number | null;
+  signal: NodeJS.Signals | null;
+  elapsedMs: number;
+}
+
+/**
+ * Run the CLI against a pipe that is never drained, and report only how the
+ * process ENDED. Nothing is read, so the kernel's 64 KiB is the whole absorber
+ * and the child hits real backpressure it can never clear.
+ */
+function runCliAgainstDeadReader(
+  args: string[],
+  cwd: string,
+  nodeOptions: string,
+  mode: 'never-read' | 'destroy-read-end',
+): Promise<Lifetime> {
+  return new Promise((resolvePromise) => {
+    const child = spawn(TSX, [CLI, ...args], {
+      cwd,
+      env: childEnv({ NO_COLOR: '1', NODE_OPTIONS: nodeOptions }),
+      stdio: ['ignore', 'ignore', 'pipe'],
+    });
+    const pipe = child.stderr;
+    if (!pipe) throw new Error('stderr was not piped');
+    if (mode === 'destroy-read-end') pipe.destroy();
+    else pipe.pause();
+
+    const started = Date.now();
+    // Ours, and it must be the ONLY thing that can end a hang — a child that
+    // reaches it is the failure this case exists to catch.
+    const cap = setTimeout(() => child.kill('SIGKILL'), UNREAD_HARD_CAP_MS);
+    child.once('exit', (code, signal) => {
+      clearTimeout(cap);
+      resolvePromise({ code, signal, elapsedMs: Date.now() - started });
+    });
+  });
+}
+
+/**
+ * Run the CLI and DO NOT read it for `STALL_MS`, by blocking this thread.
+ *
+ * `Atomics.wait` rather than a spin loop: it parks the thread instead of
+ * burning a core, which matters on a runner that is already the reason this
+ * case exists. Nothing else in this file shares the worker while it is parked.
+ */
+async function runCliWhileParentStalls(args: string[], cwd: string, nodeOptions: string): Promise<Run> {
+  const run = runCli(args, cwd, nodeOptions);
+  Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, STALL_MS);
+  return run;
+}
+
 /** The sentence this change exists to contradict. */
 const LEAD = 'objectstack: NOT A MISSING COMMAND';
 const FIX = 'objectstack: Fix: pnpm exec turbo run build --filter=@objectstack/spec';
@@ -102,13 +212,19 @@ let dir: string;
 let unbuilt: Run;
 let built: Run;
 let genuinelyMissing: Run;
+let stalled: Run;
+let unread: Lifetime;
+let closedEnd: Lifetime;
 
 beforeAll(async () => {
   dir = mkdtempSync(join(tmpdir(), 'os-run-dev-unbuilt-'));
   unbuilt = await runCli(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`);
   built = await runCli(REAL_COMMAND, dir, undefined);
   genuinelyMissing = await runCli(['definitely-not-a-command'], dir, undefined);
-}, RUN_TIMEOUT_MS * 3);
+  stalled = await runCliWhileParentStalls(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`);
+  unread = await runCliAgainstDeadReader(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`, 'never-read');
+  closedEnd = await runCliAgainstDeadReader(REAL_COMMAND, dir, `--import ${UNBUILT_HOOK}`, 'destroy-read-end');
+}, RUN_TIMEOUT_MS * 6);
 
 afterAll(() => {
   rmSync(dir, { recursive: true, force: true });
@@ -158,3 +274,71 @@ describe('the same probe, un-simulated (positive control)', () => {
     expect(genuinelyMissing.code).toBe(2);
   });
 });
+
+describe('the same probe, read by a parent that stalls (the merge-queue shape)', () => {
+  it('delivers more than the one buffer a stalled pipe holds', () => {
+    // THE control for the three cases below, and not a restatement of them: the
+    // measured failure was a capture of exactly one buffer, so clearing that
+    // line is what makes the string assertions evidence about DRAINING rather
+    // than about a run that happened to be short. Unfixed, this reads 64764.
+    expect(Buffer.byteLength(stalled.stderr)).toBeGreaterThan(PIPE_BUFFER_BYTES);
+  });
+
+  it('still names the real cause and the one command that fixes it', () => {
+    expect(stalled.stderr).toContain(LEAD);
+    expect(stalled.stderr).toContain('@objectstack/spec');
+    expect(stalled.stderr).toContain(FIX);
+  });
+
+  it("still carries oclif's own report, which is written after ours and exits on top of it", () => {
+    // Not ours to print, and the reason the fix is a DRAIN rather than a
+    // reordering: `handle()` writes this and calls `process.exit` immediately,
+    // so it survives only because awaiting our own write had already emptied
+    // the buffer ahead of it. This assertion reds in the queue beside the lead
+    // line — and a formatter that had merely failed to LOAD could not have
+    // removed it, which is what rules that reading out.
+    expect(stalled.stderr).toContain('Error: command i18n:extract:nope.ts not found');
+    expect(stalled.code).toBe(2);
+  });
+});
+
+describe('the mirror direction: a reader that is never coming back', () => {
+  /**
+   * ⚠️ This case exists because the first fix for the stalled reader above
+   * introduced a HANG here, and every instrument written for that fix pointed
+   * the other way. Waiting for a drain is only safe if something bounds the
+   * wait, and the bound has to be OBSERVED rather than assumed: the version
+   * 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.
+   */
+  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.
+    expect(unread.signal).toBeNull();
+    expect(unread.code).toBe(2);
+    expect(unread.elapsedMs).toBeLessThan(UNREAD_HARD_CAP_MS);
+  });
+
+  // ⛔ There is deliberately NO assertion here that the child WAITED for the
+  // bound before exiting, though an earlier version of this file had one. It
+  // is not sound: whether the tail finds bytes still pending — and so whether
+  // the bound is needed at all — depends on how much of the ~138 KB backlog
+  // the kernel and node's own readable buffer happened to absorb, which moves
+  // with load. Measured on one contended run the child exited at 7653 ms
+  // having never needed the bound; on another, with 7621 bytes still pending,
+  // the unfixed shim hung instead. Asserting the wait would red on the first
+  // run and pass on the second, which is a flake, not a pin. What this case
+  // pins is the property that actually matters and holds either way: the
+  // process ENDS. That the bound itself runs and trips is shown out of band,
+  // by tracing a run whose reader blocks its loop for the whole run — see the
+  // PR for the `BOUND TRIPPED` trace.
+
+  it('a CLOSED read end is released at once, not held for the bound (EPIPE reaches the callback)', () => {
+    // Pins the fast path measured alongside the hang: when the reader is gone
+    // rather than idle, the write callback fires with EPIPE and the wait ends
+    // immediately. A future change to the bound must not quietly make the
+    // closed-reader paths pay it.
+    expect(closedEnd.signal).toBeNull();
+    expect(closedEnd.elapsedMs).toBeLessThan(STALL_MS);
+  });
+});