Merge branch 'pr2461' into triage/backend-startup

# Conflicts:
#	CHANGELOG.md

electron/CONTRACT.md

@@ -38,8 +38,11 @@ Live dictation uses a WebSocket, which cannot pass through the app protocol HTTP
   Remove PYTHONHOME / PYTHONPATH from the child env.
 - stdio: ['pipe','pipe','pipe'] — stdin MUST stay open (never write, never end)
   until quit; closing it is the liveness signal. `windowsHide: true`.
-- Readiness: poll `/system/info` every 500 ms, budget 300 s
-  (OMNIVOICE_STARTUP_BUDGET_S). Then poll every 2 s as a supervisor.
+- Readiness: poll `/health` every 500 ms, budget 300 s
+  (OMNIVOICE_STARTUP_BUDGET_S). The budget is measured from the spawn, not
+  from the start of the launch, so resolving the runtime, staging the sources
+  and selecting a port never spend the backend's window. Then poll every 2 s
+  as a supervisor.
 - Exit code 78 = port in use (stage `port_in_use`), not a crash.
 - Quit: Windows `taskkill /pid <pid> /T /F`; POSIX spawn `detached: true` and
   `process.kill(-pid, 'SIGTERM')`, SIGKILL after 2 s; then end stdin.

electron/README.md

@@ -35,7 +35,8 @@ child's stdin is the liveness signal — closing it makes the backend exit.
 Environment knobs: `OMNIVOICE_PORT` (backend port), `VOICESTUDIO_UI_PORT`
 (renderer dev server, default 3902), `VOICESTUDIO_SKIP_BACKEND=1` (never
 spawn, only attach), `OMNIVOICE_BACKEND_CMD` (argv override, JSON array or
-whitespace-separated), `OMNIVOICE_STARTUP_BUDGET_S` (default 300).
+whitespace-separated), `OMNIVOICE_STARTUP_BUDGET_S` (default 300, measured from
+the spawn so a slow launch never spends the backend's window).
 
 ## Same-origin API
 

electron/src/main/backend-startup-budget.test.ts

@@ -0,0 +1,322 @@
+// @vitest-environment node
+import { EventEmitter } from 'node:events';
+import { afterEach, expect, it, vi } from 'vitest';
+
+/**
+ * #2445 — "Backend did not answer on port 3900 within 300 s".
+ *
+ * The readiness budget covers the backend. The launch that precedes it — the
+ * per-candidate interpreter import probe, staging the bundled sources and port
+ * selection — all run before the process exists, so charging that time to the
+ * backend left it seconds of its own window and then killed it.
+ */
+const mocks = vi.hoisted(() => ({
+  spawn: vi.fn(),
+  listen: vi.fn(),
+  close: vi.fn(),
+  /** Fake-clock milliseconds each pre-spawn step burns. */
+  prespawnMs: 0,
+  /** Ports the bind preflight reports as denied (EACCES) or taken (EADDRINUSE). */
+  denied: new Set<number>(),
+  occupied: new Set<number>(),
+  /** False simulates an unbuilt runtime, so start() lands on setup_required. */
+  runtimeReadyNow: true,
+}));
+
+vi.mock('electron', () => ({ app: { isPackaged: true, getPath: () => '/unused-budget-test' } }));
+vi.mock('node:child_process', () => ({ spawn: mocks.spawn }));
+vi.mock('node:net', () => ({
+  createServer: () => {
+    const server = Object.assign(new EventEmitter(), {
+      listen: (options: { port: number }, done: () => void) => {
+        mocks.listen(options.port);
+        const code = mocks.denied.has(options.port)
+          ? 'EACCES'
+          : mocks.occupied.has(options.port)
+            ? 'EADDRINUSE'
+            : null;
+        if (code) {
+          queueMicrotask(() =>
+            server.emit('error', Object.assign(new Error('bind failed'), { code })),
+          );
+        } else queueMicrotask(done);
+        return server;
+      },
+      address: () => ({ port: 49152 }),
+      close: (done: () => void) => {
+        mocks.close();
+        done();
+      },
+    });
+    return server;
+  },
+}));
+
+vi.mock('./runtime-project', () => {
+  // Both pre-spawn steps are genuinely slow on a cold, scanner-contended
+  // install, and both complete before the backend process exists.
+  const burn = async (): Promise<void> => {
+    if (mocks.prespawnMs > 0) await vi.advanceTimersByTimeAsync(mocks.prespawnMs);
+  };
+  return {
+    runtimeReady: async () => mocks.runtimeReadyNow,
+    runtimeCompatible: async () => false,
+    runtimeDependenciesReady: async () => {
+      await burn();
+      return mocks.runtimeReadyNow;
+    },
+    runtimeInstallInterrupted: async () => false,
+    // Stands in for uv sync: the real installer spawns a child, so its output
+    // lands in the same ring the backend's does.
+    installRuntime: async (
+      _bundle: string,
+      _project: string,
+      _uv: string | null,
+      run: (
+        command: string,
+        args: string[],
+        cwd: string,
+        env: NodeJS.ProcessEnv,
+      ) => Promise<string>,
+    ) => {
+      mocks.runtimeReadyNow = true;
+      await run('uv', ['sync'], '/unused-budget-test', {});
+    },
+    stageRuntimeSources: burn,
+    runtimePython: () => '/runtime/python',
+  };
+});
+
+import { BackendSupervisor } from './backend';
+
+const BUDGET_S = '10';
+
+/** A spawned process that is alive but not answering yet — a cold backend boot. */
+function fakeChild() {
+  const stdout = Object.assign(new EventEmitter(), { setEncoding: () => {} });
+  return {
+    child: Object.assign(new EventEmitter(), {
+      stdin: null,
+      stdout,
+      stderr: null,
+      stdio: [],
+    }),
+    stdout,
+  };
+}
+
+function stubBackend(ready: () => boolean): void {
+  vi.stubGlobal(
+    'fetch',
+    vi.fn(async () => {
+      if (!ready()) throw new Error('not listening yet');
+      return new Response(JSON.stringify({ status: 'ok', version: 'test' }), {
+        headers: { 'x-omnivoice-backend': 'test' },
+      });
+    }),
+  );
+}
+
+function stubEnv(): void {
+  vi.stubEnv('OMNIVOICE_PORT', '');
+  vi.stubEnv('OMNIVOICE_BACKEND_CMD', '');
+  vi.stubEnv('VOICESTUDIO_SKIP_BACKEND', '');
+  vi.stubEnv('OMNIVOICE_STARTUP_BUDGET_S', BUDGET_S);
+}
+
+afterEach(() => {
+  vi.useRealTimers();
+  vi.unstubAllGlobals();
+  vi.unstubAllEnvs();
+  vi.clearAllMocks();
+  mocks.prespawnMs = 0;
+  mocks.denied.clear();
+  mocks.occupied.clear();
+  mocks.runtimeReadyNow = true;
+});
+
+it('gives a freshly spawned backend its whole budget after slow pre-launch work', async () => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  // Two pre-spawn steps at 25 s each against a 10 s budget: the launch alone is
+  // 5x the entire readiness window, and it finishes before the process exists.
+  mocks.prespawnMs = 25_000;
+  let ready = false;
+  stubBackend(() => ready);
+  const { child } = fakeChild();
+  mocks.spawn.mockReturnValue(child);
+  const supervisor = new BackendSupervisor();
+  try {
+    await supervisor.start();
+    expect(mocks.spawn).toHaveBeenCalledTimes(1);
+    // The backend was spawned moments ago; the elapsed launch must not have
+    // already spent its budget and killed it.
+    await vi.advanceTimersByTimeAsync(0);
+    expect(supervisor.status.stage).toBe('starting');
+    await vi.advanceTimersByTimeAsync(9_000);
+    expect(supervisor.status.stage).toBe('starting');
+    ready = true;
+    await vi.advanceTimersByTimeAsync(500);
+    expect(supervisor.status.stage).toBe('ready');
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});
+
+it('still fails the backend once it has had its full budget', async () => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  let ready = false;
+  stubBackend(() => ready);
+  const { child } = fakeChild();
+  mocks.spawn.mockReturnValue(child);
+  const supervisor = new BackendSupervisor();
+  try {
+    await supervisor.start();
+    await vi.advanceTimersByTimeAsync(9_000);
+    expect(supervisor.status.stage).toBe('starting');
+    await vi.advanceTimersByTimeAsync(2_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain('did not answer on port 3900');
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});
+
+it.each([
+  ['silent', null, 'It printed no output.'],
+  [
+    'noisy',
+    'RuntimeError: no module named torch\r\n',
+    'Last output: RuntimeError: no module named torch',
+  ],
+])('carries the backend %s into the budget-expiry message', async (_label, line, expected) => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  stubBackend(() => false);
+  const { child, stdout } = fakeChild();
+  mocks.spawn.mockReturnValue(child);
+  const supervisor = new BackendSupervisor();
+  try {
+    await supervisor.start();
+    if (line) stdout.emit('data', line);
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain(expected);
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});
+
+/**
+ * A launch owns its own diagnostics. `childLog` is a ring of process output,
+ * and the previous launch — or the runtime installer, whose uv children share
+ * the same reader — leaves lines behind. A backend that then dies silently
+ * must not be handed someone else's last word.
+ */
+it('does not quote the previous backend after a restart', async () => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  stubBackend(() => false);
+  const first = fakeChild();
+  mocks.spawn.mockReturnValue(first.child);
+  const supervisor = new BackendSupervisor();
+  try {
+    await supervisor.start();
+    first.stdout.emit('data', 'previous run: CUDA out of memory\r\n');
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain('previous run: CUDA out of memory');
+
+    // The replacement fails silently, so it must not inherit that line.
+    mocks.spawn.mockReturnValue(fakeChild().child);
+    await supervisor.restart();
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain('It printed no output.');
+    expect(supervisor.status.message).not.toContain('previous run: CUDA out of memory');
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});
+
+it('blames no backend for an attach-only wait that times out', async () => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  stubBackend(() => false);
+  const first = fakeChild();
+  mocks.spawn.mockReturnValue(first.child);
+  const supervisor = new BackendSupervisor();
+  try {
+    await supervisor.start();
+    first.stdout.emit('data', 'previous run: CUDA out of memory\r\n');
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+
+    // Deny the default port so port selection falls through to 4900, which
+    // answers the identity probe but never the health one. That is the
+    // attach-only wait: a finite budget, and no process of ours to quote.
+    mocks.denied.add(3900);
+    mocks.occupied.add(4900);
+    let identified = 0;
+    vi.stubGlobal(
+      'fetch',
+      vi.fn(async (url: string) => {
+        if (!url.includes(':4900') || ++identified > 1) throw new Error('never ready');
+        return new Response(JSON.stringify({ status: 'starting' }), {
+          status: 503,
+          headers: { 'x-omnivoice-backend': 'test' },
+        });
+      }),
+    );
+    await supervisor.restart();
+    expect(mocks.spawn).toHaveBeenCalledTimes(1);
+    expect(supervisor.port).toBe(4900);
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain('Nothing was spawned for this attempt.');
+    expect(supervisor.status.message).not.toContain('previous run: CUDA out of memory');
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});
+
+it('does not quote the installer after a completed runtime setup', async () => {
+  vi.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
+  stubEnv();
+  stubBackend(() => false);
+  mocks.runtimeReadyNow = false;
+  // First spawn is uv inside installRuntime, second is the real backend.
+  let spawns = 0;
+  mocks.spawn.mockImplementation(() => {
+    spawns++;
+    const made = fakeChild();
+    if (spawns === 1)
+      queueMicrotask(() => {
+        made.stdout.emit('data', 'uv: installed 412 packages\r\n');
+        made.child.emit('close', 0);
+      });
+    return made.child;
+  });
+  const supervisor = new BackendSupervisor();
+  try {
+    // No runtime yet, so the first launch asks for setup.
+    await supervisor.start();
+    expect(supervisor.status.stage).toBe('setup_required');
+    await supervisor.setupRuntime();
+    expect(mocks.spawn).toHaveBeenCalledTimes(2);
+    expect(supervisor.status.stage).toBe('starting');
+    await vi.advanceTimersByTimeAsync(11_000);
+    expect(supervisor.status.stage).toBe('failed');
+    expect(supervisor.status.message).toContain('It printed no output.');
+    expect(supervisor.status.message).not.toContain('uv: installed 412 packages');
+  } finally {
+    (supervisor as unknown as { child: null }).child = null;
+    await supervisor.shutdown();
+  }
+});

electron/src/main/backend.ts

@@ -415,6 +415,8 @@ export class BackendSupervisor extends EventEmitter<{
   private startedAt = Date.now();
   private child: ChildProcess | null = null;
   private readonly log: string[] = [];
+  /** Only the spawned process's own output, for quoting back in failure messages. */
+  private readonly childLog: string[] = [];
   /** Bumped on every start/shutdown so stale poll loops and exit handlers no-op. */
   private generation = 0;
   /** A generation owns at most one health loop, even if readiness is observed twice. */
@@ -508,6 +510,10 @@ export class BackendSupervisor extends EventEmitter<{
     this.startedAt = Date.now();
     this.exitCode = undefined;
     this.exitSignal = undefined;
+    // Every launch begins with an empty child-output ring. A restart must not
+    // quote the backend it just killed, and a completed runtime install must
+    // not quote the installer — setupRuntime's uv children share this ring.
+    this.childLog.length = 0;
     this.setStage('attaching', { managed: false, message: undefined });
     try {
       if (await this.probe()) {
@@ -631,6 +637,7 @@ export class BackendSupervisor extends EventEmitter<{
     const gen = ++this.generation;
     this.startedAt = Date.now();
     this.log.length = 0;
+    this.childLog.length = 0;
     this.setupIssue = undefined;
     this.runtimeInterrupted = false;
     this.setupPhase = 'checking';
@@ -958,12 +965,21 @@ export class BackendSupervisor extends EventEmitter<{
     this.emit('status', this.status);
   }
 
-  private pushLog(stream: 'out' | 'err', line: string): void {
+  private pushLog(stream: 'out' | 'err', line: string, fromChild = false): void {
     line = cleanProcessLine(line);
     if (!line) return;
     if (stream === 'err') this.crashes.captureLine(line);
     this.log.push(line);
     if (this.log.length > LOG_RING_LINES) this.log.splice(0, this.log.length - LOG_RING_LINES);
+    // Failure messages quote the backend, not this shell. `log` also carries
+    // the supervisor's own "Reusing compatible Tauri runtime"/"spawning in …"
+    // lines, so taking its tail would report a launch banner as the backend's
+    // last word — exactly the evidence a startup failure needs.
+    if (fromChild) {
+      this.childLog.push(line);
+      if (this.childLog.length > LOG_RING_LINES)
+        this.childLog.splice(0, this.childLog.length - LOG_RING_LINES);
+    }
     (stream === 'err' ? console.error : console.log)(`[backend] ${line}`);
     if (this.stage === 'installing') {
       this.setupProgress.ingest(line);
@@ -975,7 +991,7 @@ export class BackendSupervisor extends EventEmitter<{
     if (!readable) return;
     let pending = '';
     const flushPending = () => {
-      if (pending.length > 0) this.pushLog(stream, pending);
+      if (pending.length > 0) this.pushLog(stream, pending, true);
       pending = '';
     };
     readable.setEncoding('utf8');
@@ -983,7 +999,7 @@ export class BackendSupervisor extends EventEmitter<{
       pending += chunk;
       const lines = pending.split(/[\r\n]+/);
       pending = lines.pop() ?? '';
-      for (const line of lines) if (line.length > 0) this.pushLog(stream, line);
+      for (const line of lines) if (line.length > 0) this.pushLog(stream, line, true);
     });
     readable.on('end', flushPending);
     readable.on('error', (error: unknown) => {
@@ -1092,7 +1108,7 @@ export class BackendSupervisor extends EventEmitter<{
       });
       return;
     }
-    const lastLine = this.log.at(-1);
+    const lastLine = this.childLog.at(-1);
     const why = signal ? `signal ${signal}` : `exit code ${code}`;
     this.setStage('crashed', {
       message: `Backend exited unexpectedly (${why}).${lastLine ? ` Last output: ${lastLine}` : ''}`,
@@ -1128,7 +1144,18 @@ export class BackendSupervisor extends EventEmitter<{
   }
 
   private async waitUntilReady(gen: number, budgetMs: number): Promise<void> {
-    const deadline = this.startedAt + budgetMs;
+    // `OMNIVOICE_STARTUP_BUDGET_S` bounds how long the *backend* may take to
+    // answer, so it is measured from the moment this poll loop begins — which
+    // is right after the process was spawned. Anchoring it to `startedAt`
+    // charged the launch against the backend's window (#2445), and everything
+    // ahead of the spawn is slow and independently bounded: resolving the
+    // runtime imports torch in a child interpreter (30 s each, once per
+    // candidate project, then again in resolveSpawnPlan), staging the bundled
+    // sources is a recursive copy, and port selection walks up to 17
+    // candidates. Once that pre-spawn work outlasted the budget, this loop
+    // failed on its very first probe — killing a backend that had been alive
+    // for a second and reporting "did not answer within 300 s".
+    const deadline = Date.now() + budgetMs;
     const waitingStage = this.stage;
     while (gen === this.generation && this.stage === waitingStage) {
       const ready = await this.probe();
@@ -1145,11 +1172,28 @@ export class BackendSupervisor extends EventEmitter<{
       }
       if (Date.now() > deadline) {
         this.generation++;
+        // killChild() nulls this.child, so record whether this launch owned a
+        // process *before* tearing it down. Checking afterwards would
+        // suppress the one diagnostic that matters — a managed backend that
+        // died silently — and would let an attach-only wait blame output from
+        // a backend this attempt never started.
+        // killChild() nulls this.child, so record whether this launch owned a
+        // process *before* tearing it down. Checking afterwards would
+        // suppress the one diagnostic that matters — a managed backend that
+        // died silently — and would let an attach-only wait blame output from
+        // a backend this attempt never started.
+        const owned = this.child !== null;
         await this.killChild();
+        const lastLine = owned ? this.childLog.at(-1) : undefined;
         this.setStage('failed', {
           message:
             `Backend did not answer on port ${this.port} within ${Math.round(budgetMs / 1000)} s ` +
-            '(OMNIVOICE_STARTUP_BUDGET_S). Check the log above.',
+            '(OMNIVOICE_STARTUP_BUDGET_S).' +
+            (!owned
+              ? ' Nothing was spawned for this attempt.'
+              : lastLine
+                ? ` Last output: ${lastLine}`
+                : ' It printed no output.'),
         });
         return;
       }