Fix #1691: surface tower owner-guard refusal in the CLI, not a 30s timeout

codev/projects/bugfix-1691-afx-tower-start-surface-the-ow/status.yaml

@@ -0,0 +1,22 @@
+id: bugfix-1691
+title: afx-tower-start-surface-the-ow
+protocol: bugfix
+phase: pr
+plan_phases: []
+current_plan_phase: null
+gates:
+  pr:
+    status: approved
+    requested_at: '2026-09-16T23:58:57.118Z'
+    approved_at: '2026-09-17T01:37:06.595Z'
+iteration: 1
+build_complete: false
+history: []
+started_at: '2026-09-16T23:38:54.218Z'
+updated_at: '2026-09-17T01:37:33.182Z'
+pr_ready_for_human: false
+pr_history:
+  - phase: pr
+    pr_number: 1692
+    branch: builder/bugfix-1691
+    created_at: '2026-09-17T01:37:33.181Z'

codev/state/bugfix-1691_thread.md

@@ -0,0 +1,94 @@
+# bugfix-1691 thread
+
+Issue #1691: `afx tower start` — surface the owner-guard refusal in the CLI instead of the
+generic 30s timeout. Split from #1690 item 1; companion to #1689's owner guard (PR #1689,
+`tower-owner.ts`). Scope is item 1 ONLY (per main's lane context). Items 2+3 (shutdown overlap,
+clear-owner hatch, flock eval) stay in #1690 and are NOT mine.
+
+Commit discipline (main): no closing keywords for #1690 — use `Refs #1690` if referencing;
+`Fix #1691:` is fine. A `Fix #N` commit SUBJECT auto-closes on merge even with a clean PR body
+(#1677 lesson).
+
+## Investigate (done)
+
+Root cause — `packages/codev/src/agent-farm/commands/tower.ts`:
+- `towerStart()` spawns the tower-server daemon detached (`stdio: 'ignore'`, `unref()`), then
+  `waitForServer(port)` (lines 149-160) polls ONLY `/api/status` for up to `STARTUP_TIMEOUT_MS`
+  (30s). It has no awareness of the spawned pid's liveness.
+- When the #1689 owner guard refuses, `bootSequence()` in `tower-server.ts` (lines 526-536) calls
+  `log('ERROR', ownershipConflictMessage(...))` then `process.exit(1)`. The daemon dies within
+  ~1s; the port never comes up.
+- So `waitForServer` loops the full 30s, then prints the generic
+  "Tower server failed to respond within 30000ms" (lines 266-271) — indistinguishable from the
+  #1685 hang class. The teaching error is only in `tower.log`.
+- Daemon log format (`tower-server.ts` `log()`, lines 142-161): `[iso] [ERROR] <message>\n`,
+  first line prefixed, continuation lines (the multi-line `ownershipConflictMessage`) unprefixed.
+
+Fix shape (implement phase):
+1. Detect fast-exit: track the spawned child's `exit` event; the readiness wait stops immediately
+   when the daemon dies before the port responds (no more burning 30s).
+2. Surface verbatim: capture `tower.log` byte offset right before the daemon can write, then on
+   fast-exit read everything appended since and print it (the guard's teaching error, or any
+   other early-boot failure).
+3. Three distinguishable outcomes: `started` / `exited` (refused-with-reason) /
+   `timeout` (timed-out-still-unknown).
+
+Testable seam: extract an injectable `waitForServerOutcome(probe, daemonAlive, opts)` returning
+the discriminated outcome, plus a `readLogSince(offset)` helper. Regression test drives the seam
+with fakes (daemon dies while probe stays false → `exited` well before timeout) and asserts the
+launcher surfaces the teaching error + exits non-zero on fast-exit.
+
+## Fix (done)
+
+Changed one product file: `packages/codev/src/agent-farm/commands/tower.ts` (+89/-11). No
+skeleton twin (the Tower launcher is product code, not a shipped template — confirmed no
+`tower.ts` under `codev-skeleton/`).
+
+- New exported `TowerStartupOutcome = 'started' | 'exited' | 'timeout'` and
+  `waitForServerOutcome(isReady, isDaemonAlive, opts)` replacing the old boolean `waitForServer`.
+  It short-circuits to `exited` the instant the daemon is seen dead (with a final readiness
+  re-probe for the benign same-tick race), so a refusal no longer burns the 30s budget.
+- `towerStart` registers `serverProcess.on('exit')` → `daemonExited`, and captures the tower.log
+  byte offset right after the launcher's pre-spawn writes. On `exited` it reads everything the
+  daemon appended since (`readLogSince`) and prints it verbatim on stderr (the guard's teaching
+  error), then `exit(1)`. Three distinguishable outcomes: started / exited (refused-with-reason)
+  / timeout (still-running, status unknown).
+
+Regression test: `packages/codev/src/agent-farm/__tests__/bugfix-1691-tower-start-surface-refusal.test.ts`.
+Unit tests pin the outcome logic incl. the "no 30s burn" timing; two towerStart tests
+(mocked spawn/http/shell) prove the teaching error is surfaced verbatim + exit(1) within seconds,
+and the empty-log fallback. Build clean, `tsc --noEmit` clean, tower-command + 1629 + 1691 suites
+green.
+
+## PR + CMAP (done)
+
+PR #1692 (`Fixes #1691`, `Refs #1690` — non-closing form for #1690 per commit discipline).
+
+CMAP: **claude=APPROVE** (HIGH, verified end-to-end), **codex=COMMENT** (HIGH), **gemini=skipped**
+(agy unauthenticated, non-blocking). Addressed feedback in a second commit:
+- codex #2 (no final liveness check after the wait loop → exit on the deadline misreports as
+  `timeout`): added a post-loop `isDaemonAlive` check. New unit test pins it (asserts `exited`
+  where the old code returned `timeout`).
+- claude #2 (ternary vs project if/else preference): converted the `started/exited` ternary to
+  if/else.
+- claude #1 (implicit timing guarantee): added an explicit `< 5000ms` elapsed assertion to the
+  towerStart fast-exit test so the "no 30s burn" bound is visible, not reliant on vitest's 5s
+  default.
+- codex #1 (capture log offset before spawn): NOT applied. Claude verified the daemon's
+  boot-to-first-log (~100ms+: module load + bootSequence) far exceeds the sub-ms parent window
+  between spawn() and offset capture, so the race is not practically reachable, and it degrades
+  gracefully (the "No output captured" fallback points to the log) if it ever did. Claude
+  explicitly praised the current placement for keeping the surfaced tail daemon-only (no launcher
+  lines echoed at the user). Kept the clean placement over a theoretical hardening.
+
+7 regression tests green; `tsc --noEmit` clean.
+
+## Post-gate follow-up (owner-directed)
+
+Owner reviewed the real end-to-end output and flagged that the refusal message references
+internal issue numbers (`#1629`, `#1515`) — fine in comments, not in a user-visible string. This
+is coupled to #1691: my fix is what promotes that message from a `tower.log` line to a CLI
+message the user reads. Stripped `(Issue #1629)` / `(#1515)` from `ownershipConflictMessage`
+(`db/tower-owner.ts`), keeping the actionable `CODEV_AGENT_FARM_DIR (NOT AGENT_FARM_DIR)` guidance;
+moved the incident context into the function's JSDoc. Updated the #1629 test (asserts the message
+now matches no `#\d+`) and my fixture. 46 tests green, tsc clean.

packages/codev/src/agent-farm/__tests__/bugfix-1629-tower-owner.test.ts

@@ -269,7 +269,9 @@ describe('ownershipConflictMessage — loud and teaching', () => {
     expect(msg).toContain('4100');
     expect(msg).toContain('/home/u/.agent-farm');
     expect(msg).toContain('CODEV_AGENT_FARM_DIR');
-    expect(msg).toContain('Issue #1629');
+    // User-visible message: carries the actionable env-var fix, but no internal
+    // issue numbers (they live in the code comment) — Issue #1691.
+    expect(msg).not.toMatch(/#\d+/);
   });
 });
 

packages/codev/src/agent-farm/__tests__/bugfix-1691-tower-start-surface-refusal.test.ts

@@ -0,0 +1,223 @@
+/**
+ * Issue #1691 — `afx tower start` must surface the owner-guard refusal in the CLI,
+ * not the generic 30s timeout.
+ *
+ * `towerStart` spawns the tower-server daemon detached and then polls its port for
+ * readiness. When the #1629 owner-lock guard refuses, the daemon logs its teaching
+ * error and `process.exit(1)`s within ~1s — but the old readiness wait only watched
+ * the port, so it burned the full 30s budget and then printed a generic "failed to
+ * respond within 30000ms", indistinguishable from a real hang (#1685 class). The
+ * daemon's refusal reached only tower.log.
+ *
+ * The fix teaches the wait to distinguish three outcomes — started / exited /
+ * timeout — by also watching the spawned daemon's liveness, and on a fast-exit it
+ * reads back what the daemon appended to tower.log for THIS run and prints it
+ * verbatim. These tests pin both halves: the pure outcome logic (fast-exit is
+ * detected immediately, not after the 30s budget) and the launcher wiring (a
+ * fast-exiting daemon's teaching error is surfaced on stderr and the CLI exits
+ * non-zero within seconds).
+ */
+
+import { describe, it, expect, vi, beforeEach, afterEach, afterAll } from 'vitest';
+import { EventEmitter } from 'node:events';
+import fs from 'node:fs';
+import os from 'node:os';
+import path from 'node:path';
+
+// A throwaway AGENT_FARM_DIR so tower.log (resolved from AGENT_FARM_DIR at module
+// load) lives under our control, and a mutable holder for the spawn stub's child —
+// both created in a hoisted block so the vi.mock factories below can reference them.
+const h = vi.hoisted(() => {
+  const nodeOs = require('node:os') as typeof import('node:os');
+  const nodePath = require('node:path') as typeof import('node:path');
+  const nodeFs = require('node:fs') as typeof import('node:fs');
+  const dir = nodeFs.mkdtempSync(nodePath.join(nodeOs.tmpdir(), 'af-1691-'));
+  return { agentFarmDir: dir, spawn: { child: null as EventEmitter & { pid?: number; unref?: () => void } | null } };
+});
+
+vi.mock('../lib/tower-client.js', () => ({
+  DEFAULT_TOWER_PORT: 4100,
+  AGENT_FARM_DIR: h.agentFarmDir,
+}));
+
+vi.mock('../utils/config.js', () => ({
+  getConfig: () => ({ serversDir: h.agentFarmDir }),
+}));
+
+// isPortInUse() = !isPortAvailable(); "available" keeps towerStart off the
+// zombie-cleanup branch and straight onto the spawn path.
+vi.mock('../utils/shell.js', () => ({
+  isPortAvailable: vi.fn(async () => true),
+}));
+
+// The readiness probe uses http.request; a request that immediately errors makes
+// isServerResponding() resolve false (the port never comes up on a refusal).
+vi.mock('node:http', () => {
+  const request = vi.fn(() => {
+    const req = new EventEmitter() as EventEmitter & { end: () => void; destroy: () => void };
+    req.destroy = () => {};
+    req.end = () => {
+      setImmediate(() => req.emit('error', new Error('ECONNREFUSED')));
+    };
+    return req;
+  });
+  return { default: { request }, request };
+});
+
+vi.mock('node:child_process', async () => {
+  const actual = await vi.importActual<typeof import('node:child_process')>('node:child_process');
+  return { ...actual, spawn: vi.fn(() => h.spawn.child) };
+});
+
+const LOG_FILE = path.join(h.agentFarmDir, 'tower.log');
+
+// Mirrors ownershipConflictMessage() — the user-visible teaching error, with no
+// internal issue numbers in the text.
+const TEACHING_ERROR = [
+  'Refusing to start: this global.db is already owned by a live Tower.',
+  '  owner pid 12345 on port 4100 (host testhost)',
+  '  shared database dir: /Users/test/.agent-farm',
+  'A second Tower opening a live global.db hijacks and deletes its shellper sessions.',
+  'If you meant to run an isolated test Tower, set CODEV_AGENT_FARM_DIR (NOT AGENT_FARM_DIR) to a throwaway directory.',
+  "Otherwise stop the existing Tower first ('afx tower stop'), or investigate pid 12345 if you believe it is stale.",
+].join('\n');
+
+let consoleErrorSpy: ReturnType<typeof vi.spyOn>;
+let consoleLogSpy: ReturnType<typeof vi.spyOn>;
+let exitSpy: ReturnType<typeof vi.spyOn>;
+
+beforeEach(() => {
+  // A dummy compiled server so towerStart takes the `node <jsScript>` branch; spawn
+  // is stubbed, so the file is never executed.
+  fs.writeFileSync(path.join(h.agentFarmDir, 'tower-server.js'), '// stub');
+  fs.rmSync(LOG_FILE, { force: true });
+  h.spawn.child = null;
+  consoleErrorSpy = vi.spyOn(console, 'error').mockImplementation(() => {});
+  consoleLogSpy = vi.spyOn(console, 'log').mockImplementation(() => {});
+  exitSpy = vi.spyOn(process, 'exit').mockImplementation(((code?: number) => {
+    throw new Error(`process.exit:${code ?? 0}`);
+  }) as never);
+});
+
+afterEach(() => {
+  vi.restoreAllMocks();
+});
+
+afterAll(() => {
+  fs.rmSync(h.agentFarmDir, { recursive: true, force: true });
+});
+
+describe('waitForServerOutcome (#1691)', () => {
+  it('returns "started" when the port answers readiness', async () => {
+    const { waitForServerOutcome } = await import('../commands/tower.js');
+    const outcome = await waitForServerOutcome(async () => true, () => true, {
+      timeoutMs: 1000,
+      intervalMs: 5,
+    });
+    expect(outcome).toBe('started');
+  });
+
+  it('returns "exited" the instant the daemon dies — it does NOT burn the 30s budget', async () => {
+    const { waitForServerOutcome } = await import('../commands/tower.js');
+    let alive = true;
+    setTimeout(() => {
+      alive = false;
+    }, 10);
+
+    const start = Date.now();
+    // A 30s budget as in production; the fix must return far sooner than that.
+    const outcome = await waitForServerOutcome(async () => false, () => alive, {
+      timeoutMs: 30000,
+      intervalMs: 10,
+    });
+    const elapsed = Date.now() - start;
+
+    expect(outcome).toBe('exited');
+    expect(elapsed).toBeLessThan(1000);
+  });
+
+  it('returns "timeout" when the daemon stays alive but never answers', async () => {
+    const { waitForServerOutcome } = await import('../commands/tower.js');
+    const outcome = await waitForServerOutcome(async () => false, () => true, {
+      timeoutMs: 60,
+      intervalMs: 10,
+    });
+    expect(outcome).toBe('timeout');
+  });
+
+  it('returns "exited" (not "timeout") when the daemon dies as the budget expires', async () => {
+    const { waitForServerOutcome } = await import('../commands/tower.js');
+    let alive = true;
+    // Dies mid-sleep, after the last in-loop check but before the loop condition re-evaluates —
+    // caught only by the post-loop liveness check.
+    setTimeout(() => {
+      alive = false;
+    }, 20);
+    const outcome = await waitForServerOutcome(async () => false, () => alive, {
+      timeoutMs: 15,
+      intervalMs: 40,
+    });
+    expect(outcome).toBe('exited');
+  });
+
+  it('prefers "started" when the port answers in the same tick the daemon is seen to exit', async () => {
+    const { waitForServerOutcome } = await import('../commands/tower.js');
+    let readyCalls = 0;
+    // First probe false (loop enters), daemon reported dead, re-probe true → started.
+    const isReady = async () => ++readyCalls >= 2;
+    const outcome = await waitForServerOutcome(isReady, () => false, {
+      timeoutMs: 1000,
+      intervalMs: 5,
+    });
+    expect(outcome).toBe('started');
+  });
+});
+
+describe('towerStart fast-exit surfacing (#1691)', () => {
+  it('surfaces the daemon refusal verbatim and exits non-zero within seconds', async () => {
+    const { towerStart } = await import('../commands/tower.js');
+
+    const child = new EventEmitter() as EventEmitter & { pid: number; unref: () => void };
+    child.pid = 999999;
+    child.unref = () => {};
+    h.spawn.child = child;
+
+    // Mimic the daemon: append its refusal to tower.log (the guard's format is
+    // `[iso] [ERROR] <message>`), then exit before the port ever answers.
+    setTimeout(() => {
+      fs.appendFileSync(LOG_FILE, `[2026-09-17T00:00:00.000Z] [ERROR] ${TEACHING_ERROR}\n`);
+      child.emit('exit', 1, null);
+    }, 30);
+
+    const start = Date.now();
+    await expect(towerStart({ wait: true })).rejects.toThrow('process.exit:1');
+    // The whole point of #1691: the CLI reacts to the fast-exit in seconds, not after the 30s
+    // readiness budget. Asserted explicitly rather than left to vitest's default test timeout.
+    expect(Date.now() - start).toBeLessThan(5000);
+
+    const stderr = consoleErrorSpy.mock.calls.map((c) => c.join(' ')).join('\n');
+    // The teaching error — not a generic timeout — is what the user sees.
+    expect(stderr).toContain('Refusing to start: this global.db is already owned by a live Tower');
+    expect(stderr).toContain('CODEV_AGENT_FARM_DIR');
+    expect(stderr).toContain('exited during startup');
+    expect(stderr).not.toContain('failed to respond within');
+  });
+
+  it('reports the fast-exit even when the daemon logged nothing', async () => {
+    const { towerStart } = await import('../commands/tower.js');
+
+    const child = new EventEmitter() as EventEmitter & { pid: number; unref: () => void };
+    child.pid = 999998;
+    child.unref = () => {};
+    h.spawn.child = child;
+
+    // Exit with no fresh log output.
+    setTimeout(() => child.emit('exit', 1, null), 30);
+
+    await expect(towerStart({ wait: true })).rejects.toThrow('process.exit:1');
+
+    const stderr = consoleErrorSpy.mock.calls.map((c) => c.join(' ')).join('\n');
+    expect(stderr).toContain('exited during startup');
+    expect(stderr).toContain('No output was captured');
+  });
+});