spec: 2026-09-08 daemon-restart mesh blackout — incident, root causes, work order
Spec-first record of the live incident (peer list empty on every mesh after a launchd respawn of the daemon). Addenda 1-4 by the reporting session; Addenda 5-6 verify them against code + broker/daemon logs and add the two root causes found while reproducing locally: - RC-A/RC-C (broker): the ws close handler mutated lease state after an await, and under Bun the ws shim fires the replaced socket's close event synchronously inside close() — both put a healthy reattached lease into grace and evicted it 90 s later while its socket stayed open (ghost). - RC-B (broker): mesh.presence at 2.49 M rows with no index beyond the PK; hello latency ~5 s under the reconnect storm. - Daemon: connect() lost the lifecycle handle on a first hello-ack timeout (peer list = [] forever), unbounded drain retries + 1 GB unrotated log, no exit forensics, MCP SSE never resubscribed after a hard daemon death, CLI stale-probe unlinking a live daemon's pid/socket (two daemons). Raw log excerpts stay local under .artifacts/test-runs/ (identifiers). Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
122
.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md
Normal file
122
.artifacts/specs/2026-09-08-daemon-restart-mesh-blackout.md
Normal file
@@ -0,0 +1,122 @@
|
||||
# 2026-09-08 — Daemon restart → mesh blackout (peer list empty, sessions "invisible")
|
||||
|
||||
**Status:** diagnosed on a live incident, fix pending. Owner: claudemesh repo session.
|
||||
**Reporter:** flexicar-orchestrator session (evidence gathered read-only from `~/.claudemesh/daemon/daemon.log`, live CLI probes, and source on `main` @ 1.37.0).
|
||||
|
||||
## Symptom (user-visible)
|
||||
After the local daemon restarted (launchd `com.claudemesh.daemon` KeepAlive), `claudemesh peer list` returned **0 peers on EVERY mesh** (flexicar, minery, legalrag, nedas-mesh…) for >40 min, although all 8 Claude sessions were alive. Sends by session pubkey reported `queued — no connected peer matches this key`. The whole orchestration went dark. User verdict: **"in case of daemon restart, sessions should be reconnected — this must not happen."**
|
||||
|
||||
## Timeline (UTC; local = UTC+1)
|
||||
- 2026-09-05 20:56:59Z — daemon pid 85205 started (ran ~3 days).
|
||||
- 2026-09-08 ~19:27–19:28Z — pid 85205 **died without logging a single line** (no exit/uncaught/SIGTERM in daemon.log, no crash report in `~/Library/Logs/DiagnosticReports`, no memorystatus kill in `log show`). launchd respawned: pid 93782 at 19:28:07 (died within 6 s — crash-loop once), pid 94504 at 19:28:13 (stable, still running).
|
||||
- 19:28:07 and 19:28:13 — `sessions_rehydrated revived=8 persisted=8` → **rehydration WORKS**: registry restored from `sessions.json`, keypairs re-derived, `onRegister` created a `SessionBrokerClient` per session.
|
||||
- 19:28:12–19:28:20 — daemon-level mesh WS: `broker_ws_hello_sent` → `broker_hello_ack_timeout` (all 9 meshes, 5 s) → `broker_ws_closed 1005` → `broker_ws_reconnect_scheduled` → reconnect → `broker_ws_hello_acked` at 19:28:20.
|
||||
- 19:28:19+ — every per-session WS: `session_broker_ws_open_attempt/open_ok/hello_acked` for ALL session pubkeys (02b5b7d5, 0fdf7159, 612fa2bc, 9f0e1c09, aee93b3b, e051e316, f34b4b9f, …). Some flapped (aee93b3b ×4 attempts, 2 closed).
|
||||
- 20:09 / 20:18Z — `drain_max_attempts err=broker_not_open` for 2 outbox rows (a session WS was NOT open at drain time despite hello_acked earlier → flapping).
|
||||
- 20:09:01 / 20:10:08Z — two sessions relaunched by the user → `session_registered` via IPC → hello_acked. **Still 0 peers.**
|
||||
- Broker (`ic.claudemesh.com`): `/health` ok, uptime 5.34 M s (~62 d, NOT redeployed), db up.
|
||||
|
||||
## What IS working after the restart
|
||||
- Registry rehydration (8/8), keypair re-derivation, attestation re-mint.
|
||||
- Per-session broker WS: open + hello_acked for every session (so the broker's **in-memory** conn map has them, lease `online`).
|
||||
- Inbound pushes: `claudemesh inbox` still lists prior messages; `/v1/events` SSE reconnects by itself (mcp/server.ts).
|
||||
|
||||
## What is BROKEN
|
||||
1. **`list_peers` → empty on all meshes.** Broker `list_peers` handler = `listPeersInMesh(meshId)` = **DB** query `presence WHERE disconnectedAt IS NULL`. Empty ⇒ the DB presence rows are marked disconnected while the in-memory lease is `online` → **split-brain between in-memory conn map and the presence table**. Hypothesis (p≈0.8): the old daemon died without close frames → broker WS closes → lease grace (90 s) → new daemon reattached within grace (`session_hello reattach`, `restorePresence(pid)` fire-and-forget `void`) → later the **DB-level stale-presence sweeper** (keyed on `lastPingAt`) flips the rows back to `disconnectedAt = now` because pongs on the reattached WS don't refresh `lastPingAt` for the reattached presence id — or `restorePresence` lost a race with the sweeper. Either way `restorePresence` is a one-shot patch on a row the sweeper keeps re-flipping. Needs confirmation from broker logs (`ws hello reattach (lease)`, `session_hello reattach`, sweeper output) and `SELECT id,session_pubkey,disconnected_at,last_ping_at FROM presence WHERE …` on the broker DB (OVH via Coolify; SSH needs Tailscale re-auth right now).
|
||||
2. **daemon.log = 1.0 GB** (disk at 95 %). `drain.ts:186` logs `drain_session_ws_not_ready` on EVERY drain tick for EVERY outbox row whose session WS isn't open — 117 797 lines in the last 20 MB, mostly for **stale session pubkeys from previous days** (4e00fc666559 ×70 676, cb26f393232e ×15 708 …) that will never reconnect. Rows are backed off but never expired; the log grows unbounded (launchd `StandardOutPath` → no rotation). This is the most plausible cause of the silent death of pid 85205 (I/O or disk pressure) — unproven.
|
||||
3. **Session WS flapping** after rehydration (multiple open/close cycles per session, `broker_not_open` at drain time). Likely the same-pubkey ghost handling on the broker (`session_replaced` close of the older socket) racing the reconnect helper. Needs broker logs.
|
||||
4. **Recovery UX**: nothing tells the user the mesh is in this state; `peer list` just says "no peers". A relaunch of a session does NOT fix it (proven twice today).
|
||||
|
||||
## Work order (spec-first, then code, then tests, then release)
|
||||
1. **Reproduce locally**: broker + daemon in a test harness: kill daemon with SIGKILL → launchd-style respawn → assert `peer list` non-empty within 10 s for rehydrated sessions; assert presence rows `disconnectedAt IS NULL` after reattach AND after one stale-sweep cycle.
|
||||
2. **Broker fix**: make the reattach path authoritative for the DB row: `restorePresence` awaited + sweeper must not flip a row whose in-memory lease is `online` (or the pong handler must bump `lastPingAt` for reattached presences). Add a self-heal: on `list_peers`, reconcile DB rows against the in-memory `connections` map (online lease ⇒ include). Log at `warn` when DB/in-memory disagree.
|
||||
3. **Daemon fix (drain.ts)**: rate-limit `drain_session_ws_not_ready` (log once per row per N minutes), expire outbox rows for session pubkeys with no registry entry after `max(attempts)`/TTL, and **rotate daemon.log** (size cap + keep N) — launchd writes stdout directly, so rotate in-process or via `newsyslog`/`logrotate`-style config installed by `daemon install-service`.
|
||||
4. **Daemon crash forensics**: install an `uncaughtException`/`unhandledRejection` + `SIGTERM` logger with flush, and a `daemon_exit` line, so the next silent death has a cause.
|
||||
5. **Operator signal**: `claudemesh doctor` (or `daemon status`) must detect "sessions registered + WS hello_acked but list_peers empty" and say so, with the one-command fix.
|
||||
6. Release as 1.37.1 (cli) + broker deploy; verify on this Mac: `claudemesh peer list --mesh flexicar` shows the 8 sessions without relaunching any of them.
|
||||
|
||||
## Evidence pointers
|
||||
- `~/.claudemesh/daemon/daemon.log` (1 GB — grep, don't cat): `sessions_rehydrated`, `broker_hello_ack_timeout`, `session_broker_ws_*`, `drain_max_attempts`, `drain_session_ws_not_ready`.
|
||||
- `~/.claudemesh/daemon/sessions.json` (persisted registry).
|
||||
- Broker source: `apps/broker/src/index.ts` L1925-1960 (member reattach), L2225-2262 (session reattach), `apps/broker/src/broker.ts` L431-445 `restorePresence`, L448+ `listPeersInMesh`, stale sweeper (`staleTimer`).
|
||||
- Daemon source: `apps/cli/src/daemon/run.ts` L212-300 (`onRegister`), L312-384 (rehydrate), `apps/cli/src/daemon/drain.ts` L182-200, `apps/cli/src/daemon/session-registry.ts` (persist/reaper).
|
||||
|
||||
## Addendum — outbox state at 20:35Z (`claudemesh daemon outbox list`)
|
||||
- `pending` rows with **attempts=120 038 … 132 380**, `last_error="session_ws_not_open"` → the drain loop has retried the same 4 rows ~130 k times (≈ once per second for days) for session pubkeys that no longer exist. This IS the 1 GB log. Rows must expire.
|
||||
- `dead` rows `max_attempts: no connected peer for target (not online…)` at attempts=25 → the **broker** rejected delivery because its DB says the target is offline, while the target's WS is hello_acked → confirms the presence split-brain (item 1). Consequence: after a daemon restart, **DMs to live sessions are refused**, not just discovery.
|
||||
- A fresh `send` now returns `recipientOnline:false, status:queued` for a session whose WS hello_acked minutes earlier.
|
||||
|
||||
## Addendum 2 — broker-side evidence (OVH, container `mcn8m74tbxfxbplmyb40b2ia-…`, image = commit a9b735a; DB schema `mesh.*`)
|
||||
**Broker log 19:28:05–19:31Z (counts):** 30 `ws close — lease grace started` · 27 `ws evict full` · 22 `lease grace expired — evicting` · 12 `session_hello reattach` · 9 `hello dedup` · 5 `ws session_hello` · 27 `ws hello`. Two daemons (pid 93782 lived 6 s, then 94504) both rehydrated 8 sessions and raced the broker within the same 90 s grace window while the broker was still processing the dead daemon's socket closes. Mesh-level hellos of 94504 hit `broker_hello_ack_timeout` (5 s) for all 9 meshes → `broker_ws_closed 1005` → reconnect → acked at 19:28:20 (broker was busy with the storm).
|
||||
|
||||
**Final broker DB state for `flexicar` (`mesh.presence`, `disconnected_at IS NULL`):** online = `aee93b3b` (intranet 2ad05da8), `8494e7e4` (cliente-front relaunched), `612fa2bc` (crm-api), `0fdf7159` (intranet f8b797d1), + control-plane `daemon-94504`. **GHOSTS (evicted on the broker, socket still open on the daemon, no `session_broker_ws_closed` in daemon.log):** `9f0e1c09` (orchestrator), `02b5b7d5` (crm-front), `e051e316` (cliente-back), `f34b4b9f` (old cliente-front). Their presences (`sUNqkMO9`, `ePekV8WH`, `BsheM0ey`, `Qxauubu7`) got `ws close — lease grace started` at 19:28:17.9–18.3 (1 s AFTER `session_hello reattach` by 94504 at 19:28:17.0–17.2) and were `lease grace expired — evicting` at 19:29:43–50. `evictPresenceFully` does NOT `ws.close()` the socket it evicts → the daemon keeps a half-open WS forever, never reconnects → session unreachable and invisible, `list_peers`/DMs from that session go into a void.
|
||||
|
||||
**Why `peer list` showed 0 on EVERY mesh from the orchestrator:** the CLI inside a launched session is session-scoped (token env) → `list_peers` travels over the ghost session WS → no answer/empty. The member-scope check is in the next addendum.
|
||||
|
||||
**`hello dedup` design flaw:** the launch wrapper's member-level `hello` carries `session_id = <claude session UUID>`; the broker's session-id dedup then KICKS the live `session_hello` presence with the same UUID (`hello dedup old_presence=a5eDg0aj`), the daemon's `session_hello` then kicks the wrapper's presence (`session_hello dedup`) — 2 evictions + 2 DB disconnects + a forced WS close per relaunch (seen at 20:10:04–20:10:44 for intranet: a5eDg0aj → FYL5tnMl → MgXl7se3 → CBj9nWzr → JVuLGue1). Control-plane and session presences must not dedup each other by session_id.
|
||||
|
||||
**Also seen:** hourly `orphan msg sweep` throws `DrizzleQueryError … TypeError: The "string" argument must be of type string … Received an instance of Date` — the sweep is broken (Date passed where a string is expected).
|
||||
|
||||
**Fix list (broker):** (1) `evictPresenceFully` must `ws.close(1000,"evicted")` so the client reconnects; (2) a server-side liveness probe: if a socket is open but its presence is gone, close it; (3) `hello dedup` must be scoped by role (control-plane vs session); (4) mesh `hello_ack` must not time out under load (ack before heavy work, or raise/adapt the client timeout); (5) fix the orphan-sweep Date bug. **Fix list (daemon):** (6) SessionBrokerClient: detect a dead-but-open WS (missing server pings / no hello_ack refresh) and reconnect; (7) after rehydration, verify presence with the broker (`sessions/me` or a `whoami` ping) and re-hello if absent; (8) never run two daemons within the same grace window (launchd ThrottleInterval / startup lock) — the 6 s crash-loop doubled the storm.
|
||||
|
||||
## Addendum 3 — ROOT CAUSE of "peer list empty on every mesh" (daemon side, confirmed in code + log)
|
||||
`apps/cli/src/daemon/broker.ts` `connect()`:
|
||||
```ts
|
||||
this.lifecycle = await connectWsWithBackoff({ ..., onStatusChange: (s) => { this._status = s; ... } });
|
||||
```
|
||||
On 2026-09-08 19:28:17.889Z the first `hello_ack` timed out (5 s; broker busy with the storm) → `connectWsWithBackoff` **rejected** → `this.lifecycle` was **never assigned** (`broker connect failed for flexicar: Error: hello_ack_timeout`, ×9 meshes). But the helper's internal reconnect loop kept running on the same object: `broker_status reconnecting → connecting → open` at 19:28:20.187Z and `onStatusChange` set `_status = "open"`. Net state: **`_status === "open"` AND `lifecycle === undefined`** → every method gated on `this.lifecycle` short-circuits:
|
||||
- `listPeers()`: `if (this._status !== "open" || !this.lifecycle) return [];` → `/v1/peers` answers `{"peers":[]}` in **30 ms** (measured; a real broker round trip is ≥200 ms) → `peer list` = 0 on all 9 meshes, forever, without any warning.
|
||||
- `isOpen()` reads `this.lifecycle?.ws` → false → `send()` no-ops → outbox drain logs `drain_max_attempts err=broker_not_open` for member-keyed rows.
|
||||
- `listSkills`, `getState`, etc. → same.
|
||||
The control-plane presence (`daemon-94504`) IS online on the broker (DB row `XqS1ExHG`, disconnected_at NULL), so the WS is real — the daemon just lost its handle to it.
|
||||
|
||||
**Fix:** `connectWsWithBackoff` must hand back the lifecycle handle **synchronously** (before the first ack) and expose readiness separately (`await lifecycle.ready`), so a first-ack timeout cannot orphan a live reconnecting socket; `connect()` must not reject while the helper is still retrying; add an invariant check (`_status === "open" && !lifecycle` → log error + self-heal by re-running connect). Regression test: simulate hello_ack timeout on first attempt + ack on the second → `listPeers()` must return the broker's list.
|
||||
|
||||
**Two daemons in 6 s:** launchd respawned pid 93782 which died within 6 s (cause unknown — no `daemon_shutdown`, no crash report; the clean `shutdown()` handler only logs on SIGINT/SIGTERM) → doubled hellos/reattaches/dedups in the same 90 s grace window. Needs `daemon_exit`/`uncaughtException` logging and a launchd `ThrottleInterval`.
|
||||
|
||||
## Addendum 4 (CORRECTED 20:55Z) — after a daemon restart, delivery INTO Claude Code survives via the hook fallback; the live SSE push path does NOT
|
||||
**Wrong claim retracted:** "no session receives pushes". Verified end-to-end after the clean restart: DM `req:ping-3` (20:41:11Z) → crm-api woke up with the injected prompt `[claudemesh] peer message arrived while idle - surface new inbox message(s)`, read its inbox and replied `ack:pong3` (20:41:39Z, in the orchestrator's inbox). So **messages reach sessions after a restart** — through the local hook layer (`~/.claude/hooks/claudemesh-wake-watcher.sh` for idle sessions, `claudemesh-inbox-drain.sh` on Stop/UserPromptSubmit, `claudemesh hook idle|working`), which polls the daemon via CLI/IPC on each tick and therefore survives daemon restarts. Latency = the watcher's poll interval, not immediate.
|
||||
|
||||
**What is dead after the restart:** the MCP plugin's SSE subscription (`/v1/events`) — the path that injects `<channel>` blocks **mid-turn** into a working session. Evidence: `lsof` shows none of the 10 live `claudemesh mcp` processes connected to the daemon (neither UDS `daemon.sock` nor TCP `127.0.0.1:47823`), and `mcp-*.log` has 0 `sse_event_received` after 20:40Z. Cause: `subscribeEvents` (`mcp/server.ts`) reconnects only on `res 'end'` / `req 'error'`; `res 'error'/'close'/'aborted'` (what a killed or `process.exit`-ed daemon produces) only logs to stderr — no reconnect, no heartbeat. Claude Code does not respawn the stdio server. Consequence: a **working** session no longer sees peer messages until its next Stop/prompt hook fires, and `now`-priority interrupts are lost until then.
|
||||
|
||||
**Fix (unchanged):** reconnect on every termination event + SSE heartbeat/idle-timeout + daemon `shutdown()` ends SSE responses before exit + replay unread on resubscribe + log reconnects to `mcp-<pid>.log`. Regression test: `kill -9` daemon under an active SSE client → resubscribed within 5 s of the new daemon accepting → a DM sent afterwards is `channel_emitted` (not only hook-drained).
|
||||
|
||||
## Addendum 5 (claudemesh repo session, 21:50Z) — verification of Addenda 1-4 + two more root causes + final design
|
||||
|
||||
**Verified against code + logs (broker `a9b735a` = HEAD, daemon 1.37.0):** Addendum 1's hypothesis (stale-presence sweeper flipping rows / pongs not refreshing `lastPingAt`) is **NOT** what happened — the `pong` handler bumps `lastPingAt` for the reattached presence id correctly. Addendum 2 (evict without closing the socket → ghost) and Addendum 3 (lost lifecycle handle) are **confirmed** and are the two visible mechanisms. Addendum 2's line "list_peers travels over the ghost session WS" is wrong (the session WS carries no RPCs) — Addendum 3 is the correct explanation for the empty list. Two more root causes found:
|
||||
|
||||
### RC-A (broker) — why a HEALTHY reattached lease was evicted: async gap in `ws.on("close")`
|
||||
`index.ts` close handler: `if (conn.ws !== ws) return;` → **`await savePeerState(...)`** → `if (conn.leaseState === "online") enter grace else evict`. The `conn.ws === ws` check happens BEFORE the await, the lease mutation AFTER. Under DB latency the handler of the *dead daemon's* socket resumes after the *new daemon* has already reattached (`conn.ws` swapped, `leaseState = "online"`) and wrongly (a) starts grace on a lease whose new socket is alive, or (b) if a previous late handler already set `offline`, evicts immediately. Log proof: `ws close — lease grace started` for `ePekV8/sUNqkMO9/BsheM0ey` at 19:28:17.9–18.4, i.e. 0.85–1.2 s after `session_hello reattach` for the same pids, with **no `session_broker_ws_closed` in daemon.log** for those sockets; and 5 `ws evict full` at 19:28:16.4–16.9 with no `lease grace expired` (the "already offline" branch). Combined with Addendum 2 (no `ws.close()` on evict) the new socket becomes a zombie: OPEN on both ends, pings/pongs flow (the `ws` lib auto-pongs), no presence.
|
||||
|
||||
### RC-B (broker, degradation) — why the broker was slow enough for the race + the 5 s hello timeouts
|
||||
`mesh.presence` has **2,491,950 rows** (2,488,046 with `disconnected_at` older than 30 d) and **no index except the PK**. `sweepStalePresences` (every 30 s), `listPeersInMesh`, `handleHookSetStatus` and the join in the fan-out paths **full-scan 2.5 M rows**; the postgres.js pool is the default 10. A restart storm (17 closes + 17 hellos + 9 timed-out re-hellos in ~10 s, each doing 4-8 queries) queued behind the scans → hello acks took 4–5 s (`hello_sent 13.25 → hello_acked 17.08–18.32`), which is what tripped the daemon's 5 s ack timeout and stretched the close handlers' awaits into the race window. Recurrence: guaranteed to worsen with N (≈ +1 row per session connect, never deleted). Fix = indexes + retention, not a bigger timeout.
|
||||
|
||||
### Final design (what ships in 1.37.1 / broker deploy)
|
||||
**Broker**
|
||||
1. Close handler: lease transition is **synchronous** (no await before it); `savePeerState` runs after, fire-and-forget; close code+reason logged. Eviction timer re-checks `leaseState === "offline"` before evicting (defensive).
|
||||
2. `evictPresenceFully(pid, reason)`: if the socket is still OPEN → `ws.close(4004, "presence_evicted")` so the client reconnects and re-hellos. Reason logged.
|
||||
3. Zombie sweeper (in the 30 s ping loop): any `wss.clients` socket that is OPEN, older than 60 s and not referenced by a `connections` entry → `close(4005, "no_presence")`.
|
||||
4. Dedup scoped by role: member `hello` dedup only kicks `control-plane` presences; `session_hello` dedup only kicks `session` presences (fixes the mutual-kick chain of Addendum 2).
|
||||
5. `sweepOrphanMessages` rewritten with the query builder (fixes the `Date`-param DrizzleQueryError; the hourly sweep has been failing).
|
||||
6. Presence retention: hourly + at startup, batched `DELETE FROM mesh.presence WHERE disconnected_at < now() - 30 d` (20k/batch). Migration `0030_presence_indexes.sql`: partial indexes on `(member_id) WHERE disconnected_at IS NULL`, `(last_ping_at) WHERE disconnected_at IS NULL`, plus `(disconnected_at)` for the retention delete. Hello handlers log `latency_ms`.
|
||||
**Daemon / CLI**
|
||||
7. `ws-lifecycle.ts`: `createWsLifecycle()` returns the handle **synchronously**; `ready` resolves on the first ack; a hello-ack timeout only forces a backoff reconnect (never rejects/orphans). `close()` is always effective. Ack timeout default 5 s → 15 s. Both clients store the handle before awaiting `ready`. Invariant `status==="open" ⇒ lifecycle` holds by construction.
|
||||
8. `drain.ts`: `drain_session_ws_not_ready` logged on attempt 1 and every 60th; not-ready path counts against the attempt cap; rows whose session pubkey has no registered session for >10 min → `dead session_gone`; any pending row older than 24 h → `dead expired`.
|
||||
9. Rotating log sink (`daemon/log-sink.ts`): when `daemon up --foreground` runs without a TTY (launchd/systemd), stdout/stderr are redirected to `daemon.log` with a 20 MB cap × 5 files and a total-budget purge; the service unit's StandardOut/Err become `daemon.launchd.log` (pre-init crashes only). Existing oversized log is rotated on first start (incident excerpts preserved in `.artifacts/test-runs/`).
|
||||
10. Forensics: `uncaughtException` / `unhandledRejection` / `exit` / `SIGHUP` / `SIGTERM` all write a `daemon_exit`/`daemon_uncaught` line synchronously before exit; plist gets `ThrottleInterval 10`.
|
||||
11. MCP SSE (`mcp/server.ts subscribeEvents`): reconnect on `res close/aborted/error` and `req close`, idle watchdog (daemon sends `: keepalive` every 15 s → no bytes for 45 s ⇒ destroy + reconnect), reconnects logged to `mcp-<pid>.log`; daemon `shutdown()` ends open SSE responses before exit.
|
||||
12. Operator signal: `GET /v1/diagnostics` (per-mesh member WS status + per-session WS status + log size); `claudemesh daemon status` prints it; `claudemesh doctor` adds: daemon version = CLI version, every member WS open, every registered session's WS open, **every registered session present in the broker's peer list** (the ghost detector), daemon.log size + stale service unit. Each with the one-command fix (`claudemesh daemon restart` / `claudemesh daemon install-service`). `peer list` prints a warning when the daemon's member WS for that mesh is not open instead of a silent empty list.
|
||||
**Tests**: vitest for the lifecycle (first ack times out, second succeeds → same handle, `listPeers` returns the broker's list; `close()` before ack stops retries), drain expiry/rate-limit, log rotation, broker pure helpers (close-action decision, role-scoped dedup, zombie selection, orphan-sweep query shape).
|
||||
**Release/deploy**: CLI 1.37.1 (npm + `cli-v1.37.1` tag) and broker via `git push gitea-vps main` → Coolify. Broker deploy first (the new close codes are harmless to old clients), then CLI upgrade + `claudemesh daemon restart` here, then the SIGKILL drill: `kill -9 <daemon pid>` → launchd respawn → `peer list --mesh flexicar` shows every live session within 10 s without relaunching any.
|
||||
|
||||
## Addendum 6 (claudemesh repo session, 22:15Z) — local reproduction results + RC-C (the actual eviction trigger) + two-daemon hazard
|
||||
|
||||
**Reproduction harness** (all local, nothing touched in prod): new broker (`bun src/index.ts`) on `:7955` against a throwaway pgvector Postgres (`docker cmh-test-pg`, migrations 0000–0030 applied by the runtime runner); isolated CLI 1.37.1 daemon (`CLAUDEMESH_CONFIG_DIR/DAEMON_DIR/SESSIONS_DIR=/tmp/cmh-drill/*`, `--foreground --no-tcp`, no TTY → rotating sink active); two fake sessions registered over IPC with live `sleep` pids and real session keypairs + parent attestations.
|
||||
|
||||
**Drill 1 — SIGKILL + respawn (the incident shape):** sessions visible in `peer list` at **t+1 s** after respawn; broker: `ws close 1006 → enter_grace` ×3, then `session_hello reattach was:offline` ×2; daemon: `sessions_rehydrated revived=2`. No eviction. PASS.
|
||||
|
||||
**Drill 2 exposed RC-C.** A minimal 20-line repro (two `session_hello` clients, same pubkey) against the local broker shows the old socket's `close` event logged BEFORE the `session_hello reattach` line, with `action: enter_grace`. Verified with an isolated script: **under Bun (the production runtime) the `ws` shim emits the server-side `close` event SYNCHRONOUSLY inside `ws.close()`; Node emits it on a later tick.** Consequence in the reattach path (`oldConn.ws.close(1000,"session_replaced")` → `oldConn.ws = ws`): the close handler runs while `conn.ws` is still the old socket → sees an online lease → starts grace + arms a 90 s eviction timer → the swap then sets the lease online again but the timer stays armed (the reattach's `clearTimeout` ran before the close) → **90 s later the healthy, reattached lease is evicted, socket left open → ghost.** In the pre-fix handler the same sequence ran with an extra `await savePeerState` in between, which is why prod logged `lease grace started` 0.85–1.2 s after `reattach` (DB latency) and `lease grace expired — evicting` ~90 s later for exactly the reattached pids (19:29:47–50). This is the primary trigger of the blackout; RC-A (async gap) is the second way the same handler could misfire. Fix: swap `conn.ws`/lease state BEFORE closing the replaced socket, clear timers AFTER; dedup paths `dropConnection()` before `close()`; the grace timer re-checks `leaseState` before evicting (this guard alone already prevented the eviction in drill 2 — logged `lease grace timer fired on online lease — skipped`). Pure-logic tests in `apps/broker/tests/lease.test.ts`.
|
||||
|
||||
**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).
|
||||
Reference in New Issue
Block a user