operator-main
ad9dbca7eb
Re-applies three workstreams lost when 793d3d7 committed over uncommitted
edits, reconciled against the parallel track's committed dm.py changes:
- followup-sweeper.py: backfill thread_uuid after successful nudge sends;
record final_nudge_target=main on final-nudge routing (C1/C2)
- response-harvester.py: resolve followups on main-chat replies when
final_nudge_target=main (C3); harvest ALL [RESULT] markers per message
- dm.py: pre-send placement gate (fail closed when post-nav URL lacks the
target thread UUID; skips main) — purely additive over 793d3d7+f268d3d
- sidechat_manager.py: wait_for_chat_list() settle-poll for list population
race (sidebar button renders before titles load)
- new: bin/tests/test_followup_fixes.py (25 tests), bin/placement-audit.py,
bin/dm-log-taxonomy.py, bin/session-probe.py,
docs/SIDECHAT-RELIABILITY.md, docs/UUID-ROTATION.md
Verified: 25/25 tests pass, py_compile clean, sweeper/harvester dry-runs clean.
Known limitation: gate catches wrong-placement, not wrong-mapping (false
autoprovision adopting the parked thread needs a creation check).
229 lines
13 KiB
Markdown
229 lines
13 KiB
Markdown
# Sidechat Reliability Runbook
|
||
|
||
Fleet sidechat DMs are the fleet's nervous system. On 2026-10-04 they were
|
||
measured at ~1/3 navigation success. This runbook is the single place that
|
||
explains how the machinery works, how each known failure looks in the logs,
|
||
and what to do when a DM doesn't arrive.
|
||
|
||
All paths below are on **bl** (`super@100.123.153.75`, via the VM).
|
||
Repo: `/home/super/Projects/NetVM` (git, local-only, no remotes).
|
||
|
||
Companion tools (all read-only unless noted):
|
||
- `bin/dm-log-taxonomy.py` — failure taxonomy over dm-log.jsonl (counts, nav-failure
|
||
breakdown per target/agent-pair, hourly bursts, ghost rate). Run: `python3 bin/dm-log-taxonomy.py`
|
||
- `bin/placement-audit.py` — human-readable placement/gate activity.
|
||
`placement-audit.py --since 24h`, `--since 60m`, `--watch`
|
||
- `bin/tests/test_followup_fixes.py` — 25 unit tests pinning the sweeper/harvester/gate contracts
|
||
|
||
---
|
||
|
||
## 1. Architecture (10 lines)
|
||
|
||
1. Operator (or timer) runs `bin/dm.py send --agent <node> --to <agent> --target <sidechat> "<msg>"`.
|
||
2. `dm.py` resolves the target name → thread UUID: `SIDCHAT_ALIASES` (intentionally
|
||
empty — hardcoded UUIDs rot), then `job-sidechats.json` dynamic mapping, then
|
||
passthrough name for sidebar search.
|
||
3. Unknown names autoprovision: `sidechat create` in the recipient's browser, and the
|
||
fresh UUID is registered in `job-sidechats.json` (self-healing).
|
||
4. Browser control goes `netvm-exec.sh <node> -- python3 muse-chat-api.py --account <node> <cmd>`,
|
||
which drives headless Chromium over CDP inside the node's Warp netns.
|
||
5. `dm.py` navigates to `/thread/<uuid>` (or sidebar title search), then the
|
||
**pre-send gate** (2026-10-04) independently samples the browser URL and requires
|
||
the expected UUID in it — fail-closed, never sends blind.
|
||
6. Send happens via CDP; `verify_placement()` re-navigates and reads the thread back
|
||
(post-send check, complementary to the pre-send gate).
|
||
7. Every step appends machine-readable events to `dm-log.jsonl` (`send_start`,
|
||
`nav_ok`, `sent`, `verified`, `placement_failed`, `pre_send_assert_failed`, …).
|
||
8. If the message carries `reply:expected` tags, `_register_followup()` arms a record in
|
||
`followups.json` (deadline, nudges, escalate target).
|
||
9. `followup-sweeper.py` (driven by gravity loop) sends nudges on expiry — in-thread
|
||
first, main chat on the final nudge — then escalates. It backfills `thread_uuid`
|
||
when a nudge provisions the thread.
|
||
10. `response-harvester.py` (every ~60s via `response-harvester.service`) reads agent
|
||
threads, records `[RESULT job_id]` markers to `job-log.jsonl`, and resolves
|
||
followups when an assistant reply lands in the matching thread.
|
||
|
||
---
|
||
|
||
## 2. Failure-mode catalog
|
||
|
||
How to read the signatures: `grep '"type": "<event>"' dm-log.jsonl`, or use
|
||
`placement-audit.py --since 24h` / `dm-log-taxonomy.py`.
|
||
|
||
### 2a. Landing-page nav (caught by the pre-send gate)
|
||
|
||
- **Signature:** `{"type":"pre_send_assert_failed","id":…,"agent":…,"to":…,
|
||
"target":…,"expected_uuid":…,"actual_url":"https://muse.ai/",
|
||
"reason":"url_mismatch"|"not_on_thread_page"|"direct_nav_failed"}`
|
||
- **Cause:** the browser never left the muse.ai landing page (or parked on the wrong
|
||
thread) after `sidechat use`; the old code would have sent anyway.
|
||
- **Effect:** send aborted, exit 1, nothing delivered, nothing marked verified.
|
||
- **Fix:** re-run the send; if it repeats, the nav layer is flapping — see §2g and the
|
||
nav workstream. The gate doing its job is *good news*, not a bug.
|
||
- **Owner:** dm.py placement-gate workstream (landed 2026-10-04).
|
||
|
||
### 2b. `sidechat_uuid_capture_failed` (autoprovision went nowhere)
|
||
|
||
- **Signature:** `{"type":"sidechat_uuid_capture_failed","id":…,"out":"https://muse.ai/"}`
|
||
- **Cause:** `sidechat create` ran but UUID capture saw the landing page — the thread
|
||
may or may not exist; dm.py cannot know.
|
||
- **Effect (pre-gate era):** the send proceeded with `thread_uuid: null` and reported
|
||
`verified:true` — a ghost send (see §2d). With the gate live, the send now fails
|
||
closed instead.
|
||
- **Owner:** dm.py autoprovision path; gate workstream.
|
||
|
||
### 2c. Stale UUID rotation (the UUID you have is dead)
|
||
|
||
- **Signature:** `{"type":"placement_failed",…,"expected_uuid":"<uuid>",
|
||
"actual_url":"https://muse.ai/thread/<different-uuid>","reason":"url_mismatch"}`
|
||
or `{"type":"placement_mismatch",…,"expected_uuid":…,"actual_uuid":…}`.
|
||
- **Cause:** thread UUIDs rotate — observed same-day (`heartbeat-opm`:
|
||
`5bd5b350` → `0077e918` → dead). Any hardcoded UUID is a time bomb; the SPA may
|
||
also redirect a dead-UUID nav to whatever thread was last open (misdelivery, not
|
||
just failure).
|
||
- **Fix:** never hardcode UUIDs — `SIDCHAT_ALIASES` in dm.py is intentionally empty
|
||
(sibling workstream removed the last hardcoded entries 2026-10-04, incl. the
|
||
twice-dead heartbeat UUID). Use name-based autoprovision + `job-sidechats.json`
|
||
dynamic mappings, which self-heal on re-provision.
|
||
- **Owner:** UUID-rotation workstream. TODO: `docs/UUID-ROTATION.md` not yet written;
|
||
this section is the interim reference.
|
||
|
||
### 2d. Placement-blind `verified:true` (the ghost send)
|
||
|
||
- **Signature:** `{"type":"verified","id":…,"agent":…,"target":…}` with **no**
|
||
`thread_uuid` field (or `"thread_uuid": null`), paired with a `sent` event —
|
||
and no `placement_failed`/`pre_send_assert_failed` anywhere near it.
|
||
- **Cause:** the old verify step checked the *current* browser chat, not the target
|
||
(see operator AGENTS.md). A send parked on the landing page still "verified".
|
||
- **Effect:** the message is lost but every downstream system believes it landed —
|
||
followups nudge a ghost, pipelines stall as `dispatched`.
|
||
- **Fix:** the pre-send gate (§2a) makes new ghost sends impossible (fail-closed).
|
||
For historical ghosts: backfill `thread_uuid` in `followups.json` once the thread
|
||
provisions, register the alias in `job-sidechats.json`, resolve manually with a note.
|
||
- **Owner:** gate workstream (prevention); operators (historical repair).
|
||
|
||
### 2e. Logged-out / dead session
|
||
|
||
- **Signature:** no single event type. Look for `nav_failed` with `"rc": 1` and CDP
|
||
tracebacks, or muse-chat-api.py login-state detection: page `Title == "muse.ai"`
|
||
(LANDING), body containing `"To log in, enter the code"` (OTP_PROMPT), or
|
||
`"Your email matches multiple accounts"` (ACCOUNT_SELECTION).
|
||
- **Cause:** Meta session expired, OTP pending, or (2026-10-04 ~19:43 UTC) all four
|
||
chromebox browsers dying silently every 10–15 min with no crash log.
|
||
- **Fix:** `agent-health.sh` watchdog relaunches dead Chromium; OTP/account-selection
|
||
states need the human (approval flow). Track: board task `9e8b15d69ca9` for the
|
||
2026-10-04 browser-flapping root cause.
|
||
- **Owner:** session-state workstream. TODO: dedicated session-probe tooling pending.
|
||
|
||
### 2f. Ghost followup (`thread_uuid: null` — can never auto-resolve)
|
||
|
||
- **Signature:** in `followups.json`: `"thread_uuid": null`, `"status": "pending"`;
|
||
in dm-log: the original send's `sidechat_uuid_capture_failed`, then sweeper
|
||
`followup_nudged` events that never resolve.
|
||
- **Cause:** the harvester's `clear_matching_followups` only matches exact
|
||
`thread_uuid` (or `target=="main"` in main). A null-UUID followup matches nothing,
|
||
forever — the sweeper nudges then escalates on a ghost.
|
||
- **Fix:** sweeper now backfills `thread_uuid` when a nudge successfully provisions
|
||
the thread (workstream landed 2026-10-04). For existing ghosts: backfill manually,
|
||
register the alias, resolve with a note. Longer-term TODO: sweeper should also
|
||
backfill on sweep ticks by scanning dm-log for the *original* dm_id's
|
||
`sidechat_autoprovisioned` event (currently only backfills on nudge success).
|
||
- **Owner:** sweeper-policy workstream.
|
||
|
||
### 2g. Flaky nav (~1/3 success) and timing races
|
||
|
||
- **Signature:** bursts of `nav_failed` / `pre_send_assert_failed` /
|
||
`placement_mismatch` for the same target in `placement-audit.py --since 60m`;
|
||
`dm-log-taxonomy.py` shows the per-target failure rate.
|
||
- **Cause:** under investigation 2026-10-04 — sidebar DOM races, CDP timing,
|
||
possibly the browser-flapping issue (§2e). The gate converts these from silent
|
||
misdeliveries into loud, retried failures (strictly better).
|
||
- **Owner:** nav-shootout, timing-races, and retry-module workstreams.
|
||
TODO: their findings land here when complete.
|
||
|
||
### 2h. `main_chat_blocked`
|
||
|
||
- **Signature:** `{"type":"main_chat_blocked","id":…,"agent":…,"to":…,"target":"main"}`
|
||
- **Cause:** a send targeted `main` without `--allow-main-chat`. Deliberate guardrail:
|
||
automation stays out of main chat unless explicitly allowed.
|
||
- **Fix:** pass `--allow-main-chat` if main delivery is really intended.
|
||
|
||
---
|
||
|
||
## 3. Diagnosis playbook: "a DM didn't arrive"
|
||
|
||
Run in order. All commands on bl unless noted.
|
||
|
||
1. **Find the send.** `grep '"id": "<8-hex-id>"' /home/super/Projects/NetVM/dm-log.jsonl`
|
||
(or grep by target). Walk its event sequence: `send_start` → `nav_ok`? →
|
||
`sent`? → `verified`? Any `*_failed` event is your answer.
|
||
2. **Placement first.** `python3 bin/placement-audit.py --since 24h` — if you see
|
||
`pre_send_assert_failed` / `placement_failed` / `placement_mismatch` for the id,
|
||
the message never left bl correctly. Check `actual_url`: landing page (§2a),
|
||
wrong thread (§2c).
|
||
3. **Check the taxonomy.** `python3 bin/dm-log-taxonomy.py` — is this an isolated
|
||
incident or is the target/agent-pair failing at a high rate right now (§2g)?
|
||
4. **Check the session.** If `nav_failed` with rc=1: is the browser alive?
|
||
`ss -tln` for the CDP port in the netns; muse-chat-api.py login-state detection
|
||
(LANDING vs LOGGED_IN per operator AGENTS.md). If all four browsers are flapping,
|
||
see board task `9e8b15d69ca9` (§2e).
|
||
5. **Check UUID freshness.** `python3 -c "import json;print(json.load(open(
|
||
'/home/super/Projects/NetVM/job-sidechats.json')).get('<target>'))"` — does the
|
||
mapped UUID still open the right thread? If the send used a UUID from anywhere
|
||
else, suspect rotation (§2c).
|
||
6. **Check the followup.** `grep -A12 '<dm_id>' /home/super/Projects/NetVM/followups.json`
|
||
— `thread_uuid: null` + `pending` = ghost (§2f). If nudges are firing, the reply
|
||
(if any) landed in a thread the harvester doesn't match: backfill + resolve manually.
|
||
7. **Check the pipeline.** If it was a pipeline step: `grep '<job_id>'
|
||
/home/super/Projects/NetVM/pipelines.json` — `dispatched` with no result after a
|
||
ghost send needs `pipeline_engine.record_step_result()` + a decision on chaining.
|
||
8. **Repair, don't re-fire blindly.** Fix the cause (nav, session, UUID), then resend
|
||
once. Repeated blind retries of a ghost just burn the nudge budget.
|
||
|
||
---
|
||
|
||
## 4. Hard lessons (non-negotiable)
|
||
|
||
1. **Never trust `verified:true` alone.** It historically meant "found the msg_id in
|
||
whatever chat the browser happened to be parked in." Always corroborate with a
|
||
placement assertion (pre-send gate) or a thread read-back.
|
||
2. **Assert the post-nav URL before sending.** The gate is now the enforcement; any
|
||
new send path must go through it. Fail closed, fail loudly (non-zero exit +
|
||
`pre_send_assert_failed` event), never degrade to blind send.
|
||
3. **Thread UUIDs rotate — never hardcode them.** Observed same-day rotation.
|
||
`SIDCHAT_ALIASES` stays empty; name-based autoprovision + `job-sidechats.json`
|
||
self-heals. If you find a hardcoded UUID anywhere, delete it.
|
||
4. **Backfill `thread_uuid`.** A followup with null UUID can never auto-resolve.
|
||
Backfill on provision (sweeper does this now), and repair historical ghosts by
|
||
hand with a note.
|
||
5. **Atomic writes on live files.** siphon/response-harvester fire every ~60s; the
|
||
sweeper loop is tight. Edit to `/tmp`, `py_compile`, atomic `mv`. Never half-write
|
||
a live file. Back up (`*.bak-<date>-<who>`) before touching shared code.
|
||
6. **One owner per file per change.** Parallel fixes on shared surfaces caused the
|
||
2026-10-03 502s: reconcile first, disjoint ownership, review the combined diff
|
||
before it goes live. dm.py is the single chokepoint — treat it accordingly.
|
||
7. **The dm-log is the source of truth for delivery; the harvester is the source of
|
||
truth for replies.** `verified` ≠ delivered; `sent` ≠ read. When they disagree,
|
||
believe the thread read-back.
|
||
|
||
---
|
||
|
||
## 5. Sibling workstream map (2026-10-04 troubleshooting sprint)
|
||
|
||
| # | Workstream | Output | Status |
|
||
|---|-----------|--------|--------|
|
||
| 1 | Gate restore | pre-send gate in `dm.py` (`assert_pre_send_placement`) | **Landed** |
|
||
| 2 | Log taxonomy | `bin/dm-log-taxonomy.py` | **Landed** |
|
||
| 3 | UUID rotation | hardcoded UUID removal (`SIDCHAT_ALIASES` emptied) | **Landed** |
|
||
| 4 | Nav shootout | — | TODO: findings pending |
|
||
| 5 | Session-state | — | TODO: probe tooling pending |
|
||
| 6 | Timing races | — | TODO: findings pending |
|
||
| 7 | Retry module | shared retry helper | TODO: pending |
|
||
| 8 | Sweeper policy | thread_uuid backfill + `final_nudge_target` | **Landed** |
|
||
| 9 | Audit CLI | `bin/placement-audit.py` | **Landed** |
|
||
| 10 | This runbook | `docs/SIDECHAT-RELIABILITY.md` | **This file** |
|
||
|
||
Related docs: `docs/DM-SPEC.md` (DM system spec), `docs/SIDECHAT_SPEC.md`,
|
||
`docs/SIDECHAT-POLICY-TRIAGE.md`, `docs/CHROMEBOX-RUNBOOK.md`.
|
||
TODO: `docs/UUID-ROTATION.md` (rotation mechanics deep-dive) — §2c is the interim reference.
|