fix: reattachLease ordering contract + flushed daemon shutdown (20:40Z recurrence = RC-C)

The 20:40Z clean-restart recurrence (spec Addendum 7) is the same RC-A/RC-C
mechanism, with prod evidence: 4 reattached presences (was:"online") hit
"lease grace started" 2.5 s later and were evicted at 20:42:05 — exactly
their disconnected_at. last_ping_at froze because the ping loop skips
offline leases; the freeze is a symptom, not a separate ping bug.

- broker: the swap-before-close ordering now lives in lease.ts#reattachLease
  and is unit-tested with a close callback that fires synchronously (Bun
  emulation): the handler sees ignore_replaced; a mis-behaving handler that
  arms a grace timer still leaves the lease online with no timer.
- cli: WsLifecycle.close() waits (<=1 s) for the socket's close event and
  shutdown() closes all broker clients in parallel, so a clean restart's
  close frames reach the broker before process.exit. Prod showed the old
  daemon's 17 sockets were only reaped by the 75 s stale-pong watchdog,
  which is why the next daemon reattached onto "online" leases (the RC-C
  path) instead of "offline" ones. Test: close() resolves only after the
  fake broker observed the close.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
Alejandro Gutiérrez
2026-09-08 23:10:27 +01:00
parent dd351a7846
commit c138e0bceb
7 changed files with 173 additions and 27 deletions

View File

@@ -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).

View File

@@ -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;

View File

@@ -133,3 +133,47 @@ export function findZombieSockets<WS extends ZombieSocketView>(
/** 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<WS> extends LeaseConnView<WS> {
leaseUntil: number;
evictionTimer: ReturnType<typeof setTimeout> | 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<WS>(
conn: SwappableLease<WS>,
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;
}

View File

@@ -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<typeof setTimeout> | 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<typeof setTimeout> | 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<void>((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");
});
});

View File

@@ -556,12 +556,14 @@ export async function runDaemon(opts: RunDaemonOptions = {}): Promise<number> {
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.

View File

@@ -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<void>((resolve) => {
const t = setTimeout(resolve, CLOSE_FLUSH_MS);
sock.once("close", () => { clearTimeout(t); resolve(); });
});
}
}
setStatus("closed");
if (!readySettled) {

View File

@@ -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");
});
});