fix(cli): stop dropping queued telemetry when process.exit races the final flush (#2970)

* fix(cli): stop dropping queued telemetry when process.exit races the final flush Two exit-path defects introduced by the 0.7.65 process-lifecycle refactor: 1. The 'exit' handler returned early once finalizeCli had started, which also skipped the flushSync() fallback. When an agent-pipe EPIPE killed the process mid-flush (the NORMAL teardown under Claude Code / Codex), the still-queued render_complete was silently dropped — fleet delivery fell from ~90% (0.7.55-0.7.64) to ~35%. flushSync() is now unconditional: empty queue is a no-op, event uuids dedupe re-sends. 2. The EPIPE handlers set commandFailed unconditionally, so every piped successful render scored success:false in cli_command_result (fleet success rate collapsed 89% -> 5-25%). EPIPE now only marks failure when the pipe died before the render artifact was validated, matching the existing isRenderSucceeded() exemption on the uncaughtException path. Regression tests cover both: flushSync-after-finalize, and EPIPE before/after artifact validation. * fix(cli): don't score a validated render as failed due to pre-artifact noise Review follow-up: commandFailed can be set by noise that precedes artifact validation — a stray unhandledRejection mid-render, or an EPIPE firing before markRenderSucceeded on a run that still completes. Once the artifact validates, that earlier noise must not flip the run's cli_command_result to success:false. Genuine failures keep a non-zero exit code and are still caught by the exitCode check. Extracted commandSucceededForTelemetry() and applied it at both tracking sites (finalizeCli and the exit handler), with a regression test. * test(cli): pin the production-reachable producer of the stale-failure override Review note: the pre-artifact-noise test drives the scenario with an EPIPE, which only reaches 'render validates afterwards' because process.exit is mocked — that sequence can't occur in production. Add a test for the reachable producer: an unhandledRejection before validation (the handler deliberately does not exit), followed by a validated render, must score success:true at exit code 0. Verified red on the pre-override cli.ts.
2026-09-01 19:42:03 +00:00 · 2026-08-04 02:02:55 +08:00
parent 3cf268e1e5
commit bc6dbc7e21
2 changed files with 190 additions and 15 deletions
@@ -67,4 +67,148 @@ describe("CLI lifecycle", () => {

    expect(order).toEqual(["cli_error", "flush"]);
  });
+
+  it("hands queued events to flushSync even after finalizeCli has run", async () => {
+    const flushSync = vi.fn();
+    const trackCommandResult = vi.fn();
+    mockInitCommand(vi.fn());
+    mockTelemetry({ flushSync, trackCommandResult });
+
+    process.argv = ["node", "cli.ts", "init", "--json"];
+    await import("./cli.js");
+    // Command finished → finalizeCli ran and tracked the result once.
+    expect(trackCommandResult).toHaveBeenCalledTimes(1);
+
+    // The process.exit() that follows fires the 'exit' handler. It must not
+    // double-track, but it MUST still hand the queue to flushSync — this is
+    // the fallback that re-delivers a render_complete whose eager flush()
+    // was killed by an EPIPE process.exit(0) racing finalizeCli. Gating it
+    // behind `finalized` was the 0.7.65 render_complete regression.
+    process.emit("exit", 0);
+    expect(trackCommandResult).toHaveBeenCalledTimes(1);
+    expect(flushSync).toHaveBeenCalled();
+  });
+
+  it("keeps an EPIPE after a validated render scored as success", async () => {
+    const trackCommandResult = vi.fn();
+    const exitSpy = vi.spyOn(process, "exit").mockImplementation((() => undefined) as never);
+    try {
+      mockInitCommand(() => emitStreamEpipe());
+      mockTelemetry({ trackCommandResult });
+
+      const successState = await import("./utils/render-success-state.js");
+      successState.markRenderSucceeded();
+      process.argv = ["node", "cli.ts", "init", "--json"];
+      await import("./cli.js");
+
+      // The pipe closing after the artifact was validated is a normal agent
+      // teardown: exit 0, and the run must NOT be scored as a failure.
+      expect(exitSpy).toHaveBeenCalledWith(0);
+      expect(trackCommandResult).toHaveBeenCalledWith(expect.objectContaining({ success: true }));
+      successState._resetRenderSuccessForTests();
+    } finally {
+      exitSpy.mockRestore();
+    }
+  });
+
+  it("does not let pre-artifact noise doom a run whose render later validates", async () => {
+    const trackCommandResult = vi.fn();
+    const exitSpy = vi.spyOn(process, "exit").mockImplementation((() => undefined) as never);
+    try {
+      const successState = await import("./utils/render-success-state.js");
+      // Noise arrives BEFORE the artifact is validated (mid-render EPIPE /
+      // stray rejection shape), then the render completes and validates.
+      mockInitCommand(() => {
+        emitStreamEpipe();
+        successState.markRenderSucceeded();
+      });
+      mockTelemetry({ trackCommandResult });
+
+      process.argv = ["node", "cli.ts", "init", "--json"];
+      await import("./cli.js");
+
+      expect(trackCommandResult).toHaveBeenCalledWith(expect.objectContaining({ success: true }));
+      successState._resetRenderSuccessForTests();
+    } finally {
+      exitSpy.mockRestore();
+    }
+  });
+
+  it("does not let a pre-validation unhandledRejection doom a validated render", async () => {
+    // The production-reachable producer of the stale-failure override: the
+    // unhandledRejection handler deliberately does NOT exit, so a stray
+    // rejection mid-render sets commandFailed (and exitCode 1), the render
+    // then completes and validates, and finalizeCli writes exit code 0.
+    const trackCommandResult = vi.fn();
+    // Detach the test runner's own unhandledRejection listeners so the
+    // synthetic emit reaches only the CLI's handler, then restore them.
+    const priorListeners = process.listeners("unhandledRejection");
+    process.removeAllListeners("unhandledRejection");
+    try {
+      const successState = await import("./utils/render-success-state.js");
+      mockInitCommand(() => {
+        process.emit("unhandledRejection", new Error("stray teardown noise"), Promise.resolve());
+        successState.markRenderSucceeded();
+      });
+      mockTelemetry({ trackCommandResult });
+
+      process.argv = ["node", "cli.ts", "init", "--json"];
+      await import("./cli.js");
+
+      expect(trackCommandResult).toHaveBeenCalledWith(
+        expect.objectContaining({ success: true, exitCode: 0 }),
+      );
+      successState._resetRenderSuccessForTests();
+    } finally {
+      process.removeAllListeners("unhandledRejection");
+      for (const listener of priorListeners) process.on("unhandledRejection", listener);
+    }
+  });
+
+  it("still scores an EPIPE before the artifact is validated as a failure", async () => {
+    const trackCommandResult = vi.fn();
+    const exitSpy = vi.spyOn(process, "exit").mockImplementation((() => undefined) as never);
+    try {
+      mockInitCommand(() => emitStreamEpipe());
+      mockTelemetry({ trackCommandResult });
+
+      process.argv = ["node", "cli.ts", "init", "--json"];
+      await import("./cli.js");
+
+      expect(exitSpy).toHaveBeenCalledWith(0);
+      expect(trackCommandResult).toHaveBeenCalledWith(expect.objectContaining({ success: false }));
+    } finally {
+      exitSpy.mockRestore();
+    }
+  });
 });
+
+function mockInitCommand(run: () => void): void {
+  vi.doMock("./commands/init.js", () => ({
+    default: {
+      meta: { name: "init" },
+      args: { json: { type: "boolean" } },
+      run,
+    },
+  }));
+}
+
+function mockTelemetry(overrides: {
+  flushSync?: ReturnType<typeof vi.fn>;
+  trackCommandResult?: ReturnType<typeof vi.fn>;
+}): void {
+  vi.doMock("./telemetry/index.js", () => ({
+    flush: vi.fn(async () => {}),
+    flushSync: overrides.flushSync ?? vi.fn(),
+    incrementCommandCount: vi.fn(),
+    showTelemetryNotice: vi.fn(),
+    shouldTrack: () => false,
+    trackCliError: vi.fn(),
+    trackCommand: vi.fn(),
+    trackCommandResult: overrides.trackCommandResult ?? vi.fn(),
+  }));
+}
+
+function emitStreamEpipe(): void {
+  process.stdout.emit("error", Object.assign(new Error("write EPIPE"), { code: "EPIPE" }));
+}
@@ -8,15 +8,16 @@
 //
 // commandFailed must be declared here (before the handlers) so the EPIPE
 // stream-error path can set it before process.exit(0). The telemetry exit
-// handler reads this flag to determine success/failure — an EPIPE exit
-// should NOT score as success:true in telemetry.
+// handler reads this flag to determine success/failure — an EPIPE that
+// interrupts a command should NOT score as success:true, but one that
+// arrives after the render artifact was validated is the normal agent-pipe
+// teardown and must stay success:true (see handleStreamEpipe).
 let commandFailed = false;

 for (const stream of [process.stdout, process.stderr]) {
  stream.on("error", (err) => {
    if ((err as NodeJS.ErrnoException).code === "EPIPE") {
-      commandFailed = true;
-      process.exit(0);
+      handleStreamEpipe();
    }
  });
 }
@@ -285,7 +286,7 @@ async function finalizeCli(result: CommandResult): Promise<void> {
  await telemetryReady.catch(() => {});
  _trackCommandResult?.({
    command,
-    success: result.exitCode === 0 && !commandFailed,
+    success: result.exitCode === 0 && commandSucceededForTelemetry(),
    exitCode: result.exitCode,
    durationMs: Date.now() - commandStart,
    runId,
@@ -320,14 +321,21 @@ process.on(
  "exit",
  // fallow-ignore-next-line complexity
  (code) => {
-    if (finalized) return;
-    _trackCommandResult?.({
-      command,
-      success: code === 0 && !commandFailed,
-      exitCode: code,
-      durationMs: Date.now() - commandStart,
-      runId,
-    });
+    if (!finalized) {
+      _trackCommandResult?.({
+        command,
+        success: code === 0 && commandSucceededForTelemetry(),
+        exitCode: code,
+        durationMs: Date.now() - commandStart,
+        runId,
+      });
+    }
+    // Unconditional — `finalized` only means finalizeCli STARTED its awaited
+    // flush(). A process.exit() racing that flush (the EPIPE path under agent
+    // pipes) kills the in-flight request, and gating this fallback behind
+    // `finalized` silently dropped the still-queued events — the 0.7.65
+    // render_complete regression. flushSync() is safe to over-call: an empty
+    // queue is a no-op, and event uuids make re-sends idempotent.
    _flushSync?.();
  },
 );
@@ -377,6 +385,30 @@ function exitAfterPostRenderTermination(
  process.exit(0);
 }

+// A closed pipe (EPIPE) is the NORMAL teardown when the CLI runs under a
+// piped agent (Claude Code, Codex, …) — the reader may stop consuming as
+// soon as it has what it needs. Exit cleanly, but only score the run as a
+// failure when the pipe died BEFORE the render artifact was validated:
+// unconditionally setting `commandFailed = true` here marked every piped
+// successful render as success:false (0.7.65–0.7.90). Delivery of anything
+// still queued (render_complete's eager flush() dies with the process) is
+// owned by the unconditional flushSync() in the `exit` handler below.
+function handleStreamEpipe(): never {
+  if (!isRenderSucceeded()) commandFailed = true;
+  process.exit(0);
+}
+
+// Success gate for the cli_command_result telemetry field. `commandFailed`
+// can be set by pre-artifact noise — a stray unhandledRejection mid-render,
+// or an EPIPE that fires before validation on a run that still completes.
+// Once the render artifact has been validated (`isRenderSucceeded()`), that
+// earlier noise must not score the run as a failure: the run delivered.
+// Genuine failures keep a non-zero exit code and are caught by the
+// `exitCode === 0 &&` half of the expression at both call sites.
+function commandSucceededForTelemetry(): boolean {
+  return !commandFailed || isRenderSucceeded();
+}
+
 // Terminate the process after a genuine CLI failure — mark commandFailed,
 // emit telemetry, flush, exit(1). Same rationale as above: keeps the arrow
 // handler linear so fallow CRAP stays under threshold.
@@ -392,8 +424,7 @@ function exitAfterCliFailure(

 process.on("uncaughtException", (error) => {
  if ((error as NodeJS.ErrnoException).code === "EPIPE") {
-    commandFailed = true;
-    process.exit(0);
+    handleStreamEpipe();
  }
  // Post-artifact-validated shutdown throws must not turn a valid render
  // into an exit-1 "no final error message" failure. The render command