diff --git a/.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md b/.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md index c1409e9..2813eb4 100644 --- a/.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md +++ b/.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md @@ -120,3 +120,22 @@ The control-plane presence (`daemon-94504`) IS online on the broker (DB row `XqS **Drill 2 also exposed a two-daemon hazard (CLI):** `services/daemon/lifecycle.ts probeDaemon()` treated ANY probe failure (incl. a 2.5 s timeout against a busy-but-live daemon) as "stale" and `cleanupStaleFiles()` unlinked the live daemon's `daemon.sock` + `daemon.pid`. The daemon kept running unreachable; the next CLI call auto-spawned a second daemon; both rehydrated the same sessions and kicked each other's sockets with `session_replaced` every second (20 hellos/s on the broker), forever. Fixes: (a) a probe failure is "stale" only on `ECONNREFUSED`/`ENOENT` or a dead pid — otherwise "busy" (files intact, no spawn); (b) the daemon probes the socket for another live daemon before taking the lock, and re-asserts its pid file every 30 s (`daemon_pidfile_restored` / `daemon_pidfile_conflict`); (c) the WS lifecycle treats `1000 session_replaced` as terminal (whoever replaced us owns the identity; no reconnect fight), surfaced as `replaced: true` in `/v1/diagnostics`. **Drill 3 (final build, local broker restarted on the reordered code):** (a) two `session_hello` clients with the same pubkey → the replaced socket's close is now logged `code 1000 session_replaced action: ignore_replaced`, the reattach reads `was: online`, no grace timer armed; (b) with `daemon.pid` deleted by hand, a second `daemon up` is refused: `daemon already running (pid 36531, answering on …/daemon.sock)` + `daemon_exit code 1` forensics line; (c) SIGKILL + respawn → both sessions visible at t+1 s; (d) the pid-file guard rewrote a deleted pid file within 30 s (`daemon_pidfile_restored`); (e) broker evictions over the whole drill: 0. Note for future drills: the broker integration suite's `cleanupAllTestMeshes()` deletes every mesh owned by the test user — including a drill mesh created with `setupTestMesh` — so run the suite and the drill against different databases (the "1008 unauthorized" seen mid-drill was that, not a product bug). + +## Addendum 5 — recurrence after the CLEAN restart (22:05Z): reattached presences die, fresh ones survive +Clean `claudemesh daemon down` at 20:40:31Z → new daemon 72349, `sessions_rehydrated 8/8`, all 8 session WS `hello_acked` at 20:40:33Z, `peer list` = 7 at 20:41Z. By 22:05Z `peer list` = 4 and `mesh.presence` online for flexicar = exactly the 4 presences whose `connected_at = 20:40:33` (**fresh** `session_hello` rows: 9f0e1c09, 02b5b7d5, e051e316, 59d1cfb1) + control-plane. The 3 that vanished (612fa2bc, 0fdf7159, aee93b3b) were the ones the new daemon **reattached** to pre-existing rows (`connected_at` 19:28:17 / 20:10:43, `last_ping_at` frozen at 20:40:33). Neither daemon.log (new file) nor the broker log of the last 20 min shows a close/evict/reattach line for them — they were evicted silently between 20:45Z and 21:45Z, and the daemon still believes their WS is open (no `session_broker_ws_closed`). **Reattach is the broken path**: after a reattach the presence stops being pinged (`last_ping_at` frozen) → the DB stale-presence sweeper flips it → `list_peers` drops it, and later eviction/close never reaches the daemon. Fresh hellos are healthy. Test to add: reattach within grace → assert `last_ping_at` keeps advancing and the row stays online for ≥10 min. + +## Addendum 7 (claudemesh repo session, 22:20Z) — the 20:40Z recurrence IS RC-A/RC-C; broker log + DB evidence; one more mitigation +The "Addendum 5 — recurrence after the CLEAN restart" reading ("reattach stops pinging, evicted silently, no close/evict lines") is corrected by the broker log and `mesh.presence` rows for the same window: + +| UTC | broker log (`mcn8m74…`) | presences | +|---|---|---| +| 20:40:33.086–.381 | `session_hello reattach … was:"online"` ×4 | `OsMWiJPO` 612f, `JVuLGue1` aee9, `fB5eIuRx` 0fdf, `JOk0n5TA` a8d5 (4 reattached, not 3) | +| 20:40:35.699–.810 | `ws close — lease grace started` ×4 (same pids) | the DEAD daemon's socket close handler, resumed after `await savePeerState` (2.5 s of DB latency), lands on the reattached lease = RC-A/RC-C | +| 20:42:05.699–.893 | `lease grace expired — evicting` + `ws evict full` ×4 | `disconnected_at` = 20:42:05.700/.738/.800/.832 — exact match | +| 20:41:59.9 | `ws stale terminate` ×9 (`last_pong_ago_ms` 89.9 s) for daemon-94504's control-plane sockets | the "clean" shutdown never flushed its close frames | + +`last_ping_at` froze at 20:40:33 (= `restorePresence` at reattach) because the ping loop skips leases in `leaseState === "offline"` — the lease had been wrongly moved offline at 20:40:35; the freeze is a symptom, not a separate ping bug. The 4 fresh rows kept pinging (`last_ping_at` 22:07:01 at query time) because nothing touched their lease. So the recurrence is the same mechanism already fixed (Addendum 6 fix list); no reattach-specific ping path exists or is needed. + +**Why the reattach was `was:"online"` after a CLEAN restart (new finding):** `shutdown()` awaited `b.close()` per client sequentially and then `process.exit(0)`; the WS close frames were still unflushed when the process died, so the broker saw no close, kept all 17 leases "online" until its 75 s stale-pong watchdog terminated them (20:41:59), and the new daemon's hellos 1 s after start reattached onto "online" leases → the RC-C path (close of the replaced socket) instead of the safe `was:"offline"` path. Mitigation shipped in 1.37.1: `WsLifecycle.close()` now waits (≤1 s) for the socket's `close` event, and `shutdown()` closes all clients in parallel before exiting → the broker receives the closes immediately, starts grace, and every restart reattaches onto an `offline` lease — the safe path even against a pre-fix broker. + +**Tests added for the suggested scenario:** `apps/broker/tests/lease.test.ts` "reattachLease" — the ordering contract extracted into `lease.ts#reattachLease` is exercised with a close callback that fires synchronously (Bun emulation): the handler sees `ignore_replaced`, and even a mis-behaving handler that arms a grace timer leaves the lease online with no timer. `apps/cli/tests/unit/ws-lifecycle.test.ts` — `close()` resolves only after the fake broker observed the close frame. A live assertion ("`last_ping_at` advances ≥10 min after a reattach") belongs to the post-deploy verification on this Mac (SIGKILL + clean-restart drills, then `SELECT last_ping_at` for the reattached rows after 10 min). diff --git a/apps/broker/src/index.ts b/apps/broker/src/index.ts index 62fc42f..99d9c43 100644 --- a/apps/broker/src/index.ts +++ b/apps/broker/src/index.ts @@ -128,6 +128,7 @@ import { shouldEvictOnGraceExpiry, dedupTargets, findZombieSockets, + reattachLease, CLOSE_CODE_PRESENCE_EVICTED, CLOSE_CODE_NO_PRESENCE, } from "./lease"; @@ -2273,8 +2274,6 @@ async function handleSessionHello( // it differs, swap in the new WS, restore online. This is the "one // presence per session pubkey" invariant — it kills the same-name // ghost that used to win queued-DM claim races. - const wasState = oldConn.leaseState; - const replacedWs = oldConn.ws !== ws ? oldConn.ws : null; // ORDER MATTERS (2026-09-08, RC-C): swap the lease onto the new socket // and mark it online BEFORE closing the old socket. Under Bun (the // production runtime) the `ws` shim emits the old socket's `close` @@ -2282,25 +2281,11 @@ async function handleSessionHello( // 20-line repro; Node emits it on a later tick. With the old order the // close handler ran while `conn.ws` was still the old socket, saw an // online lease, and put THIS lease into grace with a 90 s eviction - // timer that the swap below never cleared — the reattached session was - // evicted 90 s later while its new socket stayed open (ghost). Swapping - // first makes that handler see `conn.ws !== closingWs` → ignored. - oldConn.ws = ws; - oldConn.leaseState = "online"; - oldConn.leaseUntil = 0; - oldConn.lastPongAt = Date.now(); - if (replacedWs) { - try { replacedWs.close(1000, "session_replaced"); } catch { /* already dead */ } - } - // Clear any grace timer — including one a synchronous close event may - // have just armed — AFTER the close call, and restore online state in - // case that handler flipped it. - if (oldConn.evictionTimer) { - clearTimeout(oldConn.evictionTimer); - oldConn.evictionTimer = null; - } - oldConn.leaseState = "online"; - oldConn.leaseUntil = 0; + // timer that the swap never cleared — the reattached session was + // evicted 90 s later while its new socket stayed open (ghost; prod + // 20:40:33 reattach → 20:40:35 grace → 20:42:05 evict, ×4). The + // ordering lives in lease.ts#reattachLease so it is unit-tested. + const wasState = reattachLease(oldConn, ws, (old) => old.close(1000, "session_replaced")); // Refresh mutable fields from the new hello. oldConn.sessionId = hello.sessionId; oldConn.cwd = hello.cwd; diff --git a/apps/broker/src/lease.ts b/apps/broker/src/lease.ts index 5338bfa..1cd2c34 100644 --- a/apps/broker/src/lease.ts +++ b/apps/broker/src/lease.ts @@ -133,3 +133,47 @@ export function findZombieSockets( /** Close codes the broker uses when it is the one ending a socket. */ export const CLOSE_CODE_PRESENCE_EVICTED = 4004; export const CLOSE_CODE_NO_PRESENCE = 4005; + +export interface SwappableLease extends LeaseConnView { + leaseUntil: number; + evictionTimer: ReturnType | null; + lastPongAt: number; +} + +/** + * Reattach a lease onto a fresh socket (RC-C-safe ordering). + * + * 1. Swap `conn.ws`, mark the lease online and refresh the pong clock. + * 2. THEN close the replaced socket via `closeOld` — which under Bun runs + * the old socket's `close` handler synchronously; that handler now sees + * `conn.ws !== closingWs` and ignores the event. + * 3. THEN clear any grace timer (including one a mis-behaving handler may + * have just armed) and force the lease online again. + * + * Returns the previous lease state (for logging). Pure apart from the + * injected `closeOld`, so the ordering contract is unit-testable under + * Node even though the hazard only manifests under Bun. + */ +export function reattachLease( + conn: SwappableLease, + newWs: WS, + closeOld: (oldWs: WS) => void, + now: number = Date.now(), +): LeaseState { + const wasState = conn.leaseState; + const replaced = conn.ws !== newWs ? conn.ws : null; + conn.ws = newWs; + conn.leaseState = "online"; + conn.leaseUntil = 0; + conn.lastPongAt = now; + if (replaced !== null) { + try { closeOld(replaced); } catch { /* already dead */ } + } + if (conn.evictionTimer) { + clearTimeout(conn.evictionTimer); + conn.evictionTimer = null; + } + conn.leaseState = "online"; + conn.leaseUntil = 0; + return wasState; +} diff --git a/apps/broker/tests/lease.test.ts b/apps/broker/tests/lease.test.ts index 9a20fa1..dc62e77 100644 --- a/apps/broker/tests/lease.test.ts +++ b/apps/broker/tests/lease.test.ts @@ -13,6 +13,7 @@ import { shouldEvictOnGraceExpiry, dedupTargets, findZombieSockets, + reattachLease, type DedupConnView, } from "../src/lease"; @@ -126,3 +127,59 @@ describe("findZombieSockets", () => { expect(findZombieSockets([z], new Set(), () => undefined, now, 60_000)).toEqual([z]); }); }); + +describe("reattachLease (RC-C ordering: swap before close)", () => { + const OPEN = 1; + type Sock = { id: string; readyState: number; OPEN: number }; + const mk = (id: string): Sock => ({ id, readyState: OPEN, OPEN }); + + test("a close handler that fires SYNCHRONOUSLY inside closeOld() sees the NEW socket and an online lease", () => { + const oldWs = mk("old"); + const newWs = mk("new"); + const conn = { ws: oldWs, leaseState: "online" as const, leaseUntil: 0, evictionTimer: null as ReturnType | null, lastPongAt: 0 }; + let seenAction: string | null = null; + // Emulate Bun: closing the old socket runs its close handler right away. + const closeOld = (ws: Sock) => { + seenAction = decideCloseAction(conn, ws); + if (seenAction === "enter_grace") { + // what the real handler would do if the ordering were wrong + conn.leaseState = "offline"; + conn.evictionTimer = setTimeout(() => { /* would evict */ }, 90_000); + } + }; + const was = reattachLease(conn, newWs, closeOld, 123); + expect(was).toBe("online"); + expect(seenAction).toBe("ignore_replaced"); + expect(conn.ws).toBe(newWs); + expect(conn.leaseState).toBe("online"); + expect(conn.evictionTimer).toBeNull(); + expect(conn.lastPongAt).toBe(123); + }); + + test("even if a handler wrongly arms a grace timer during closeOld(), the lease ends online with no timer (the prod 20:40Z recurrence)", () => { + const oldWs = mk("old"); + const newWs = mk("new"); + const conn = { ws: oldWs, leaseState: "online" as const, leaseUntil: 0, evictionTimer: null as ReturnType | null, lastPongAt: 0 }; + let fired = false; + reattachLease(conn, newWs, () => { + conn.leaseState = "offline"; + conn.leaseUntil = Date.now() + 90_000; + conn.evictionTimer = setTimeout(() => { fired = true; }, 5); + }); + expect(conn.leaseState).toBe("online"); + expect(conn.leaseUntil).toBe(0); + expect(conn.evictionTimer).toBeNull(); + return new Promise((r) => setTimeout(() => { expect(fired).toBe(false); r(); }, 20)); + }); + + test("reattach of an offline (grace) lease clears its eviction timer and never calls closeOld on the same socket", () => { + const ws = mk("same"); + let closed = 0; + const conn = { ws, leaseState: "offline" as const, leaseUntil: 99, evictionTimer: setTimeout(() => {}, 90_000), lastPongAt: 0 }; + const was = reattachLease(conn, ws, () => { closed++; }); + expect(was).toBe("offline"); + expect(closed).toBe(0); + expect(conn.evictionTimer).toBeNull(); + expect(conn.leaseState).toBe("online"); + }); +}); diff --git a/apps/cli/src/daemon/run.ts b/apps/cli/src/daemon/run.ts index 606d864..4d4028f 100644 --- a/apps/cli/src/daemon/run.ts +++ b/apps/cli/src/daemon/run.ts @@ -556,12 +556,14 @@ export async function runDaemon(opts: RunDaemonOptions = {}): Promise { process.stdout.write(JSON.stringify({ msg: "daemon_shutdown", signal: sig, ts: new Date().toISOString() }) + "\n"); inboxPruner.stop(); if (drain) await drain.close(); - for (const b of brokers.values()) { - try { await b.close(); } catch { /* ignore */ } - } - for (const b of sessionBrokers.values()) { - try { await b.close(); } catch { /* ignore */ } - } + // 1.37.1: close every broker socket IN PARALLEL and wait for the close + // frames to flush (each close() is bounded to ~1 s). Sequential awaits + // + an unflushed exit left the broker seeing no close at all on a + // clean restart — see WsLifecycle.close(). + await Promise.allSettled([ + ...[...brokers.values()].map((b) => b.close()), + ...[...sessionBrokers.values()].map((b) => b.close()), + ]); sessionBrokers.clear(); // ipc.close() ends every open SSE response (MCP plugins see a clean // `end` and resubscribe to the next daemon) before the listeners go. diff --git a/apps/cli/src/daemon/ws-lifecycle.ts b/apps/cli/src/daemon/ws-lifecycle.ts index 7b0b53e..3464b51 100644 --- a/apps/cli/src/daemon/ws-lifecycle.ts +++ b/apps/cli/src/daemon/ws-lifecycle.ts @@ -130,6 +130,8 @@ export interface WsLifecycle { } export const DEFAULT_HELLO_ACK_TIMEOUT_MS = 15_000; +/** Upper bound `close()` waits for the close handshake to reach the wire. */ +export const CLOSE_FLUSH_MS = 1_000; const DEFAULT_BACKOFF_CAPS_MS: readonly number[] = [1_000, 2_000, 4_000, 8_000, 16_000, 30_000]; const defaultLog: WsLog = (level, msg, meta) => { @@ -347,6 +349,23 @@ export function createWsLifecycle(opts: WsLifecycleOptions): WsLifecycle { if (sock.readyState === sock.CONNECTING) sock.terminate(); else sock.close(); } catch { /* ignore */ } + // 1.37.1: wait (bounded) for the close handshake to actually reach + // the wire. `shutdown()` calls close() on every client and then + // `process.exit()`; without this the close frames were still in + // the kernel buffer when the process died, so the broker saw no + // close at all, kept the leases "online" for 75–90 s until its + // stale-pong watchdog killed them, and the NEXT daemon's hellos + // reattached onto still-"online" leases — the exact precondition + // for the RC-C eviction (2026-09-08 20:40Z clean restart: 4 + // reattached presences evicted at 20:42:05). A flushed close makes + // the broker start grace immediately and the reattach lands on an + // `offline` lease — the safe path, even on pre-fix brokers. + if (sock.readyState !== sock.CLOSED) { + await new Promise((resolve) => { + const t = setTimeout(resolve, CLOSE_FLUSH_MS); + sock.once("close", () => { clearTimeout(t); resolve(); }); + }); + } } setStatus("closed"); if (!readySettled) { diff --git a/apps/cli/tests/unit/ws-lifecycle.test.ts b/apps/cli/tests/unit/ws-lifecycle.test.ts index 02c0b40..bacffcb 100644 --- a/apps/cli/tests/unit/ws-lifecycle.test.ts +++ b/apps/cli/tests/unit/ws-lifecycle.test.ts @@ -187,3 +187,23 @@ describe("createWsLifecycle — session_replaced is terminal (spec addendum 6)", await handle.close(); }); }); + +describe("createWsLifecycle — close() flushes the close handshake (spec addendum 7)", () => { + let broker: FakeBroker | null = null; + afterEach(async () => { if (broker) { await broker.close(); broker = null; } }); + + it("resolves only after the broker has observed the close (so process.exit right after is safe)", async () => { + const serverCloses: number[] = []; + broker = await startFakeBroker((sock) => { + sock.on("close", (code) => serverCloses.push(code)); + sock.send(JSON.stringify({ type: "hello_ack" })); + }); + const { handle } = makeClient(broker.url); + await handle.ready; + await handle.close(); + // The broker side has already seen the close frame when close() resolves. + expect(serverCloses).toHaveLength(1); + expect(serverCloses[0]).toBe(1005); // close() without a code → no status + expect(handle.status).toBe("closed"); + }); +});