diff --git a/docs/decomposition/agent-boot-readiness.md b/docs/decomposition/agent-boot-readiness.md new file mode 100644 index 00000000..d43b33f7 --- /dev/null +++ b/docs/decomposition/agent-boot-readiness.md @@ -0,0 +1,559 @@ +# Agent Boot & Readiness — Stage Decomposition + +> **Status:** Stages 1 and 2 **IMPLEMENTED** on `feat/session-lifecycle-observability` +> (plan: [`../superpowers/plans/2026-07-28-session-lifecycle-observability.md`](../superpowers/plans/2026-07-28-session-lifecycle-observability.md)). +> **Stage 3 is now the blocking step and it is not an engineering task** — it is +> using the app normally until the corpus has repeats. Stages 4–6 cannot be +> scheduled until it does. +> +> **What shipped:** `src/shared/lifecycle/events.ts` (closed vocabulary, +> allowlisted payload), `src/main/lifecycle/SessionLifecycleJournal.ts`, +> `src/main/ipc/lifecycle.ts`, `src/renderer/src/lifecycle/report.ts`, +> ~20 emit points, `npm run lifecycle:summarize`, the readiness reason + elapsed +> on the pane, and the Bug B submit unwind. +> +> **Corrections this work forced on the document below:** §3 said nine wake call +> sites. Making `caller` a required parameter of `ensureSessionLive` turned the +> compiler into the census and found **thirteen**. The grep undercounted, which +> is a small instance of the document's own thesis. +> +> **For agentic workers:** REQUIRED SUB-SKILL: `staged-decomposition`. Stages use +> checkbox (`- [ ]`) syntax. Do not start a stage before its predecessor's +> artifact exists and has been verified independently. If a stage disproves this +> document, revise the document — do not patch forward. +> +> **Trigger (verbatim):** "I cannot submit the prompt at the start. The agent +> takes minutes to start. I get some notification about the agents not starting. +> I'm not sure we ever had a proper logging infrastructure to even follow along +> what's going on here." +> +> **Prior art this supersedes:** #545/#548 (atomic recovery), #596/#597 (remount +> kill), #598 (condition answering), #590, #606, #283/#301, #258. Every one of +> those was a correct local fix. Collectively they did not converge, and §0 says +> why. + +--- + +## 0. Why another attempt, and why this one is shaped differently + +Boot has been patched roughly thirty times since 2026-04-11 (see the history in +`git log --grep` over `boot|resume|recover|rehydrat|wake`). The fixes were not +wrong. #548's atomic main-owned `recover()` is genuinely the right ownership +model. The problem is that **every one of those fixes was authored from source +reading and reasoning, against a failure nobody had ever recorded.** + +Compare with the rendering pipeline, which had the identical bug class — several +subsystems each believing they owned the same visible thing, focused patches that +each regressed a neighbour. That was not fixed by more patches. It was fixed by +`docs/rendering/rendering-design-principles.md` P1: + +> You cannot fix a rendering bug by reading code and editing it. You reproduce it +> as a fixture first, or you will regress something you can't see. + +Rendering now has 48 debug bundles, a recording corpus, five machine-checked +replay invariants, and a single decision point that records *why* for every +candidate. **Boot has none of that.** It has ~30 patches and a +`console.warn`. + +This decomposition applies the rendering method to boot. Stage 1 is +instrumentation and it produces nothing visible, which is exactly why it has +never been built. + +### The evidence that we are flying blind (measured, not asserted) + +| Claim | Evidence | +|---|---| +| **No boot event is journaled at all.** | `AppRunIncidentKind` (`src/main/incident/journalTypes.ts:87-111`) has 20 members: crash, heap, window, orchestration, MCP host, remote. The only session member is `session.input_write_failed`. There is no kind for spawn, recover, adopt, readiness, or stall. | +| **The perf tracer is off by default and is the wrong instrument.** | `src/renderer/src/performance/client.ts:27` — `enabled: false`, gated behind `AGENT_CODE_PERF`. It emits durations. It cannot answer "which gate state is this session stuck in." | +| **The session recorder structurally cannot see boot.** | `SessionRecorderManager.ts:99-150` — the recorder starts on the session's **first event**, and auto-record is behind `AGENT_CODE_SESSION_RECORD`. The boot window is over before it arms. | +| **Readiness is edge-triggered into silence.** | `claudeSession.ts:785-798` `publishPromptGate` emits `input-readiness` only on a transition into ready, or out of ready. A session that never becomes ready emits **nothing** after `SessionManager` line 887 sets `{ready:false, reason:'starting'}`. The renderer waits forever with no further fact. | +| **The stall reason exists and is thrown away.** | `derivePromptGateState` (`claudeSession.ts:744-783`) computes a precise reason — `blocked`, `occupied/human-draft`, `warming/replay-pending`, `warming/composer-unpainted`. `SessionInputReadiness.reason` is documented as "diagnostic/advisory; correctness gates only on `ready`." Nothing displays it, nothing logs it. | +| **What the user actually sees is reasonless.** | `TileLeaf/readiness.ts:13` → `'agent failed to start'`. `session.ts:219` → `'Timed out waiting for agent to become ready for input'`. No session id, no phase, no provider, no elapsed. This is the "bullshit notification." | +| **Cold boot fans out unbounded.** | `rehydrate.ts:588` — `Promise.all` over every visible leaf, each with a 30s deadline (`rehydrate.ts:62`). The in-file comment already concedes 9 providers "all started in this Promise.all in the same ~3 seconds." Nobody has measured what that does to TUI paint latency, which is what the composer classifier reads. | + +**Conclusion:** the reason boot has resisted thirty fixes is not that the fixes +were bad. It is that *we have never once observed a failure*. Every fix was a +hypothesis. This is precisely the 40%-then-whack-a-mole mechanism the +`staged-decomposition` skill describes, and the exit is the same: enumerate from +reality, not from imagination. + +### First candidate shape — reported 2026-07-28 + +Reported verbatim: *"`Cannot deliver prompt: 9dc65b98-… is not a live agent +session`. The agent just states Sending forever and does nothing — `Sending · +17s` — and I have to reload the agent to send the prompt."* + +This is **two independent defects that compound**, and separating them matters +because only one of them needs the corpus. + +#### A — The cause: registry split-brain (needs Stage 1) + +`sessionManager.ts:1740-1752` — `deliverPromptToAgent` looks up +`this.sessions.get(sessionId)`, finds **no entry**, and returns +`code: 'not-ready'`. So main's live registry has no backend for a session the +renderer believes is started, `inputReady`, and writable. + +Why the entry is missing is **unknown and not derivable from source**. Candidates: +a backend exited without the renderer processing `onSessionExit`; a cancelled +recovery that removed the registry entry (`recover()` step 5) while the pane kept +its optimistic runtime; a kill from the #597 residue paths; or a wedged provider +in the accepted-cost class (Unknown 7). **This is exactly the question the boot +journal exists to answer**, and no amount of further source reading will settle +it — which is the thesis of this document, now with a concrete instance. + +#### B — The amplifier: the optimistic submit state is never unwound (source-confirmed) + +`useComposerKeybinds.ts:223` calls `setStreamingBaseline`, which sets +`streamPhase: 'submitting'`, `submittedAt: now`, `awaitingAssistant: true` +(`streaming.ts:141-176`) — **before** the `try`. + +The `catch` (`useComposerKeybinds.ts:279-307`) sets `promptDelivery`, removes the +optimistic Codex echo, and shows a toast. **It never resets `streamPhase`, +`submittedAt`, or `awaitingAssistant`.** + +And nothing else can. There are exactly three paths that clear `streamPhase` to +`'idle'`: + +1. `onSessionExit` (`useIpcSubscriptions.ts:831`) — requires a real exit event, which never arrives, because the pane's problem is precisely that main has *no entry* to exit. +2. `emptyRuntime()` (`session-runtime/state.ts:729`) — only on a fresh runtime, i.e. **reload**. +3. `reduceStreamPhase` from a real provider semantic event — which cannot arrive, because nothing was ever written. And `streamPhaseMachine.ts:118` **deliberately refuses to stomp `submitting`/`requesting`** from screen-derived signals; that guard is scar tissue with its rationale at `:105`. + +**Therefore `Sending` counts up forever and reload is the only exit.** That is +the reported behaviour, exactly, and it is provable without a recording. + +**Why B matters more than its size suggests:** the system *correctly detected and +reported* this failure. The toast fired. `promptDelivery` was set to a typed +failure state. And the pane still wedged, because the optimistic state that was +set before the attempt was never unwound after it. Every future fix to A will +keep feeling like it did nothing, as long as B turns any delivery failure into a +permanently stuck pane. + +**Fix constraint:** the reset belongs at the submit site that *owns* the +optimistic set. Do **not** weaken the `streamPhaseMachine` guard at `:118` to +achieve it — that guard is a shipped regression's tombstone, and relaxing it +reintroduces the pinned-`submitting` bug it was written to fix. + +> **Status: B is FIXED** — shipped as part of Stage 2 rather than as a patch +> ahead of it, because "the pane stops lying about its own state" is precisely +> what Stage 2 is. The unwind fires only when main reports +> `promptWritten === false && enterWritten === false`; the `uncertain` path and +> the `streamPhaseMachine` guard are both untouched. Every firing is recorded as +> `submit.unwound`, so the corpus will measure how often the old build would +> have wedged a pane. +> +> **A is still unfixed, deliberately.** It is now recorded and classified — +> `delivery.reject` carries `never-owned` versus `entry-lost-after-owned`, which +> are two different defects that are byte-identical to the user. Which one +> actually happens is a Stage 3 question, and answering it from source instead +> of from the corpus would be the thirty-first patch. + +### On "temporary code" + +You offered to write throwaway code to diagnose this. Counter-proposal, and it +matters: **Stage 1 must be permanent.** A temporary probe gets deleted the moment +a fix looks like it worked, and then the next regression is invisible again — +which is the exact history of `8fa0c910` (the #283 instrumentation PR, explicitly +labelled "REMOVE once root cause is fixed", and duly removed). The journal is +small, metadata-only, always-on, and bounded. Throwaway probes are welcome *on +top of* it, not instead of it. + +--- + +## 1. A and D + +### A — what exists and is trusted + +| Thing | Where | Trust | +|---|---|---| +| `SessionManager.recover()` atomicity | `src/main/sessionManager.ts` | **Trusted.** Synchronous claim, typed conflict, kill-cancels. #548's ownership model is correct and is not being re-litigated. | +| Persisted local `SessionId` as ownership key | `rehydrate.ts:100-120` | **Trusted.** Stable across restart; provider id is a launch hint only. | +| `SessionInputReadiness` level + monotonic revision | `sessionManager.ts:453-468` | **Trusted as a transport.** The revision ordering is sound. | +| `derivePromptGateState` reason vocabulary | `claudeSession.ts:744-783` | **Trusted as a computation.** Its scars are documented and real (the removed 10s staleness bound). It is not trusted as *complete* — see Unknowns. | +| `SessionFeed` nine-channel contract | `src/shared/sessionFeed/` | **Trusted.** The journal will not open its own subscriptions. | +| `AppRunJournal` writer + run manifest | `src/main/incident/` | **Trusted as a substrate.** Bounded, redacting, run-scoped. The boot journal should reuse it, not invent a second one. | +| Redaction discipline | `@shared/performance/serialization`, the rendering redactor | **Trusted.** Hard-gated. Reused verbatim. | +| The three-ledger diagnosis | `docs/superpowers/plans/2026-07-16-session-recovery-reconciliation.md` §"Why this plan exists" | **Trusted.** Still the correct model of the problem. | + +### D — the end state + +1. When an agent is slow or stuck at boot, **the pane says which phase it is in + and for how long** — not "agent failed to start." +2. Any boot failure the user hits is **reproducible from a recorded artifact** + without asking them to reproduce it. +3. Every observed stall shape has **a name, a frequency, and a fixture**. +4. The lifecycle has **one arbiter with a recorded decision per transition**, in + the shape rendering's ownership ledger has — `debug output is a serialization + of the same decision the code acted on, never a second derivation`. +5. Cold boot of a realistic workspace has a **measured** time budget, and the + fan-out is shaped by that measurement rather than by `Promise.all`. +6. `Timed out waiting for agent to become ready for input` is either gone or + carries the reason it timed out. + +**D is not "boot is fast."** D is "boot is *observable*, and every failure is a +named shape with a fixture." Speed follows from knowing where the time goes; it +cannot precede it. + +--- + +## 2. The stages + +### Stage 1 — The boot journal ✅ SHIPPED + +- [x] **Produces:** `~/.config/agent-code/boot/.jsonl` — one append-only, + metadata-only, bounded record per app run, containing every session-lifecycle + transition from all three processes on one clock: + `rehydrate.start/complete`, `recover.request/claim/adopt/spawn/conflict/cancel/fail`, + `provider.start.begin/end`, `proxy.up`, `mcp.register`, `tail.attach`, + `replay.quiesce`, `gate./` **on every evaluation, not only on + transition**, `history.load.start/end`, `first-paint`, `wake.request` with its + caller, `kill` with its cause, `timeout.fire`. Each carries `runId`, + `sessionId`, `kind`, monotonic ms, and phase-relative elapsed. + Plus a paired reader: `Save Boot Journal` command and a `scripts/` summarizer + that prints one line per session — the phase ladder and where it stopped. +- [x] **Verified by:** boot the app with a known workspace; the journal must + account for every visible pane with a monotonically ordered ladder and no + gaps. Independently checkable: the ladder's terminal event must match what the + pane visibly did. It needs no later stage to be judged correct — either it + explains the boot you just watched, or it does not. +- [x] **Why separate:** if this lands with a fix, the fix defines what gets + recorded, and we will only record the phases the fix's author already believed + in. Recording must be authored by someone who does not yet know the answer. + This is also the stage that survives every future regression, which a fix does + not. +- [x] **Reality check:** built against the *existing* call sites listed in §0 — + every event name above corresponds to a line that already executes today. No + new lifecycle is invented here; this stage only makes the existing one legible. + +**Always on. No env flag.** Rationale: `AGENT_CODE_PERF` and +`AGENT_CODE_SESSION_RECORD` are both off by default, which is why we have zero +recordings of a failure that happens daily. Bounded by the existing +`AGENT_CODE_DEBUG_MAX_GB` / TTL sweeper. + +### Stage 2 — The pane tells the truth ✅ SHIPPED (with one gap, stated) + +> **Gap:** the pane shows the COARSE reason. Claude's detailed verdict +> (`replay-pending` / `composer-unpainted` / `human-draft`) is collapsed to +> `provider-not-ready` before it leaves main, and recovering it means widening +> the `SessionInputReadiness` contract — Tier 3 transport this PR does not +> touch (§4). The detail is recorded in `gate.eval` meanwhile. Whether to widen +> that contract is a Stage 4 decision, made from the corpus. + +- [x] **Produces:** the composer/pane surfaces the live gate reason and elapsed + time — `Replaying transcript… 4s`, `Waiting for composer… 38s`, + `Permission prompt on screen`, `Draft in composer` — sourced from + `SessionInputReadiness.reason`, which already crosses the wire and is currently + discarded. Plus: failure toasts carry reason + session id + phase. +- [x] **Verified by:** with Stage 1's journal open beside the app, the on-screen + reason must match the journal's current gate state at all times. Any divergence + is a bug in this stage, and the journal is the referee. +- [x] **Why separate:** this is what converts *your* future bug reports from "it + didn't start" into "it sat at composer-unpainted for 90s" — which is the input + Stage 3 needs. Merged into a fix, it becomes a cosmetic afterthought and gets + cut for scope. +- [x] **Reality check:** the reason strings already exist and are already + computed (`claudeSession.ts:744-783`, `codexSession.ts`, opencode). This stage + transports and renders; it invents no new state. + +**This is a diagnostic, not a fix.** It changes no gate logic. + +### Stage 3 — The corpus + +- [ ] **Produces:** `testing/fixtures/boot-journals/` — real recorded boots with + frequencies, deliberately spanning: cold start after quit · renderer reload · + cold start after crash · 1 pane · ~5 panes · ~15 panes · Claude-only · + Codex-only · mixed · with and without worktrees · a boot that was fast · every + boot that was slow or stuck. Target: **enough runs that the slow/stuck shapes + repeat**, not a fixed count. +- [ ] **Verified by:** replayable — a journal in this directory, fed to Stage 1's + summarizer, reproduces the same phase ladder every time. Redaction hard-gated: + the extractor refuses to emit a fixture containing a sensitive value, mirroring + `scripts/extract-rendering-fixtures.mjs`. +- [ ] **Why separate:** this is the stage that requires *you*, and calendar time, + and normal use. It cannot be compressed or simulated. Any stage that depends on + it and is attempted early will be built against imagined cases — the 40% + mechanism. +- [ ] **Reality check:** it is nothing but recordings. That is the whole point. + +### Stage 4 — The catalog + +- [ ] **Produces:** `docs/decomposition/evidence/boot-shapes/catalog.md` — every + distinct stall/failure shape observed in Stage 3, each with: a name, its + frequency, the exact phase it stalls in, which providers exhibit it, and the + fixture that contains it. Plus a machine-readable classifier that maps a + journal to a shape. +- [ ] **Verified by:** every run in the corpus classifies into exactly one shape, + with **zero `unknown`**. An unclassifiable run means the catalog is incomplete + and Stage 3 needs more recording — not that the run should be discarded. +- [ ] **Why separate:** the catalog is where "the agent takes minutes to start" + stops being one complaint and becomes N distinct engineering problems with + known frequencies. Merged into implementation, we would fix the shape that was + most recently in context and ship 40%. +- [ ] **Reality check:** derived only from Stage 3 recordings. A shape that was + never observed does not enter the catalog, however plausible. + +### Stage 5 — The replay harness and its invariants + +- [ ] **Produces:** a pure `bootJournal → SessionLifecycle[]` replay plus + machine-checked invariants asserted at every event, needing no expected output. + Candidate invariants, to be confirmed by the catalog: every visible pane reaches + a terminal outcome · exactly one process per local id · no kill of a backend + this call adopted · no readiness silence exceeding a corpus-derived bound · + every `wake.request` names a caller · no gate evaluation without a reason. +- [ ] **Verified by:** replaying the whole corpus. Known-good boots pass; every + catalogued bad shape trips a specific named invariant. An invariant no recorded + run can trip is not evidence — it is decoration, and gets deleted. +- [ ] **Why separate:** this is the permanent regression net. Built after the + fixes, it would be written to pass them — the 481-of-481 vanity-metric failure. + Built here, against real recordings, it is written to catch them. +- [ ] **Reality check:** every invariant traces to a shape in the Stage 4 catalog + or it does not ship. + +### Stage 6+ — Fix one catalogued shape at a time + +- [ ] **Produces:** one PR per shape, highest-frequency first. Each begins with a + failing assertion against the fixture that contains it. +- [ ] **Verified by:** the fixture goes green, the rest of the corpus does not + regress, no invariant weakens. +- [ ] **Why separate:** one shape per PR is what makes a regression attributable. + #548 fixed several at once and shipped #596, #598, #590, and #606 behind it. +- [ ] **Reality check:** no shape gets a fix before it has a fixture. **A second + conditional added to an existing gate means the substrate is wrong — stop and + revise this document.** + +Whether the endpoint is "a lifecycle arbiter in the shape of the render ledger" +is **deliberately not decided here.** The catalog decides it. If the shapes are +independent, they get independent fixes. If they are the same ownership +disagreement wearing six hats, that is the evidence that justifies an arbiter — +and only then. + +--- + +## 3. The file census — what actually touches this + +Measured, not estimated. Union of the lifecycle symbols +(`recoverSession` · `SessionRecover*` · `inputReady` · `SessionInputReadiness` · +`input-readiness` · `promptGate` · `PromptGateState` · `isPromptAcceptanceReady` · +`rehydrateWorkspace` · `commitRehydratedState` · `bootstrapComplete` · +`WorkspaceRestoreStatus` · `ensureSessionLive` · `waitForSessionInputReady` · +`spawnSession` · `SessionSpawnOptions` · `preferredSessionId` · +`spawningSessionIds` · `loadInitialHistoryForSession` · `recoverTmuxName` · +`seedResumedRuntimeFields` · `killSessionBackendIfOwned`), tests excluded: + +> **46 production files · 23,459 LOC.** +> The top six files carry **145 of ~280** total references. +> **`refs`** = symbol occurrences (entanglement density). +> **`X`** = file also owns unrelated concerns (a refactor here is a *split*, not a move). + +### Tier 1 — Deciders. **This is the arbiter's future body.** + +Files that make ownership / readiness / lifecycle *decisions* today. Isolating +these is the whole point of the exercise. + +| refs | LOC | X | File | What it decides | +|---:|---:|:-:|---|---| +| 44 | 1267 | | `renderer/workspace/hook/actions/session.ts` | `ensureSessionLive`, `waitForSessionInputReady` (30s), `killSessionBackendIfOwned`, `replaceSession`, `reloadAgentSessions`. **The single most entangled file in the subsystem.** #596 and #598 both live here. | +| 28 | 806 | | `renderer/workspace/hook/persistence/rehydrate.ts` | Restore orchestration, the 30s per-session deadline, `Promise.all` fan-out (`:588`), unknown-kind policy, MCP domain threading. | +| 24 | 2057 | X | `main/sessionManager.ts` | `recover()`, recovery claims, `spawningSessionIds`, readiness cache + revision, kill/cancel. Also owns PTY attach/detach, tmux, screens, paste — **split candidate**. | +| 17 | 969 | X | `renderer/workspace/hook/index.ts` | Wires wake into MCP/orchestration request handling. Also the workspace god-hook. | +| 6 | 231 | | `renderer/workspace/hook/persistence/useBootstrap.ts` | `WorkspaceRestoreStatus`, when restore is "complete". | +| 5 | 230 | | `renderer/workspace/providerSessionIdentity.ts` | `resumableProviderSessionId`, `seedResumedRuntimeFields`, provisional-id policy. | +| 5 | 147 | | `renderer/workspace/hook/persistence/useAutoSave.ts` | Gates autosave on restore completion. | +| — | — | | `renderer/workspace/hook/persistence/recoveryProjection.ts` | Pure leaf→outcome projection (already extracted by #548 — **the one piece that is already the right shape**). | +| — | — | | `renderer/workspace/sessionOwnership.ts`, `idRemap.ts` | Owned vs live-process id sets (#258's fix), residual remap. | + +### Tier 2 — Provider attesters. **Three implementations that must agree.** + +| refs | LOC | File | Readiness model | +|---:|---:|---|---| +| 26 | 1108 | `providers/claude/runtime/claudeSession.ts` | `derivePromptGateState` — re-derived continuously; 250ms replay quiet window; `blocked`/`occupied`/`warming`/`ready`. **Emits only on transition (`:785`) — the silence bug.** | +| 6 | 622 | `providers/codex/runtime/codexSession.ts` | Latches ready on first composer sighting; resets only on exit. | +| 3 | 468 | `providers/opencode/runtime/opencodeSession.ts` | Ready when the server is up. | +| 1 | 317 | `providers/claude/runtime/promptDelivery.ts` | Per-delivery acceptance gate (+ Codex's equivalent). | + +**The asymmetry is the risk.** Claude can go ready→not-ready→ready; Codex cannot. +Any invariant written against one provider is wrong for the other. The catalog +must record shapes **per provider**. + +### Tier 3 — Transport. **Thin, correct, must stay thin.** + +Carry the readiness fact; decide nothing. Do not grow these. + +`shared/types/session.ts` (12/482) · `preload/api/session.ts` (11/265) · +`shared/sessionFeed/{SessionFeed,types,SessionFeed.contract}.ts` · +`main/ipc/session.ts` · `main/sessions/forwarder.ts` · +`features/sessionFeed/{Ipc,Fake}SessionFeed.ts` · +`remote-client/{WebSocketSessionFeed,wire}.ts` · +`main/remote/{RemoteServer,SessionFeedSource,protocol/messages}.ts` · +`preload/api/{types,index,provider}.ts` + +### Tier 4 — Consumers that currently **decide**, and must stop + +This tier is the "too intertwined" problem in concrete form. Each of these reads +a readiness fact and then makes its own lifecycle decision — which is exactly the +distributed-ownership pattern the render ledger was built to end. + +| refs | LOC | X | File | The decision it should not be making | +|---:|---:|:-:|---|---| +| 10 | 879 | X | `workspace/tile-tree/TileLeaf.tsx` | `send()` wakes on `!inputReady` — **caused #598** (a live condition *is* not-ready, so every modal click took the wake path). | +| 10 | 392 | | `workspace/tile-tree/AgentTerminalLeaf.tsx` | Mount-time unconditional wake — **caused #596**. Now carries an `adopted` vs `spawned` conditional, i.e. the second conditional the skill warns about. | +| 9 | 2186 | X | `workspace/hook/actions/pane.ts` | Three separate wake sites inside a pane-layout file. | +| 6 | 498 | | `workspace/tile-tree/TerminalLeaf.tsx` | Its own wake, near-parallel to `AgentTerminalLeaf` but not identical (documented asymmetry in the #597 plan). | +| 4 | 309 | | `workspace/hook/actions/undoClose.ts` | Revive semantics. | +| 3 | 266 | | `workspace/hook/actions/providerSwitchCore.ts` | Wake-before-switch — **#590**. | +| 3 | 2316 | X | `workspace/hook/ipc/useIpcSubscriptions.ts` | Ingest orchestrator that also applies readiness revisions. | +| 2 | 94 | | `workspace/hook/actions/agentIndexNavigation.ts` | Wakes on navigate. | +| 2 | 742 | X | `session-runtime/state.ts` | Holds `inputReady` on the runtime. | +| 2 | 30 | | `workspace/tile-tree/TileLeaf/readiness.ts` | Produces `'agent failed to start'` — **the reasonless string**. | +| 1 | 762 | X | `workspace/orchestrationMcp.ts` | Waits on readiness before dispatching child prompts — **#567**. | +| 1 | 444 | X | `workspace/agentManagementMcp.ts` | Same, via the management surface. | +| 1 | 623 | X | `tile-tree/TileLeaf/useComposerKeybinds.ts` | Composer-level readiness branch. | +| 1 | 114 | | `tile-tree/TileLeaf/ComposerActions.tsx` | Deliberate failed/exited wake path. | + +**Nine distinct wake call sites across seven files.** Every past incident is one +of them behaving differently from the others. **Target: one.** + +### Tier 5 — Observers (read-only, correct as-is) + +`features/debug/ui/DebugPanel.tsx` · `features/debug/ui/DevDebugPanel.tsx` + +### Tier 6 — Word collisions. **Explicitly out of scope — do not chase.** + +These match `rehydrate` but have nothing to do with session boot. Listed so the +next agent does not waste a pass on them: + +`features/global-editor/{ui/GlobalEditorShell.tsx,store.ts,lib/globalEditorPersistence.ts}` +(the editor's own `rehydratedCwdsRef` / store rehydrate) · +`features/reply-to-selection/lib/selectionStash.ts` · +`main/storage/debugRetention.ts` · `workspace/tile-tree/paneLabels.ts` · +`workspace/dispatch/tiledDispatchSelectors.ts` · +`workspace/tile-tree/useKeybinds.ts` (comments only). + +> **Naming debt worth fixing on the way past:** "rehydrate" means at least three +> unrelated things in this codebase (session restore, editor state, Zustand +> persist). A grep for it returns 63 files; only 46 are real, and the 17 false +> positives are the kind of thing that silently pads an agent's context and +> dilutes its attention. Renaming session restore to something unambiguous is a +> cheap, in-blast-radius cleanup. + +### What the census tells us before any recording starts + +1. **The problem is not size, it is placement.** 23k LOC is not unreasonable for + multi-provider process lifecycle. Nine wake sites is. +2. **Six files hold the decisions; forty hold the consequences.** Tier 1 + the + Claude runtime is ~6,400 LOC. That is a tractable arbiter. +3. **Four Tier-1/4 files exceed 2,000 LOC and own unrelated concerns** + (`sessionManager.ts`, `pane.ts`, `useIpcSubscriptions.ts`, `hook/index.ts`). + Any change here is a split, not a move — and splitting them **before** the + catalog exists would be refactoring blind. **Stage 6+, not now.** +4. **The transport layer (Tier 3) is already right.** #548 built it correctly. + Nothing in this plan should touch it, and any proposal that does is a signal + the proposal is wrong. + +--- + +## 4. What is being isolated + +**The hard part is not spawning a process. It is arbitrating boot-time truth +between three ledgers plus three providers** — the same shape as rendering's +distributed-ownership problem, and currently distributed across ~8,500 lines of +`rehydrate.ts` + `session.ts` + `useIpcSubscriptions.ts` + `sessionManager.ts` + +three provider runtimes. + +- **`src/shared/boot/`** — the event vocabulary and the pure lifecycle model. + No I/O, no Electron, no React. +- **`src/main/boot/`** — the journal writer. Single consumer. Reuses + `AppRunJournal`'s file/rotation/redaction substrate rather than inventing a + second one. +- **Forbidden imports:** `rendering/` must never import `boot/` — it does not + need to, and the one-way `session-runtime/ → rendering/ → features/feed/` + layering must not gain a fourth edge. `boot/` must never import + `features/`. The journal must never be a *decider* — if a fix needs the + journal's state to make a runtime decision, that is the signal that the + arbiter belongs in `shared/boot/` as real state, with the journal as its + serialization. Same rule as rendering's P4: **debug output is a serialization + of the decision, never a second derivation.** + +### The rule that keeps the census from becoming a refactor + +**Stages 1–5 add files. They do not move or split any file in §3.** + +It is tempting to read the census as a to-do list — nine wake sites, four +oversized files, collapse them. Do not. Every one of those consolidations is a +guess about which behaviours are equivalent, and #596/#598 are what happens when +that guess is wrong. Stage 1 instruments the nine wake sites *as they are*, so +the corpus can tell us which of them actually behave differently. **The census is +the map of what to record, not the list of what to change.** + +Concretely, per tier: + +| Tier | Stages 1–5 may | Stage 6+ may | +|---|---|---| +| 1 Deciders | add journal emit calls at existing decision points | become the arbiter | +| 2 Providers | emit every gate evaluation, not just transitions | unify the readiness model *if* the catalog proves the asymmetry is a bug and not a requirement | +| 3 Transport | **nothing** | **nothing** | +| 4 Consumers | emit `wake.request` with its caller identity | collapse toward one wake site, one shape at a time, each with a fixture | +| 5 Observers | render the reason (Stage 2) | — | +| 6 Collisions | rename, opportunistically | — | + +--- + +## 5. Unknowns + +Not one of these can be answered by reading code. Every previous attempt answered +them by assumption. + +1. **Why is the composer `unpainted` or `drafted` at boot?** This is the prime + suspect for "cannot submit at the start" — `derivePromptGateState` returns + `warming/composer-unpainted` or `occupied/human-draft` and emits nothing + further. Is the TUI genuinely not painted, or is the classifier misreading a + painted screen under load? **Unknown. Nothing has ever recorded it.** +2. **Where do the "minutes" actually go?** Candidates: `Promise.all` fan-out + contention · provider process startup · proxy/mitmdump spawn · MCP + registration · transcript history load · TUI paint under CPU pressure. No + breakdown has ever been measured. Assuming it is concurrency would be exactly + the mistake this document exists to prevent. +3. **Does the 30s recovery deadline ever fire?** Or does the pane sit + indefinitely at not-ready with the deadline never reached, which looks + identical to the user but is a different bug in a different file. +4. **Is this per-provider?** Codex latches ready on first composer sighting; + Claude re-derives continuously. That asymmetry predicts different shapes. + Untested. +5. **Does it scale with pane count?** #258's fork bomb says load matters; nothing + has measured the knee. +6. **Cold start vs renderer reload — same shape or different?** They take + different paths (`spawned` vs `adopted`) and #596 proved they behave + differently under the same code. +7. **Is the wedged-provider class from #597's accepted cost now showing up?** + `lifecycle: 'live'` ≠ healthy: a provider that registers then wedges is now + adopted-and-skipped with **no in-app retry**. That was accepted in writing on + 2026-07-22 and nothing replaced #548's self-heal. This is a live candidate for + "I cannot submit and I have to force a restart" — **and it would present + exactly as described.** Unconfirmed. +8. **How much of the pain is the 120×40 TUI resize** (`detachAgentPty`, deferred + from #596) rather than boot at all? Different bug, same felt experience. + +If any of these are answered before Stage 3 completes, they were guessed. + +--- + +## 6. Fixture plan + +| | | +|---|---| +| **Where real data comes from** | Stage 1's boot journal, always on, from your normal daily use. | +| **Which stage produces it** | Stage 1 emits, Stage 3 collects and redacts into `testing/fixtures/boot-journals/`. | +| **Extraction** | `scripts/extract-boot-journals.mts`, modelled on `extract-rendering-recordings.mjs`, with the same **hard-gated** redactor — it refuses to emit a fixture containing a sensitive value rather than best-effort scrubbing. | +| **Never recorded** | prompts, assistant text, tool payloads, file contents, commands, MCP tokens, credentials. Metadata only: ids, kinds, phases, reasons, timestamps, counts. | +| **Test authorship rule** | Assertions are written **before** the fix, against a recorded fixture. A test written after a fix, from imagined input, is a vanity metric — `docs/decomposition/claude-queue-reconciliation.md` and the rendering principles both say this, and the 481-of-481 case is the proof. | +| **Human judgement required** | What *should* own readiness when the composer holds a draft and a prompt is queued? What *should* happen when a provider registers but never paints? These are product semantics, not derivable from the corpus. They will be asked, not invented. | + +--- + +## 7. What this costs, honestly + +Stages 1 and 2 are days, not weeks, and they are the ones that immediately change +your daily experience — the pane stops lying to you. Stage 3 is calendar time and +mostly your normal use. Stages 4–6 cannot be scheduled until the catalog exists, +which is the point: **we do not currently know how many problems we have.** + +The alternative is a thirty-first patch. diff --git a/docs/superpowers/plans/2026-07-28-session-lifecycle-observability.md b/docs/superpowers/plans/2026-07-28-session-lifecycle-observability.md new file mode 100644 index 00000000..5dc83f71 --- /dev/null +++ b/docs/superpowers/plans/2026-07-28-session-lifecycle-observability.md @@ -0,0 +1,353 @@ +# Session Lifecycle Observability — Implementation Plan + +**Status:** Ready for implementation + +**Date:** 2026-07-28 + +**Branch:** `feat/session-lifecycle-observability` + +**Worktree:** `.worktrees/session-lifecycle-observability` + +**Decomposition:** [`docs/decomposition/agent-boot-readiness.md`](../../decomposition/agent-boot-readiness.md) +— read §0 and §3 before touching anything here. This plan implements **Stage 1 +and Stage 2** of that decomposition. Stages 3–6 are deliberately out of scope and +cannot start until this PR has been running long enough to produce a corpus. + +--- + +## Goal + +Make the agent boot/readiness path **observable**, and stop one confirmed defect +from turning every delivery failure into a wedged pane. + +Three shipped outcomes: + +1. **A `session.lifecycle` event stream**, always on, in the existing incident + journal — every spawn, recover, adopt, readiness transition, wake request + (with its caller), prompt delivery, and kill, on one clock across all three + processes. +2. **A pane that names its own stall.** `Replaying transcript… 4s` instead of a + silent disabled composer, and `agent failed to start` replaced by the actual + reason. +3. **The optimistic submit state unwinds on a provable non-delivery** — the + `Sending · 17s` forever bug, which today can only be cleared by reloading the + agent. + +**Explicit non-goal: this PR does not fix why backends go missing.** It makes the +next occurrence diagnosable and non-wedging. That distinction is the whole point +of the decomposition; a PR that quietly also "fixes" the root cause would be +patch #31 and would invalidate the corpus it is meant to produce. + +--- + +## Why this plan exists + +Boot has been patched ~30 times since 2026-04-11 and has never converged. +`docs/decomposition/agent-boot-readiness.md` §0 establishes the reason with +measured evidence: **no boot event has ever been recorded.** Every fix was +authored from source reading against a failure nobody had captured. + +The concrete instance that triggered this work (decomposition §0, "First +candidate shape"): + +> `Cannot deliver prompt: 9dc65b98-… is not a live agent session` — and then the +> pane shows `Sending · 17s`, counting up forever, until the agent is reloaded. + +That is two defects compounding, and only one of them is diagnosable from source: + +- **A (cause, unknown):** `sessionManager.ts:1740-1752` finds no registry entry + for a session the renderer believes is live and ready. Why is not derivable + from source. **This PR does not fix A. It records it.** +- **B (amplifier, confirmed):** the submit path sets `streamPhase: 'submitting'` + *before* the attempt and never unwinds it on failure. **This PR fixes B.** + +--- + +## Confirmed defect B — the full trace + +Recorded here because the fix must not be re-derived later from the symptom. + +1. `useComposerKeybinds.ts:223` calls `workspace.setStreamingBaseline(...)`. +2. `streaming.ts:141-176` sets `streamPhase: 'submitting'`, `submittedAt: now`, + `awaitingAssistant: true`, `turnStartedAt: now`, `phaseChangedAt: now`. +3. `caps.composerSubmit(...)` throws when delivery fails. +4. `useComposerKeybinds.ts:279-307` catches: sets `promptDelivery`, removes the + optimistic Codex echo, shows a toast. **It never touches `streamPhase`.** + +There are exactly three ways `streamPhase` can return to `'idle'`, and under a +`before-write` delivery failure **none of them can fire**: + +| Path | Why it cannot fire | +|---|---| +| `onSessionExit` → `useIpcSubscriptions.ts:831` | Requires a real exit event. Main has no registry entry *to* exit — that is the failure. | +| `emptyRuntime()` → `session-runtime/state.ts:729` | Only on a fresh runtime, i.e. **agent reload**. This is why reload is the only escape. | +| `reduceStreamPhase` from a provider semantic event | Nothing was ever written, so no event will arrive. And `streamPhaseMachine.ts:118` **deliberately refuses to stomp `submitting`/`requesting`** from screen-derived signals (rationale at `:105`). | + +`WorkIndicator.tsx:112` renders `'submitting'` as `Sending`, and +`useElapsed(submittedAt)` counts up at 1 Hz. Hence `Sending · 17s → 4m → …`. + +### The fix, and the trap it must avoid + +The decomposition's standing warning is that a guard added to protect a path +becomes the next weapon (#548's kill-timeout → #596; `TileLeaf`'s `!inputReady` +gate → #598). So the discriminator is explicit: + +- **Unwind ONLY when main reports `promptWritten === false && enterWritten === + false`.** That is a fact already on the wire in `PromptDeliveryResult`, not an + inference about *why* delivery failed. Nothing was written ⇒ no turn can start + ⇒ the optimistic phase is provably a lie. +- **Do NOT unwind the `uncertain` case** (`promptWritten` or `enterWritten` + true). There we genuinely do not know whether a turn began; unwinding could + hide a real running turn. That case keeps today's behaviour and is a Stage 4 + catalog question. +- **Do NOT relax `streamPhaseMachine.ts:118`.** That guard is a shipped + regression's tombstone. The unwind belongs at the submit site that *owns* the + optimistic set, which is the same site that set it. + +--- + +## Design + +### Where the code lives, and what may import it + +Per decomposition §4: + +| Path | Contents | Consumers | +|---|---|---| +| `src/shared/lifecycle/events.ts` | The closed event-name vocabulary, the `SessionLifecycleEvent` payload type, and the redaction contract. Pure types + constants. No I/O, no Electron, no React. | main, preload, renderer | +| `src/main/lifecycle/SessionLifecycleJournal.ts` | Thin typed emitter over the existing `AppRunJournal`. Single sink. | `sessionManager`, `ipc/lifecycle` | +| `src/main/ipc/lifecycle.ts` | `session:lifecycle-report` — renderer → main bridge, defensive parsing + token bucket, modelled on `ipc/incident.ts`. | main only | +| `src/renderer/src/lifecycle/report.ts` | Renderer-side emit helper (fire-and-forget). | renderer emit sites | +| `scripts/summarize-lifecycle.mts` | Reads a run's `events.jsonl`, prints one phase ladder per session. | humans | + +**Forbidden:** `src/renderer/src/rendering/**` must never import `lifecycle/**`. +The one-way `session-runtime/ → rendering/ → features/feed/` layering does not +gain a fourth edge. `lifecycle/**` must never import `features/**`. + +**The journal is a sink, never a decider.** No production branch may read a +lifecycle event to make a runtime decision. If a future fix needs that, the state +belongs in `shared/` as real state with the journal as its *serialization* — +same rule as rendering's P4 (`debug output is a serialization of the same +decision, never a second derivation`). + +### Why extend `AppRunJournal` instead of a new store + +`AppRunJournal` already solves every hard part, with scar tissue we must not +re-earn: always-on (unlike `AGENT_CODE_PERF`, which is why we have zero +recordings), per-run 50 MiB hard ceiling, drop-oldest pending bound, atomic +heartbeat, redaction via `sanitizePerformanceData`, degrades to a silent no-op +when `~/.config` is unwritable, and synchronous flush on quit. + +`SessionManager` already holds a journal reference and already emits three +`session.recovery` events (`sessionManager.ts:435-451`). This plan widens that +seam; it does not open a new one. + +**Corollary benefit:** lifecycle events land in the same `events.jsonl` as heap +pressure, window-unresponsive, and crash breadcrumbs — so a stall can be +correlated against main-process health without joining two files. + +### Event vocabulary (closed) + +`area: 'session.lifecycle'`. Names are a closed set; adding one is a deliberate +contract change. + +| Name | Emitted by | Key data | +|---|---|---| +| `rehydrate.start` / `rehydrate.complete` | renderer | tab/leaf/detached/buried counts, resolved count, duration | +| `recover.request` | renderer | kind, hasResumeId, caller | +| `recover.claim` / `recover.join` | main | claim state | +| `recover.adopted` / `recover.spawned` | main | lifecycle, durationMs | +| `recover.conflict` / `recover.cancelled` / `recover.failed` | main | typed code | +| `spawn.begin` / `spawn.end` | main | kind, durationMs, ok | +| `provider.start.begin` / `provider.start.end` | main | kind, durationMs | +| `gate.eval` | main (provider) | kind, gate state, reason, **every evaluation, not only transitions** | +| `readiness.publish` | main | ready, reason, revision | +| `wake.request` | renderer | **caller identity** (which of the nine sites) | +| `wake.result` | renderer | disposition, durationMs | +| `history.load.start` / `history.load.end` | renderer | durationMs, entryCount, status | +| `submit.begin` | renderer | provider, hasImages | +| `submit.result` | renderer | ok, stage, code, promptWritten, enterWritten | +| `submit.unwound` | renderer | **the Bug B fix firing** — phase restored | +| `delivery.reject` | main | code, stage, registryHit | +| `kill.request` | main | cause | + +`gate.eval` on **every** evaluation is the single most important choice here. The +edge-triggered `publishPromptGate` (`claudeSession.ts:785`) is why a +never-ready session is currently invisible: it emits nothing. Recording every +evaluation is what makes "stuck at `composer-unpainted` for 90 s" a fact instead +of a guess. + +### Redaction + +Metadata only: ids, kinds, phases, reasons, counts, durations, booleans. **Never** +prompts, assistant text, tool payloads, file contents, commands, MCP URLs, or +tokens. Enforced by routing every payload through the journal's existing +`sanitizePerformanceData`, and by a unit test asserting the emitter drops unknown +keys rather than passing them through. + +--- + +## Delivery slices + +Red-green-refactor. Behaviour and its regression test land together. + +### Slice 1 — Vocabulary and the main emitter + +**Files:** `src/shared/lifecycle/events.ts` (new), +`src/main/lifecycle/SessionLifecycleJournal.ts` (new). + +**Tests first** — `src/main/lifecycle/SessionLifecycleJournal.test.ts`: + +1. A known event name reaches the underlying journal with `area: + 'session.lifecycle'`. +2. Unknown top-level data keys are dropped, not forwarded. +3. A throwing journal never propagates out of the emitter (recovery correctness + outranks forensics — same contract as `recordRecovery`). +4. A null journal is a silent no-op. + +### Slice 2 — Main emit points + +**Files:** `src/main/sessionManager.ts`. + +Widen `recordRecovery` into the typed emitter and add emissions at the existing +decision points: `recover()` claim/join/adopt/spawn/conflict/cancel, `spawn()` +begin/end, provider `start()` begin/end, `setInputReadiness`, the +`deliverPromptToAgent` registry miss (`:1745`), and `kill`. + +**Tests** — extend `src/main/sessionManager.recover.test.ts`: + +1. Adoption emits `recover.adopted` exactly once with a duration. +2. Cold spawn emits `recover.spawned` and both `provider.start.*`. +3. A typed conflict emits `recover.conflict` carrying the code. +4. Kill-during-recovery emits `recover.cancelled`, not a phantom success. +5. The registry-miss delivery rejection emits `delivery.reject` with + `registryHit: false`. + +### Slice 3 — Renderer bridge and emit points + +**Files:** `src/main/ipc/lifecycle.ts` (new), `src/preload/api/lifecycle.ts` +(new), `src/preload/api/{index,types}.ts`, +`src/renderer/src/lifecycle/report.ts` (new), `rehydrate.ts`, +`hook/actions/session.ts`, `hook/actions/initialHistory.ts`, and the nine wake +call sites (**instrumented in place — not consolidated**, per decomposition §4). + +**Tests:** + +1. IPC rejects an unknown event name. +2. IPC rate-limits a storm and emits one suppression summary. +3. `wake.request` carries a distinct caller identity for each of the nine sites + (this is the data that will tell Stage 4 which of them actually differ). +4. `rehydrate.start`/`complete` bracket a restore with the resolved count. + +### Slice 4 — Provider gate evaluation + +**Files:** `providers/claude/runtime/claudeSession.ts`, +`providers/codex/runtime/codexSession.ts`, +`providers/opencode/runtime/opencodeSession.ts`. + +Emit `gate.eval` on every `derivePromptGateState` evaluation (Claude) and each +provider's equivalent. **Do not change any gate logic in this PR.** + +**Tests:** a resumed Claude session that never quiesces emits repeated +`gate.eval` with `reason: 'replay-pending'` — i.e. the currently-silent stall +becomes a visible fact. + +### Slice 5 — Stage 2a: the pane names its stall + +**Files:** `renderer/.../TileLeaf/readiness.ts`, the composer status badge, and +the failure toast sites. + +Surface `SessionInputReadiness.reason` + elapsed. Replace the reasonless +`'agent failed to start'` with reason + session id. + +**Tests:** each readiness reason maps to its user-facing string; a failure with a +typed code renders the code, not the generic string. + +### Slice 6 — Stage 2b: unwind the optimistic submit (Bug B) + +**Files:** `renderer/.../TileLeaf/useComposerKeybinds.ts`, +`renderer/.../hook/actions/streaming.ts`. + +Add an explicit unwind that restores `streamPhase`, `submittedAt`, +`turnStartedAt`, `phaseChangedAt`, and `awaitingAssistant` to their pre-submit +values, called from the catch **only** when the delivery result proves nothing +was written. + +**Tests first** — `useComposerKeybinds.renderer.test.tsx`: + +1. `deliverPrompt` rejects with `promptWritten: false, enterWritten: false` ⇒ + phase returns to `idle`, `submittedAt` null, draft preserved, toast shown. +2. `deliverPrompt` rejects with `promptWritten: true` ⇒ phase **stays** + `submitting` and `promptDelivery` is `uncertain` (today's behaviour, pinned). +3. A successful submit is unaffected. +4. `streamPhaseMachine`'s `submitting`/`requesting` guard is unchanged — + existing test stays green. + +### Slice 7 — Summarizer and docs + +**Files:** `scripts/summarize-lifecycle.mts` (new), `package.json` script, +`docs/decomposition/agent-boot-readiness.md` status update. + +One phase ladder per session, terminal state, and elapsed per phase. This is the +reader that makes Stage 3's corpus usable. + +--- + +## Invariants + +1. The journal is a **sink**. No production branch reads a lifecycle event. +2. Emission **never** throws into a caller and never awaits. +3. Metadata only. No prompts, payloads, commands, URLs, or tokens. +4. Always on. No env flag gates lifecycle events. +5. Bounded — inherits the per-run 50 MiB ceiling and drop-oldest pending bound. +6. `gate.eval` fires on every evaluation, not only transitions. +7. The nine wake sites are **instrumented, not merged**, in this PR. +8. Submit unwind requires proof nothing was written; never an inference. +9. `streamPhaseMachine.ts:118` is unchanged. +10. No gate/readiness/ownership **logic** changes anywhere in this PR. + +--- + +## Non-goals + +- Fixing why backends go missing (Bug A). Recorded, not fixed. +- Consolidating the nine wake call sites. +- Splitting `sessionManager.ts`, `pane.ts`, `useIpcSubscriptions.ts`, or + `hook/index.ts`. +- Touching Tier 3 transport (`SessionFeed`, preload contracts, remote wire) — + #548 built it correctly. +- Changing the `uncertain` prompt-delivery path. +- A new metrics subsystem, dashboard, or settings toggle. +- Renaming `rehydrate` (noted in decomposition §3 as opportunistic; not here — + it would bury the diff). + +--- + +## Verification + +Per `project_verification_tsc_gate`: electron-vite and vitest do **not** +type-check. Raw `tsc` on both projects is the gate. + +```bash +npm run typecheck # builds workflow-mcp, then tsc -b +npm run test:contract +npm run test:core +npm run test:renderer +npm run test:system +``` + +Run the full suite **once at the end**, not per slice. + +**Not verified by launching the app** (`feedback_never_launch_app`) — correctness +is argued from source and pinned by tests. + +--- + +## Risks + +| Risk | Mitigation | +|---|---| +| Journal volume — `gate.eval` on every evaluation could be chatty | Inherits the 50 MiB per-run ceiling and drop-oldest bound. Slice 4 measures event rate in its test and coalesces identical consecutive evaluations if needed. | +| The unwind hides a real running turn | Gated on `promptWritten === false && enterWritten === false`, a main-reported fact. The `uncertain` path is explicitly untouched and pinned by test 2. | +| Instrumentation drifts from the paths it claims to record | Every emit point sits at an existing decision site; no new control flow is introduced. | +| Scope creep into fixing A | Stated as invariant 10 and non-goal 1. A reviewer should reject any gate-logic change in this diff. | diff --git a/package.json b/package.json index e3f5c1f2..5aedd02d 100644 --- a/package.json +++ b/package.json @@ -40,7 +40,8 @@ "test:coverage": "npm run workflow-mcp:build && NODE_ENV=test vitest run --coverage", "test:package": "npm run build && node scripts/verify-build-output.mjs", "test:contract": "node scripts/check-test-contract.mjs", - "check:keybindings": "tsx --tsconfig tsconfig.web.json scripts/check-command-keybindings.mts", + "lifecycle:summarize": "tsx --tsconfig tsconfig.node.json scripts/summarize-lifecycle.mts", + "check:keybindings": "tsx --tsconfig tsconfig.web.json scripts/check-command-keybindings.mts", "check": "npm run test:contract && npm run check:keybindings && npm run typecheck && npm test && npm run test:package", "audit:production": "npm audit --omit=dev --audit-level=high", "verify:package:mac": "node scripts/verify-packaged-mac.mjs", diff --git a/scripts/summarize-lifecycle.mts b/scripts/summarize-lifecycle.mts new file mode 100644 index 00000000..74700610 --- /dev/null +++ b/scripts/summarize-lifecycle.mts @@ -0,0 +1,265 @@ +#!/usr/bin/env npx tsx --tsconfig tsconfig.node.json +// Session-lifecycle ladder summarizer. +// +// Turns a run's `events.jsonl` into one readable phase ladder per session, and +// flags the ladders that ended somewhere they should not have. +// +// WHY this script exists at all: the lifecycle stream is only worth recording +// if a human can read it without a JSONL viewer and a lot of patience. Stage 3 +// of docs/decomposition/agent-boot-readiness.md is "use the app normally for a +// week and collect real boots" — that is only tolerable if reading the result +// is one command. +// +// npm run lifecycle:summarize # newest run +// npm run lifecycle:summarize -- --run # a specific run id +// npm run lifecycle:summarize -- --all # every retained run +// npm run lifecycle:summarize -- --stalled # only sessions that look wrong +// npm run lifecycle:summarize -- --dir # read runs from elsewhere +// +// `--dir` exists so a journal copied off another machine (or out of a debug +// bundle) can be read without moving files into ~/.config, and so this script +// is verifiable against a fixture without touching real user data. +// +// It reads only; it never writes, prunes, or blesses anything. + +import { readdir, readFile, stat } from 'node:fs/promises' +import { homedir } from 'node:os' +import { join } from 'node:path' +import process from 'node:process' + +// Duplicated rather than imported from @main/storage/paths.js on purpose: that +// module pulls in Electron-adjacent imports, and a read-only forensics script +// must run from a plain `tsx` with no app context. The constant is a stable +// user-visible location, not an internal detail likely to drift. +const DEFAULT_RUNS_DIR = join(homedir(), '.config', 'agent-code', 'incidents', 'runs') +const LIFECYCLE_AREA = 'session.lifecycle' + +type JournalEvent = { + seq: number + ts: number + tsIso: string + area: string + name: string + severity: string + ids?: { sessionId?: string } + data?: Record +} + +/** + * Names that legitimately terminate a recovery ladder. + * + * A `recover.claim` with none of these following it is a STRANDED CLAIM: main + * took ownership of a local session id and never resolved it. That state + * presents to the user as "the agent never started", with nothing anywhere + * explaining why — the exact failure this whole subsystem was built to make + * visible. + */ +const RECOVERY_TERMINALS = new Set([ + 'recover.adopted', + 'recover.spawned', + 'recover.conflict', + 'recover.cancelled', + 'recover.failed', +]) + +function parseArgs(argv: string[]): { + run: string | null + all: boolean + stalledOnly: boolean + dir: string +} { + const runIndex = argv.indexOf('--run') + const dirIndex = argv.indexOf('--dir') + return { + run: runIndex >= 0 ? (argv[runIndex + 1] ?? null) : null, + all: argv.includes('--all'), + stalledOnly: argv.includes('--stalled'), + dir: dirIndex >= 0 ? (argv[dirIndex + 1] ?? DEFAULT_RUNS_DIR) : DEFAULT_RUNS_DIR, + } +} + +async function listRuns(runsDir: string): Promise { + const entries = await readdir(runsDir).catch(() => [] as string[]) + const withTimes = await Promise.all( + entries.map(async name => { + const info = await stat(join(runsDir, name)).catch(() => null) + return info?.isDirectory() ? { name, mtime: info.mtimeMs } : null + }), + ) + return withTimes + .filter((entry): entry is { name: string; mtime: number } => entry !== null) + .sort((a, b) => b.mtime - a.mtime) + .map(entry => entry.name) +} + +async function readLifecycleEvents(runsDir: string, runId: string): Promise { + const raw = await readFile(join(runsDir, runId, 'events.jsonl'), 'utf8').catch(() => '') + const events: JournalEvent[] = [] + for (const line of raw.split('\n')) { + if (line.trim() === '') continue + try { + const parsed = JSON.parse(line) as JournalEvent + // A truncated final line is normal for an append-only file being read + // while the app is still running; skip it rather than fail the report. + if (parsed.area === LIFECYCLE_AREA) events.push(parsed) + } catch { + continue + } + } + return events.sort((a, b) => a.seq - b.seq) +} + +function describe(event: JournalEvent): string { + const data = event.data ?? {} + const parts: string[] = [] + for (const key of ['caller', 'kind', 'gate', 'reason', 'code', 'disposition', 'status', 'cause']) { + const value = data[key] + if (value !== undefined && value !== null && value !== '') parts.push(`${key}=${String(value)}`) + } + if (typeof data.ready === 'boolean') parts.push(`ready=${data.ready}`) + if (typeof data.ok === 'boolean') parts.push(`ok=${data.ok}`) + if (typeof data.durationMs === 'number') parts.push(`${Math.round(data.durationMs)}ms`) + if (typeof data.elapsedMs === 'number' && data.elapsedMs > 0) { + parts.push(`stalled ${Math.round(data.elapsedMs / 1000)}s`) + } + return parts.join(' ') +} + +/** + * The diagnoses this report can make without a human reading every rung. + * + * Each corresponds to a shape named in the decomposition. They are deliberately + * conservative: a flag here should mean "look at this", never "this is the bug". + */ +function diagnose(events: JournalEvent[]): string[] { + const names = events.map(e => e.name) + const findings: string[] = [] + + const claims = names.filter(n => n === 'recover.claim').length + const terminals = names.filter(n => RECOVERY_TERMINALS.has(n)).length + if (claims > terminals) { + findings.push('STRANDED CLAIM — recovery began and never resolved') + } + + const loadStarts = names.filter(n => n === 'history.load.start').length + const loadEnds = names.filter(n => n === 'history.load.end').length + if (loadStarts > loadEnds) { + findings.push('TRANSCRIPT LOAD NEVER ENDED — the #283 stuck-at-loading shape') + } + for (const event of events) { + if (event.name !== 'history.load.end') continue + const status = String(event.data?.status ?? '') + if (status.startsWith('dropped') || status === 'no-terminal-write') { + findings.push(`TRANSCRIPT TERMINAL WRITE LOST (${status})`) + } + } + + // A ladder whose ONLY readiness fact is the seeded 'starting' is the + // fingerprint of "the agent takes minutes to start": publishPromptGate is + // edge-triggered, so a provider that never reaches its composer boundary + // emits nothing further and the renderer waits forever. + const readiness = events.filter(e => e.name === 'readiness.publish') + if (readiness.length > 0 && !readiness.some(e => e.data?.ready === true)) { + findings.push('NEVER BECAME READY — no readiness.publish ever reported ready=true') + } + + const longestStall = events + .filter(e => e.name === 'gate.eval') + .map(e => Number(e.data?.elapsedMs ?? 0)) + .reduce((max, value) => Math.max(max, value), 0) + if (longestStall >= 30_000) { + const gate = events.filter(e => e.name === 'gate.eval').at(-1)?.data + findings.push( + `LONG GATE STALL — ${Math.round(longestStall / 1000)}s at ` + + `${String(gate?.gate ?? '?')}/${String(gate?.reason ?? '?')}`, + ) + } + + for (const event of events) { + if (event.name !== 'delivery.reject') continue + findings.push(`DELIVERY REJECTED — ${String(event.data?.reason ?? event.data?.code ?? '?')}`) + } + if (names.includes('submit.unwound')) { + findings.push('SUBMIT UNWOUND — a prompt failed with nothing written (pre-fix this wedged the pane)') + } + + // Many wakes collapsing onto few recoveries is the #596 remount-storm shape. + const wakes = names.filter(n => n === 'wake.request').length + if (wakes >= 5 && wakes > claims * 3) { + findings.push(`WAKE STORM — ${wakes} wake requests for ${claims} recoveries`) + } + + return findings +} + +function report(runId: string, events: JournalEvent[], stalledOnly: boolean): void { + const bySession = new Map() + const global: JournalEvent[] = [] + for (const event of events) { + const sessionId = event.ids?.sessionId + if (sessionId === undefined) { + global.push(event) + continue + } + const list = bySession.get(sessionId) ?? [] + list.push(event) + bySession.set(sessionId, list) + } + + console.log(`\n═══ run ${runId} — ${events.length} lifecycle events, ${bySession.size} sessions`) + for (const event of global) { + console.log(` · ${event.name} ${describe(event)}`.trimEnd()) + } + + let flagged = 0 + for (const [sessionId, sessionEvents] of bySession) { + const findings = diagnose(sessionEvents) + if (stalledOnly && findings.length === 0) continue + if (findings.length > 0) flagged += 1 + + const first = sessionEvents[0] + console.log(`\n ── ${sessionId} (${first.tsIso})`) + for (const event of sessionEvents) { + // Offset from the session's first event: absolute timestamps are noise + // when the question is always "how long after the previous rung". + const offset = ((event.ts - first.ts) / 1000).toFixed(1).padStart(7) + const detail = describe(event) + console.log(` ${offset}s ${event.name}${detail ? ` ${detail}` : ''}`) + } + for (const finding of findings) console.log(` ⚠ ${finding}`) + } + + if (stalledOnly && flagged === 0) { + console.log(' (no session in this run tripped a diagnosis)') + } +} + +async function main(): Promise { + const args = parseArgs(process.argv.slice(2)) + const runs = await listRuns(args.dir) + if (runs.length === 0) { + console.log(`No runs under ${args.dir}. Launch Agent Code once and retry.`) + return + } + + const selected = args.run !== null + ? runs.filter(id => id === args.run) + : args.all + ? runs + : runs.slice(0, 1) + + if (selected.length === 0) { + console.log(`Run ${args.run} not found. Available: ${runs.slice(0, 10).join(', ')}`) + process.exitCode = 1 + return + } + + for (const runId of selected) { + const events = await readLifecycleEvents(args.dir, runId) + if (events.length === 0 && args.all) continue + report(runId, events, args.stalledOnly) + } + console.log('') +} + +await main() diff --git a/src/main/ipc/index.ts b/src/main/ipc/index.ts index dfdaf127..53ee0a0e 100644 --- a/src/main/ipc/index.ts +++ b/src/main/ipc/index.ts @@ -39,6 +39,7 @@ import type { CaffeinateController } from '@main/caffeinate/CaffeinateController import type { RemoteController } from '@main/remote/RemoteController.js' import type { AppRunJournal } from '@main/incident/AppRunJournal.js' import { registerIncidentIpc } from '@main/ipc/incident.js' +import { registerLifecycleIpc } from '@main/ipc/lifecycle.js' import { registerUsageIpc } from '@main/ipc/usage.js' import { registerCliUpdatesIpc } from '@main/ipc/cliUpdates.js' import type { CliUpdateOrchestrator } from '@main/setup/cliUpdateOrchestrator.js' @@ -107,6 +108,7 @@ export function registerAllIpc(deps: IpcDeps): void { registerCaffeinateIpc(deps.caffeinateController) registerRemoteIpc(deps.remoteController) registerIncidentIpc(deps.appRunJournal) + registerLifecycleIpc(deps.appRunJournal) registerUsageIpc() registerCliUpdatesIpc(deps.cliUpdateOrchestrator) registerWorkflowIpc(deps.workflowBridge) diff --git a/src/main/ipc/lifecycle.test.ts b/src/main/ipc/lifecycle.test.ts new file mode 100644 index 00000000..751b68d7 --- /dev/null +++ b/src/main/ipc/lifecycle.test.ts @@ -0,0 +1,116 @@ +import { EventEmitter } from 'node:events' +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' + +import { SESSION_LIFECYCLE_AREA } from '@shared/lifecycle/events.js' + +// One shared emitter stands in for ipcMain so the handler can be driven +// synchronously. `ipcMain.on` is the only surface this module uses. +const bus = new EventEmitter() +vi.mock('electron', () => ({ + ipcMain: { + on: (channel: string, listener: (event: unknown, payload: unknown) => void) => { + bus.on(channel, payload => listener({}, payload)) + }, + }, +})) + +type Recorded = { area: string; name: string; ids?: { sessionId?: string }; data?: Record } + +function send(payload: unknown): void { + bus.emit('session:lifecycle-report', payload) +} + +describe('registerLifecycleIpc', () => { + let records: Recorded[] + + beforeEach(async () => { + // Frozen clock so the token bucket is deterministic: with real time a + // synchronous storm never refills, and the suppression summary — which only + // emits once a token is available again — could never be observed. + vi.useFakeTimers() + vi.setSystemTime(new Date('2026-07-28T00:00:00Z')) + bus.removeAllListeners() + records = [] + const { registerLifecycleIpc } = await import('./lifecycle') + registerLifecycleIpc({ record: (r: Recorded) => records.push(r) } as never) + }) + + afterEach(() => { + vi.useRealTimers() + }) + + const lifecycle = (): Recorded[] => records.filter(r => r.area === SESSION_LIFECYCLE_AREA) + + it('accepts a known event name and forwards its session id', () => { + send({ name: 'wake.request', sessionId: 's1', data: { caller: 'tile-leaf.send' } }) + + expect(lifecycle()).toHaveLength(1) + expect(lifecycle()[0]).toMatchObject({ + name: 'wake.request', + ids: { sessionId: 's1' }, + data: { caller: 'tile-leaf.send' }, + }) + }) + + it('drops an event name outside the closed vocabulary', () => { + // A renderer from a different build must not be able to widen the + // vocabulary at runtime — the closed set is what keeps the stream readable. + send({ name: 'totally.made.up', sessionId: 's1' }) + send({ name: 'wake.request', sessionId: 's1' }) + + expect(lifecycle().map(r => r.name)).toEqual(['wake.request']) + }) + + it('ignores malformed payloads without throwing', () => { + // IPC is a runtime trust boundary and a renderer mid-freeze is exactly the + // sender most likely to be malformed. + expect(() => { + send(null) + send('a string') + send(42) + send({}) + send({ name: 123 }) + }).not.toThrow() + expect(lifecycle()).toHaveLength(0) + }) + + it('strips payload keys outside the allowlist', () => { + send({ + name: 'submit.result', + sessionId: 's1', + data: { ok: false, prompt: 'secret user text', stack: 'nope' }, + }) + + expect(lifecycle()[0].data).toEqual({ ok: false }) + }) + + it('rate-limits a storm and records the count of what it dropped', () => { + // A remount loop or retry storm is precisely the pathological state this + // instrumentation exists to observe. Unbounded, it would flood the journal + // and evict the breadcrumbs explaining it. + for (let i = 0; i < 500; i += 1) { + send({ name: 'wake.request', sessionId: 's1', data: { caller: 'tile-leaf.send' } }) + } + + // Exactly BURST admitted while the clock is frozen; the other 200 dropped. + expect(lifecycle()).toHaveLength(300) + expect(lifecycle().every(r => r.name === 'wake.request')).toBe(true) + + // The drop must be RECORDED, not silent: a reader reconstructing a ladder + // has to tell "this pane emitted nothing" from "this pane's events were + // dropped". One second of refill admits the next report, which carries the + // count of everything lost. + vi.setSystemTime(new Date('2026-07-28T00:00:01Z')) + send({ name: 'wake.request', sessionId: 's1' }) + + const suppressed = lifecycle().filter(r => r.name === 'report.suppressed') + expect(suppressed).toHaveLength(1) + expect(suppressed[0].data).toMatchObject({ suppressed: 200, reason: 'rate-limited' }) + }) + + it('truncates an unreasonably long session id rather than storing it whole', () => { + send({ name: 'wake.request', sessionId: 'x'.repeat(5000) }) + + expect((lifecycle()[0].ids?.sessionId ?? '').length).toBe(200) + }) +}) diff --git a/src/main/ipc/lifecycle.ts b/src/main/ipc/lifecycle.ts new file mode 100644 index 00000000..b90925e1 --- /dev/null +++ b/src/main/ipc/lifecycle.ts @@ -0,0 +1,83 @@ +import { ipcMain } from 'electron' + +import type { AppRunJournal } from '@main/incident/AppRunJournal.js' +import { SessionLifecycleJournal } from '@main/lifecycle/SessionLifecycleJournal.js' +import { isSessionLifecycleEventName } from '@shared/lifecycle/events.js' + +// Bridges renderer-observed session-lifecycle facts into the always-on journal. +// +// WHY the renderer needs its own channel at all: main sees ownership (who holds +// the backend) but is structurally blind to intent (WHO asked for a wake, and +// whether restore ever finished). The nine wake call sites, rehydrate's +// completion accounting, transcript loading, and composer submit all live in +// the renderer. A boot ladder assembled from main alone cannot answer "why did +// something try to wake this pane", which is the question #596 and #598 both +// turned on. +// +// WHY `send` and not `invoke`: this is fire-and-forget diagnostics. An invoke +// would couple a renderer emit point to main IPC latency, and every emit point +// sits on a hot path (mount effects, submit handlers). Nothing in the renderer +// may ever wait on, or branch on, a lifecycle report. +// +// WHY main re-validates what the renderer already filtered: IPC is a runtime +// trust boundary. `ipc/incident.ts` states the rule this file follows — the +// sender "may itself be misbehaving", and a renderer mid-freeze or mid-crash is +// exactly the sender we most expect to be malformed. Filtering in the renderer +// too is not redundancy for its own sake: it means a mistake surfaces in a +// renderer unit test rather than only as a missing field on someone's disk. + +export function registerLifecycleIpc(journal: AppRunJournal): void { + const lifecycle = new SessionLifecycleJournal(journal) + + // Token bucket, same shape as the incident channel but sized for a different + // traffic profile. Lifecycle events are routine rather than crash-adjacent, + // and one cold boot of a large workspace legitimately emits a burst: ~15 + // visible panes × (recover.request + wake.request + history.load start/end) + // lands ~60 events inside a second or two. + // + // WHY the ceiling exists anyway: a remount loop or a retry storm is precisely + // the pathological state this instrumentation is meant to observe, and an + // unbounded channel would let that state flood the journal and evict the + // breadcrumbs explaining it. Dropping the excess and recording the COUNT + // keeps the storm visible as one honest fact instead of ten thousand. + const RATE_PER_SEC = 100 + const BURST = 300 + let tokens = BURST + let lastRefill = Date.now() + let suppressed = 0 + + ipcMain.on('session:lifecycle-report', (_event, report: unknown) => { + if (!report || typeof report !== 'object') return + const r = report as Record + // An unknown name is dropped rather than passed through. The vocabulary is + // closed on purpose (see @shared/lifecycle/events) and a renderer from a + // different build must not be able to widen it at runtime. + if (!isSessionLifecycleEventName(r.name)) return + const sessionId = typeof r.sessionId === 'string' ? r.sessionId.slice(0, 200) : undefined + + const now = Date.now() + tokens = Math.min(BURST, tokens + ((now - lastRefill) / 1000) * RATE_PER_SEC) + lastRefill = now + if (tokens < 1) { + suppressed += 1 + return + } + tokens -= 1 + if (suppressed > 0) { + // Recorded inline, at the point the gap happened, so a reader + // reconstructing a ladder can tell "this pane emitted nothing" apart from + // "this pane's events were dropped". + lifecycle.record('report.suppressed', undefined, { suppressed, reason: 'rate-limited' }) + suppressed = 0 + } + + // `pickLifecycleData` inside the emitter drops unallowlisted keys and + // non-primitive values, so the raw renderer payload is safe to hand over + // untouched here — the allowlist is the boundary, not this function. + lifecycle.record( + r.name, + sessionId ? { sessionId } : undefined, + r.data as never, + ) + }) +} diff --git a/src/main/lifecycle/SessionLifecycleJournal.test.ts b/src/main/lifecycle/SessionLifecycleJournal.test.ts new file mode 100644 index 00000000..611d4701 --- /dev/null +++ b/src/main/lifecycle/SessionLifecycleJournal.test.ts @@ -0,0 +1,110 @@ +import { describe, expect, it } from 'vitest' + +import { SESSION_LIFECYCLE_AREA } from '@shared/lifecycle/events' +import { SessionLifecycleJournal, type LifecycleJournalSink } from './SessionLifecycleJournal' + +type Recorded = Parameters[0] + +function fakeSink(): { sink: LifecycleJournalSink; records: Recorded[] } { + const records: Recorded[] = [] + return { + records, + sink: { + record(input) { + records.push(input) + }, + }, + } +} + +describe('SessionLifecycleJournal', () => { + it('records a known event under the session.lifecycle area with its session id', () => { + const { sink, records } = fakeSink() + const lifecycle = new SessionLifecycleJournal(sink) + + lifecycle.session('recover.adopted', 'sess-1', { kind: 'claude', durationMs: 42 }) + + expect(records).toHaveLength(1) + expect(records[0].area).toBe(SESSION_LIFECYCLE_AREA) + expect(records[0].name).toBe('recover.adopted') + expect(records[0].ids).toEqual({ sessionId: 'sess-1' }) + expect(records[0].data).toEqual({ kind: 'claude', durationMs: 42 }) + }) + + it('derives severity from the event name rather than the call site', () => { + const { sink, records } = fakeSink() + const lifecycle = new SessionLifecycleJournal(sink) + + lifecycle.session('recover.adopted', 'sess-1') + lifecycle.session('recover.failed', 'sess-1', { code: 'start-failed' }) + + expect(records[0].severity).toBe('info') + expect(records[1].severity).toBe('warn') + }) + + it('drops payload keys that are not allowlisted', () => { + // The allowlist is what makes "metadata only" a structural guarantee rather + // than a convention. A call site that reaches for a content-bearing field + // must lose the field, not leak it into an always-on on-disk stream. + const { sink, records } = fakeSink() + const lifecycle = new SessionLifecycleJournal(sink) + + lifecycle.session('submit.result', 'sess-1', { + ok: false, + // @ts-expect-error deliberately passing keys outside the allowlist. One + // directive covers the literal: excess-property checking reports the + // object once, at its first offending key. + prompt: 'refactor the auth module', + transcript: 'assistant said things', + }) + + expect(records[0].data).toEqual({ ok: false }) + }) + + it('drops non-primitive values so nested payloads cannot bypass the allowlist', () => { + // `sanitizePerformanceData` in the underlying journal only inspects TOP-LEVEL + // keys. An allowlisted key holding an object would therefore carry arbitrary + // nested content straight to disk. Flat primitives keep the allowlist total. + const { sink, records } = fakeSink() + const lifecycle = new SessionLifecycleJournal(sink) + + lifecycle.session('submit.result', 'sess-1', { + // @ts-expect-error deliberately passing a non-primitive for an allowlisted key + reason: { nested: 'content' }, + ok: true, + }) + + expect(records[0].data).toEqual({ ok: true }) + }) + + it('omits data entirely when nothing survives the allowlist', () => { + const { sink, records } = fakeSink() + const lifecycle = new SessionLifecycleJournal(sink) + + // @ts-expect-error deliberately passing only unallowlisted keys + lifecycle.session('wake.request', 'sess-1', { secret: 'x' }) + + expect(records[0].data).toBeUndefined() + }) + + it('never propagates a throwing sink to the caller', () => { + // Emit points sit on the recovery path — the code that repairs the app after + // a crash. A diagnostic that can throw would turn "boot is slow" into "boot + // is broken". This is the single most important property in the file. + const lifecycle = new SessionLifecycleJournal({ + record() { + throw new Error('disk is on fire') + }, + }) + + expect(() => lifecycle.session('recover.spawned', 'sess-1')).not.toThrow() + }) + + it('is an inert no-op when constructed without a sink', () => { + // SessionManager is constructed without a journal in tests, and the incident + // journal itself degrades to a no-op when its directory is unwritable. + const lifecycle = new SessionLifecycleJournal(null) + + expect(() => lifecycle.session('rehydrate.start', 'sess-1')).not.toThrow() + }) +}) diff --git a/src/main/lifecycle/SessionLifecycleJournal.ts b/src/main/lifecycle/SessionLifecycleJournal.ts new file mode 100644 index 00000000..95086df2 --- /dev/null +++ b/src/main/lifecycle/SessionLifecycleJournal.ts @@ -0,0 +1,116 @@ +import type { AppRunJournalIds } from '@main/incident/journalTypes.js' +import { + SESSION_LIFECYCLE_AREA, + pickLifecycleData, + severityForLifecycleEvent, + type SessionLifecycleData, + type SessionLifecycleEventName, +} from '@shared/lifecycle/events.js' + +/** + * The single sink for session-lifecycle events. + * + * WHY this is a thin wrapper over `AppRunJournal` rather than its own store: + * + * `AppRunJournal` already solves every hard part of always-on disk logging, and + * each solution is scar tissue we must not re-earn — a per-run 50 MiB hard + * ceiling (the "logging ate 500 GB" incident), a drop-oldest pending bound, an + * atomic heartbeat, redaction through `sanitizePerformanceData`, and a silent + * degrade to no-op when `~/.config` is unwritable so the diagnostic layer can + * never brick launch. A second store would either duplicate all of that or, + * far more likely, quietly omit a piece of it. + * + * It also matters that these events land in the SAME `events.jsonl` as heap + * pressure, `window.unresponsive`, and crash breadcrumbs. A boot stall that + * coincides with a GC storm is one file scan away from being obvious, and two + * files away from never being noticed. + * + * WHY it takes a structural sink type instead of the concrete class: tests must + * be able to assert emissions without constructing a real journal (which writes + * files and installs `process.report` hooks). `AppRunJournal` satisfies this + * type by construction, so production wiring is unchanged. + * + * ── THE INVARIANT THAT KEEPS THIS FROM BECOMING PART OF THE PROBLEM ── + * + * **Nothing in production reads these events.** This is a sink, never a + * decider. That is the entire reason ~15 emit points scattered across the + * lifecycle surface do not constitute new coupling: no control flow depends on + * them, no state is derived from them, and the whole subsystem is removable in + * one revert without touching behaviour. + * + * If a future fix ever needs a lifecycle fact to make a runtime decision, that + * state belongs in `@shared` as real state with the journal as its + * *serialization* — never a second derivation that could disagree with what the + * code actually did. Same rule as the rendering pipeline's P4. + */ +export type LifecycleJournalSink = { + record(input: { + area: string + name: string + severity?: 'debug' | 'info' | 'warn' | 'error' | 'fatal' + ids?: AppRunJournalIds + data?: Record + }): void +} + +export class SessionLifecycleJournal { + /** + * `null` is a first-class case, not a defensive afterthought: `SessionManager` + * is constructed without a journal in tests and in any non-journaled caller, + * and the incident journal itself degrades to `started = false` when its + * directory is unwritable. + */ + constructor(private readonly sink: LifecycleJournalSink | null = null) {} + + /** + * Record one lifecycle fact. + * + * Contract, all three parts load-bearing: + * + * 1. **Never throws.** Callers sit on the recovery path — the code that + * repairs the app after a crash. A diagnostic that can throw turns + * "boot is slow" into "boot is broken", which would be a spectacular way + * for the observability work to become the outage. This mirrors the + * existing `SessionManager.recordRecovery` guard. + * 2. **Never awaits.** Emission must not add a scheduling boundary to an + * ownership decision. `AppRunJournal.record` is a synchronous push onto a + * bounded in-memory buffer; the disk write is its own 1s timer. + * 3. **Never widens the payload.** `pickLifecycleData` drops unallowlisted + * keys and non-primitive values, so a call site cannot leak content into + * a metadata-only stream even by accident. + */ + record( + name: SessionLifecycleEventName, + ids?: AppRunJournalIds, + data?: SessionLifecycleData, + ): void { + if (!this.sink) return + try { + this.sink.record({ + area: SESSION_LIFECYCLE_AREA, + name, + severity: severityForLifecycleEvent(name), + ids, + data: pickLifecycleData(data), + }) + } catch { + // Deliberately swallowed and deliberately not logged. A console.warn here + // would fire once per event during exactly the disk-trouble that broke + // the journal, converting a silent degradation into console spam on the + // main thread. Lifecycle correctness outranks optional forensics. + } + } + + /** + * Convenience for the overwhelmingly common shape: an event about one + * session. Exists so call sites read as one short line — the property that + * keeps ~15 emit points from cluttering the code they instrument. + */ + session( + name: SessionLifecycleEventName, + sessionId: string, + data?: SessionLifecycleData, + ): void { + this.record(name, { sessionId }, data) + } +} diff --git a/src/main/sessionManager.lifecycle.test.ts b/src/main/sessionManager.lifecycle.test.ts new file mode 100644 index 00000000..5474b54e --- /dev/null +++ b/src/main/sessionManager.lifecycle.test.ts @@ -0,0 +1,337 @@ +import { EventEmitter } from 'node:events' +import { beforeEach, describe, expect, it, vi } from 'vitest' + +import { SESSION_LIFECYCLE_AREA } from '@shared/lifecycle/events.js' + +// Mirrors the mock preamble in sessionManager.recover.test.ts. Kept as a +// separate file rather than appended there because these assertions are about +// the DIAGNOSTIC stream, not about ownership correctness — mixing them would +// make a future reader unsure which failures mean "recovery is broken" and +// which mean "we stopped recording something". +const { createSession, deliverPrompt } = vi.hoisted(() => ({ + createSession: vi.fn(), + deliverPrompt: vi.fn(), +})) + +vi.mock('@providers/registry.main.js', () => ({ + getMainProvider: () => ({ createSession, deliverPrompt }), +})) + +vi.mock('@main/setup/toolchain.js', () => ({ + getToolPath: () => '/usr/bin/true', +})) + +vi.mock('@main/performance/PerformanceService.js', () => ({ + performanceService: { mark: vi.fn(), record: vi.fn(), error: vi.fn() }, +})) + +vi.mock('@main/storage/feedDebugLog.js', () => ({ + forgetFeedDebugSession: vi.fn(), +})) + +class FakeAgentSession extends EventEmitter { + readonly start = vi.fn(async (): Promise => { + this.emit('started', { projectDir: '/tmp/project' }) + }) + readonly stop = vi.fn(async (): Promise => {}) + readonly write = vi.fn() + readonly resize = vi.fn() +} + +type LifecycleRecord = { area: string; name: string; ids?: { sessionId?: string }; data?: Record } + +function journalSpy() { + const all: LifecycleRecord[] = [] + return { + journal: { record: (input: LifecycleRecord) => all.push(input) }, + /** Only the lifecycle stream — the same journal carries other areas. */ + lifecycle: () => all.filter(r => r.area === SESSION_LIFECYCLE_AREA), + names: () => all.filter(r => r.area === SESSION_LIFECYCLE_AREA).map(r => r.name), + find: (name: string) => all.find(r => r.area === SESSION_LIFECYCLE_AREA && r.name === name), + } +} + +describe('SessionManager lifecycle journal', () => { + beforeEach(() => { + createSession.mockReset() + createSession.mockImplementation(() => new FakeAgentSession()) + deliverPrompt.mockReset() + }) + + it('records the full cold-start ladder in order', async () => { + // This ladder IS the artifact. "The agent takes minutes to start" becomes a + // measurable claim only once every rung carries a duration, and the gap + // between rungs is where the minutes will turn out to live. + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + + expect(spy.names()).toEqual([ + 'recover.claim', + 'spawn.begin', + // Seeded `{ ready: false, reason: 'starting' }` BEFORE the provider is + // asked to start — pinned deliberately, because this is the *only* + // readiness fact a never-ready session ever produces. `publishPromptGate` + // is edge-triggered, so if the provider never reaches its composer + // boundary nothing further is emitted and the renderer waits forever with + // no additional signal. A ladder that ends here is the fingerprint of + // "the agent takes minutes to start". + 'readiness.publish', + 'provider.start.begin', + 'provider.start.end', + 'recover.spawned', + ]) + expect(spy.find('recover.claim')?.ids).toEqual({ sessionId: 's1' }) + expect(spy.find('recover.spawned')?.data).toMatchObject({ + kind: 'claude', + disposition: 'spawned', + lifecycle: 'live', + }) + expect(typeof spy.find('provider.start.end')?.data?.durationMs).toBe('number') + }) + + it('records hasResumeId on the claim so cold resume is separable from a fresh pane', async () => { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ + sessionId: 's1', + kind: 'claude', + cwd: '/tmp/project', + resumeSessionId: 'provider-history', + }) + + expect(spy.find('recover.claim')?.data).toMatchObject({ hasResumeId: true }) + }) + + it('records adoption with the adopted backend readiness, not just the disposition', async () => { + // #596's entire root cause was that callers could not tell an adopted live + // agent from a freshly spawned one. Recording readiness AT adoption is what + // lets the Stage 4 catalog separate "adopted a busy healthy agent" from + // "adopted a wedged one". + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project/.' }) + + const adopted = spy.find('recover.adopted') + expect(adopted?.data).toMatchObject({ disposition: 'adopted', lifecycle: 'live' }) + expect(adopted?.data).toHaveProperty('ready') + expect(createSession).toHaveBeenCalledTimes(1) + }) + + it('records an ownership conflict with the reason that produced it', async () => { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + const conflict = await manager.recover({ sessionId: 's1', kind: 'codex', cwd: '/tmp/project' }) + + expect(conflict).toMatchObject({ ok: false, code: 'ownership-conflict' }) + expect(spy.find('recover.conflict')?.data).toMatchObject({ + code: 'ownership-conflict', + reason: 'live-entry-mismatch', + }) + }) + + it('classifies a delivery rejection against an id main has never owned', async () => { + // The reported failure: "Cannot deliver prompt: is not a live agent + // session". `never-owned` means the renderer invented or resurrected an id — + // a persistence/ownership defect. + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + const result = await manager.deliverPromptToAgent('ghost-id', 'hello') + + expect(result).toMatchObject({ ok: false, code: 'not-ready', stage: 'before-write' }) + expect(spy.find('delivery.reject')?.data).toMatchObject({ + code: 'not-ready', + registryHit: false, + reason: 'never-owned', + }) + }) + + it('distinguishes a delivery rejection for a session main owned and lost', async () => { + // Same user-visible message, completely different defect: main DID own this + // id, so a lifecycle teardown was not observed by the renderer — an + // event-delivery bug rather than an id-provenance bug. These two shapes are + // byte-identical to the user and were indistinguishable in logs until now. + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + await manager.kill('s1') + await manager.deliverPromptToAgent('s1', 'hello') + + expect(spy.find('delivery.reject')?.data).toMatchObject({ + registryHit: false, + reason: 'entry-lost-after-owned', + }) + }) + + it('classifies kill by what it actually terminated', async () => { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + await manager.kill('s1') + await manager.kill('never-existed') + + const kills = spy.lifecycle().filter(r => r.name === 'kill.request') + expect(kills.map(k => k.data?.cause)).toEqual(['live-entry', 'no-owner']) + }) + + it('records every published readiness transition with its monotonic revision', async () => { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('input-readiness', { ready: true, reason: 'ready' }) + + const publishes = spy.lifecycle().filter(r => r.name === 'readiness.publish') + expect(publishes.length).toBeGreaterThanOrEqual(2) + expect(publishes[0].data).toMatchObject({ ready: false, reason: 'starting' }) + expect(publishes.at(-1)?.data).toMatchObject({ ready: true, reason: 'ready' }) + // Revisions are the ordering key every consumer uses to reject a stale seed. + // A non-monotonic sequence here would mean the recorded stream cannot be + // trusted to reconstruct what the renderer actually saw. + const revisions = publishes.map(p => p.data?.revision as number) + expect(revisions).toEqual([...revisions].sort((a, b) => a - b)) + }) + + it('records the rich gate verdict that input-readiness collapses away', async () => { + // publishPromptGate reduces its verdict to 'ready' | 'provider-not-ready' + // before it reaches main, so "replaying history", "the composer never + // painted" and "a human has a draft in the box" are indistinguishable in + // every log we have today. They are three different problems. + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('prompt-gate', { kind: 'warming', reason: 'composer-unpainted' }) + + const evals = spy.lifecycle().filter(r => r.name === 'gate.eval') + expect(evals).toHaveLength(1) + expect(evals[0].data).toMatchObject({ + gate: 'warming', + reason: 'composer-unpainted', + elapsedMs: 0, + }) + }) + + it('records a change of WHAT a gate is blocked on', async () => { + // Regression test for a real defect found in review. The dedupe originally + // compared gate kind + reason, but `blocked` states carry no `reason` — they + // carry `condition`. Every blocked state therefore looked identical, so + // trust-dialog → permission-prompt was silently dropped and its `since` + // never reset. That is the one event whose stated purpose is recording what + // a gate is blocked on. + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('prompt-gate', { kind: 'blocked', condition: 'trust-dialog', resolvable: true }) + session.emit('prompt-gate', { kind: 'blocked', condition: 'permission-prompt', resolvable: true }) + + const evals = spy.lifecycle().filter(r => r.name === 'gate.eval') + expect(evals.map(e => e.data?.conditionKind)).toEqual(['trust-dialog', 'permission-prompt']) + }) + + it('records what a blocked gate is blocked on', async () => { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('prompt-gate', { kind: 'blocked', condition: 'trust-dialog', resolvable: true }) + + expect(spy.lifecycle().find(r => r.name === 'gate.eval')?.data).toMatchObject({ + gate: 'blocked', + conditionKind: 'trust-dialog', + resolvable: true, + }) + }) + + it('re-samples a stalled gate so the stall has a measured duration', async () => { + // A single "not ready" event is nearly worthless — that is the normal state + // for a moment during every boot. The same verdict still holding 90 seconds + // later is the entire bug, and nothing in the app records elapsed time in a + // gate state. + vi.useFakeTimers() + try { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('prompt-gate', { kind: 'warming', reason: 'composer-unpainted' }) + await vi.advanceTimersByTimeAsync(11_000) + + const samples = spy.lifecycle() + .filter(r => r.name === 'gate.eval') + .filter(r => (r.data?.elapsedMs as number) > 0) + expect(samples.length).toBeGreaterThanOrEqual(2) + expect(samples.at(-1)?.data).toMatchObject({ + gate: 'warming', + reason: 'composer-unpainted', + }) + expect(samples.at(-1)?.data?.elapsedMs as number).toBeGreaterThanOrEqual(10_000) + } finally { + vi.useRealTimers() + } + }) + + it('stops sampling once nothing is stalled, so an idle workspace writes nothing', async () => { + vi.useFakeTimers() + try { + const { SessionManager } = await import('./sessionManager') + const spy = journalSpy() + const session = new FakeAgentSession() + createSession.mockImplementation(() => session) + const manager = new SessionManager(null, null, spy.journal as never) + + await manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }) + session.emit('prompt-gate', { kind: 'warming', reason: 'replay-pending' }) + session.emit('prompt-gate', { kind: 'ready' }) + await vi.advanceTimersByTimeAsync(30_000) + + const samples = spy.lifecycle() + .filter(r => r.name === 'gate.eval') + .filter(r => (r.data?.elapsedMs as number) > 0) + expect(samples).toHaveLength(0) + } finally { + vi.useRealTimers() + } + }) + + it('emits nothing when constructed without a journal', async () => { + const { SessionManager } = await import('./sessionManager') + const manager = new SessionManager() + + await expect( + manager.recover({ sessionId: 's1', kind: 'claude', cwd: '/tmp/project' }), + ).resolves.toMatchObject({ ok: true }) + }) +}) diff --git a/src/main/sessionManager.ts b/src/main/sessionManager.ts index 86c01f13..e5aa560b 100644 --- a/src/main/sessionManager.ts +++ b/src/main/sessionManager.ts @@ -50,6 +50,8 @@ import type { AgentProviderKind, SessionKind } from '@shared/types/providerKind. import type { BuiltInMcpDomain, BuiltInMcpServerConfig } from '@mcp/shared/types.js' import type { BuiltInMcpHttpHost } from '@mcp/runtime/BuiltInMcpHttpHost.js' import type { AppRunJournal } from '@main/incident/AppRunJournal.js' +import { SessionLifecycleJournal } from '@main/lifecycle/SessionLifecycleJournal.js' +import type { PromptGateState } from '@shared/types/session.js' import type { SessionSpawnOptions, SessionSpawnResult, @@ -376,8 +378,15 @@ export class SessionManager extends EventEmitter { private readonly beforeAgentSessionStart: (() => Promise) | null = null, ) { super() + // Typed lifecycle emitter over the same journal. Constructed here rather + // than injected so every SessionManager — including the ones tests build + // with a null journal — has a non-null emitter and no call site needs a + // `?.` guard. See SessionLifecycleJournal for why nothing may READ these. + this.lifecycle = new SessionLifecycleJournal(journal) } + private readonly lifecycle: SessionLifecycleJournal + // Terminal attach/replay state. // // Why: when the renderer opens a new terminal pane, the sequence @@ -432,22 +441,127 @@ export class SessionManager extends EventEmitter { this.lastActivityAt.set(sessionId, Date.now()) } - private recordRecovery( - name: 'session.recovery.joined' | 'session.recovery.completed' | 'session.recovery.failed', - data: Record, - ): void { - // WHY this helper is best-effort and metadata-only: recovery is the path - // that repairs the app after a crash, so diagnostics must never become a - // new startup dependency. The existing journal is already byte/pending- - // bounded; this wrapper additionally prevents an unexpected journal bug - // from delaying ownership reconciliation. Callers provide only local id, - // provider kind, disposition/lifecycle, duration, or typed failure code— - // never prompts, commands, transcript text, MCP URLs, tokens, or payloads. - try { - this.journal?.record({ area: 'session.recovery', name, data }) - } catch { - // Recovery correctness outranks optional forensic breadcrumbs. - } + /** + * Last gate verdict observed per session, plus when this stretch of it began. + * + * Exists so a STALL has a duration. A single "not ready, composer-unpainted" + * event is nearly worthless — that is the normal state for a moment during + * every boot. The same verdict still holding ninety seconds later is the + * whole bug, and nothing in the app records elapsed time in a gate state. + */ + private readonly lastGateEvaluation = new Map< + string, + { signature: string; gate: string; kind: SessionKind; reason: string | null; since: number; samples: number } + >() + + private gateSampler: ReturnType | null = null + + private noteGateEvaluation(sessionId: string, kind: SessionKind, gate: PromptGateState): void { + const reason = 'reason' in gate ? gate.reason : null + const conditionKind = gate.kind === 'blocked' ? gate.condition : null + // WHY the signature includes the condition and not just kind+reason: + // + // `blocked` states carry NO `reason` field — they carry `condition` and + // `resolvable`. Comparing only kind+reason therefore made every blocked + // state look identical, so a transition from blocked/trust-dialog to + // blocked/permission-prompt was silently dropped AND its `since` never + // reset. That is the one event whose stated purpose is recording what a + // gate is blocked on, so dropping a change of what it is blocked on + // defeated it entirely. + const signature = `${gate.kind}:${reason ?? ''}:${conditionKind ?? ''}` + const previous = this.lastGateEvaluation.get(sessionId) + const changed = previous === undefined || previous.signature !== signature + const since = changed ? Date.now() : previous.since + this.lastGateEvaluation.set(sessionId, { + signature, + gate: gate.kind, + kind, + reason, + since, + samples: changed ? 0 : (previous?.samples ?? 0), + }) + // The upstream `publishPromptGate` already returns early on an unchanged + // verdict, so this is not the load-bearing deduplication — it exists so + // `since` stays anchored to when the CURRENT state began, and so a future + // provider that emits unconditionally cannot flood the journal. + if (!changed) return + this.lifecycle.session('gate.eval', sessionId, { + kind, + gate: gate.kind, + reason, + ...(gate.kind === 'blocked' + ? { conditionKind: gate.condition, resolvable: gate.resolvable } + : {}), + elapsedMs: 0, + }) + this.ensureGateSampler() + } + + /** + * Re-record any session that has been sitting in a non-ready gate, once every + * SAMPLE seconds. + * + * WHY sampling at all, given `prompt-gate` is already edge-triggered at the + * source: a transition tells you a stall STARTED and nothing tells you it is + * still going. Without re-sampling, a session wedged for ten minutes and one + * wedged for two seconds produce byte-identical journals — and the duration + * is the entire diagnostic. Periodic sampling answers "stuck at X for 90s" + * in a few hundred bytes; emitting unconditionally from the screen-snapshot + * path would cost megabytes and evict the breadcrumbs around it. + * + * WHY it only runs while something is non-ready: an idle workspace of ready + * agents writes nothing at all. + * + * TWO BOUNDS, both learned in review, both protecting the SAME shared budget: + * + * 1. **States that mean "waiting on a human" are not sampled.** `occupied` + * (a draft in the composer) and `blocked` (a trust or permission prompt on + * screen) are the app working correctly and waiting for the user. A pane + * parked on an unanswered trust dialog would otherwise emit 17,280 events + * a day describing a non-problem. + * 2. **Sampling stops after MAX_SAMPLES per stall stretch.** The signal + * saturates: knowing a gate has been stuck for two minutes proves the + * stall; the 300th identical sample proves nothing more. + * + * Why both matter more than they look: `AppRunJournal.reserveJournalBytes` is + * a PERMANENT latch. Once a run hits the 50 MiB ceiling, every later event + * AND incident is dropped for the rest of that run — heap pressure, + * window-unresponsive, crash breadcrumbs included. An unbounded sampler could + * therefore blind the incident journal over a multi-day run, which is exactly + * the outcome this instrumentation exists to prevent. + */ + private ensureGateSampler(): void { + if (this.gateSampler) return + const SAMPLE_MS = 5_000 + // ~2 minutes of stall at 5s. Past that the fact is established. + const MAX_SAMPLES = 24 + // Gate kinds that mean "correctly waiting for the user", not "stalled". + const AWAITING_HUMAN = new Set(['occupied', 'blocked']) + this.gateSampler = setInterval(() => { + let stalled = 0 + for (const [sessionId, state] of this.lastGateEvaluation) { + if (state.gate === 'ready') continue + if (AWAITING_HUMAN.has(state.gate)) continue + if (!this.sessions.has(sessionId)) continue + if (state.samples >= MAX_SAMPLES) continue + stalled += 1 + state.samples += 1 + this.lifecycle.session('gate.eval', sessionId, { + // `kind` was missing here, so every SAMPLE dropped out of + // provider-filtered queries while the transitions stayed in. + kind: state.kind, + gate: state.gate, + reason: state.reason, + elapsedMs: Date.now() - state.since, + }) + } + if (stalled === 0 && this.gateSampler) { + clearInterval(this.gateSampler) + this.gateSampler = null + } + }, SAMPLE_MS) + // Never hold the process open for a diagnostic timer. + this.gateSampler.unref?.() } private setInputReadiness(sessionId: string, next: AgentInputReadiness): void { @@ -466,6 +580,19 @@ export class SessionManager extends EventEmitter { // seed that arrives after a newer event. Process/activity signals cannot // safely substitute for this fact. this.emit('input-readiness', { sessionId, input }) + // Records only the DEDUPED transitions this method actually publishes — + // deliberately not every provider evaluation. The per-evaluation stream is + // `gate.eval`, emitted at the provider, and the two together are what make + // a stall legible: `gate.eval` says the provider keeps re-deciding + // "not ready, composer-unpainted", while the absence of a following + // `readiness.publish` proves no consumer was ever told anything changed. + // That gap is invisible today and is the shape behind "the agent takes + // minutes to start". + this.lifecycle.session('readiness.publish', sessionId, { + ready: input.ready, + reason: input.reason ?? null, + revision, + }) } private cleanupSessionState( @@ -505,6 +632,7 @@ export class SessionManager extends EventEmitter { this.lastConditionsSnapshot.delete(sessionId) this.lastTranscriptFile.delete(sessionId) this.lastInputReadiness.delete(sessionId) + this.lastGateEvaluation.delete(sessionId) this.spawnInfo.delete(sessionId) // Keep lastActivityAt after removal. Process telemetry can be asked about a // pane the renderer still knows but whose PTY already exited; deleting this @@ -623,18 +751,17 @@ export class SessionManager extends EventEmitter { const existingClaim = this.recoveriesInFlight.get(options.sessionId) if (existingClaim) { if (existingClaim.kind === kind && existingClaim.cwd === cwd) { - this.recordRecovery('session.recovery.joined', { - sessionId: options.sessionId, + this.lifecycle.session('recover.join', options.sessionId, { kind, lifecycle: 'spawning', }) return existingClaim.promise } - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.conflict', options.sessionId, { kind, code: 'ownership-conflict', lifecycle: 'spawning', + reason: 'claim-in-flight', }) return Promise.resolve(this.recoveryConflict(options.sessionId, existingClaim)) } @@ -643,11 +770,18 @@ export class SessionManager extends EventEmitter { if (existingEntry) { const snapshot = this.getBackendSnapshot(options.sessionId) if (snapshot && snapshot.kind === kind && path.resolve(snapshot.cwd) === cwd) { - this.recordRecovery('session.recovery.completed', { - sessionId: options.sessionId, + // Adoption carries the ADOPTED BACKEND'S readiness, not just the + // disposition. #596 turned on exactly this distinction: a caller that + // adopts a live-but-not-ready agent behaves completely differently from + // one that spawned a fresh process, and until now nothing recorded + // which case a given wake was. Pairing this with `wake.request`'s + // caller tag is what will let the Stage 4 catalog separate them. + this.lifecycle.session('recover.adopted', options.sessionId, { kind, disposition: 'adopted', lifecycle: snapshot.lifecycle, + ready: snapshot.input.ready, + reason: snapshot.input.reason ?? null, durationMs: 0, }) return Promise.resolve({ @@ -659,21 +793,21 @@ export class SessionManager extends EventEmitter { : {}), }) } - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.conflict', options.sessionId, { kind, code: 'ownership-conflict', lifecycle: snapshot?.lifecycle ?? 'live', + reason: 'live-entry-mismatch', }) return Promise.resolve(this.recoveryConflict(options.sessionId, snapshot)) } if (this.spawningSessionGenerations.has(options.sessionId)) { - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.conflict', options.sessionId, { kind, code: 'ownership-conflict', lifecycle: 'spawning', + reason: 'spawn-generation-held', }) return Promise.resolve(this.recoveryConflict(options.sessionId, null)) } @@ -696,6 +830,16 @@ export class SessionManager extends EventEmitter { } claim.promise = Promise.resolve().then(() => this.runRecovery(options, claim)) this.recoveriesInFlight.set(options.sessionId, claim) + // The moment this session becomes main-owned. Recorded because a claim that + // is published and never followed by adopted/spawned/conflict/cancelled/ + // failed is a stranded pane — the exact state that presents to the user as + // "the agent never started" with nothing anywhere explaining why. That + // unterminated-claim shape is the first invariant the Stage 5 replay + // harness will check for. + this.lifecycle.session('recover.claim', options.sessionId, { + kind, + hasResumeId: Boolean(options.resumeSessionId), + }) return claim.promise } @@ -725,11 +869,11 @@ export class SessionManager extends EventEmitter { ): Promise { try { if (claim.cancelled) { - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.cancelled', options.sessionId, { kind: claim.kind, code: 'cancelled', lifecycle: 'spawning', + reason: 'cancelled-before-start', durationMs: performance.now() - claim.startedAt, }) return { @@ -739,6 +883,7 @@ export class SessionManager extends EventEmitter { message: `Recovery for session ${options.sessionId} was cancelled`, } } + this.lifecycle.session('spawn.begin', options.sessionId, { kind: claim.kind }) const spawnPromise = this.spawnWithId({ ...options, cwd: claim.cwd, @@ -752,11 +897,15 @@ export class SessionManager extends EventEmitter { // renderer a phantom backend; stop any late materialization and report // the stable cancelled outcome instead. await this.kill(options.sessionId) - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.cancelled', options.sessionId, { kind: claim.kind, code: 'cancelled', lifecycle: snapshot?.lifecycle ?? 'spawning', + // Distinguishes "the user closed the pane mid-start" from a provider + // that resolved start() after its registry entry was already gone. + // Both return `cancelled` to the renderer, but only the latter is a + // provider-behaviour question worth chasing. + reason: claim.cancelled ? 'cancelled-during-start' : 'entry-vanished', durationMs: performance.now() - claim.startedAt, }) return { @@ -766,11 +915,16 @@ export class SessionManager extends EventEmitter { message: `Recovery for session ${options.sessionId} was cancelled`, } } - this.recordRecovery('session.recovery.completed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.spawned', options.sessionId, { kind: claim.kind, disposition: 'spawned', lifecycle: snapshot.lifecycle, + // A cold-spawned backend is almost never ready at this instant. Capturing + // readiness HERE gives the corpus a baseline to measure "minutes to + // start" against: the interval between this event and the first + // `readiness.publish` with ready:true is the number nobody has ever had. + ready: snapshot.input.ready, + reason: snapshot.input.reason ?? null, durationMs: performance.now() - claim.startedAt, }) return { @@ -781,11 +935,11 @@ export class SessionManager extends EventEmitter { } } catch (error) { if (claim.cancelled) { - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.cancelled', options.sessionId, { kind: claim.kind, code: 'cancelled', lifecycle: 'spawning', + reason: 'cancelled-after-throw', durationMs: performance.now() - claim.startedAt, }) return { @@ -795,8 +949,7 @@ export class SessionManager extends EventEmitter { message: `Recovery for session ${options.sessionId} was cancelled`, } } - this.recordRecovery('session.recovery.failed', { - sessionId: options.sessionId, + this.lifecycle.session('recover.failed', options.sessionId, { kind: claim.kind, code: 'start-failed', lifecycle: 'spawning', @@ -1047,6 +1200,25 @@ export class SessionManager extends EventEmitter { if (!ownsEntry()) return this.setInputReadiness(sessionId, input) }) + // The RICH stall reason, and the reason this listener exists at all. + // + // `publishPromptGate` collapses its detailed verdict into an + // input-readiness event carrying only 'ready' | 'provider-not-ready', so + // by the time readiness reaches main the distinction between "replaying + // history", "the composer never painted", and "a human has a draft in the + // box" is already gone. Those are three completely different problems and + // they are indistinguishable in every log we have today. + // + // Only Claude emits this; Codex and opencode latch a coarse boolean. That + // asymmetry is itself worth recording rather than papering over — see + // `sampleStalledGates` for the provider-agnostic duration signal. + // + // Nothing here changes gate behaviour. This is a listener on an event the + // provider already emitted. + session.on('prompt-gate', (gate: PromptGateState) => { + if (!ownsEntry()) return + this.noteGateEvaluation(sessionId, kind, gate) + }) session.on('pty-data', (data: string) => { if (!ownsEntry()) return this.markActivity(sessionId) @@ -1121,14 +1293,36 @@ export class SessionManager extends EventEmitter { }) this.sessions.set(sessionId, agentEntry) + // Clear any gate state left by a PREVIOUS backend under this same local + // id. Stable ids are deliberately reused after a failed start, and + // cleanupSessionState is generation-owned — it returns early for a + // superseded entry, so relying on teardown alone let a fresh backend + // inherit the dead one's `since` (fabricating elapsed) and, because the + // first verdict then looked unchanged, skip arming the sampler entirely. + this.lastGateEvaluation.delete(sessionId) this.rememberSessionId(sessionId) this.throwIfRecoveryCancelled(recoveryClaim) + // Hoisted out of the try so the catch can report a duration too: a + // provider that throws after 90 seconds and one that throws instantly are + // completely different failures, and the old code could not tell them + // apart because this was scoped to the success path. + const startStartedAt = performance.now() try { - const startStartedAt = performance.now() + // WHY this duplicates the performanceService span below: that span is + // gated behind AGENT_CODE_PERF, which is off by default — which is + // precisely why "the agent takes minutes to start" has never had a + // measurement attached to it. This pair is always on. The perf span + // stays for its richer sampling when someone deliberately enables it. + this.lifecycle.session('provider.start.begin', sessionId, { kind }) await session.start() await this.settleEntryStart(sessionId, agentEntry) this.throwIfRecoveryCancelled(recoveryClaim) if (!ownsEntry()) throw new RecoveryCancelledError() + this.lifecycle.session('provider.start.end', sessionId, { + kind, + ok: true, + durationMs: performance.now() - startStartedAt, + }) performanceService.record({ kind: 'span_end', process: 'main', @@ -1140,6 +1334,11 @@ export class SessionManager extends EventEmitter { }) } catch (err) { await this.settleEntryStart(sessionId, agentEntry) + this.lifecycle.session('provider.start.end', sessionId, { + kind, + ok: false, + durationMs: performance.now() - startStartedAt, + }) performanceService.error('session.spawn.providerStart.error', err, { sessionId, kind, @@ -1730,6 +1929,11 @@ export class SessionManager extends EventEmitter { ): Promise { if (this.promptDeliveriesInFlight.has(sessionId)) { record?.('duplicate-blocked') + this.lifecycle.session('delivery.reject', sessionId, { + code: 'delivery-in-flight', + stage: 'reservation', + registryHit: this.sessions.has(sessionId), + }) return { ok: false, stage: 'reservation', code: 'delivery-in-flight', retrySafe: true, disposition: 'retry-same-session', @@ -1743,6 +1947,31 @@ export class SessionManager extends EventEmitter { // comparisons, and we need `entry.session` narrowed to // AgentSession for the registry call below. if (!entry || entry.kind === 'terminal') { + // ── THE REPORTED FAILURE ── + // "Cannot deliver prompt: is not a live agent session", followed by + // a pane stuck on `Sending · 17s` until the agent is reloaded. + // + // This branch is REGISTRY SPLIT-BRAIN: the renderer believes the pane is + // started, ready and writable, while main holds no entry for it. Why the + // entry is missing is NOT derivable from source — the candidates (an exit + // the renderer never processed, a cancelled recovery, a kill, a wedged + // provider) are indistinguishable at this line. + // + // `everKnown` is the discriminator that makes them distinguishable in the + // corpus, and it is the whole reason this event exists: an id main has + // NEVER owned means the renderer invented or resurrected it (a + // persistence/ownership bug), while an id main owned and lost means a + // lifecycle teardown was not observed by the renderer (an event-delivery + // bug). Those are different defects in different files, and today they + // produce byte-identical user-visible symptoms. + this.lifecycle.session('delivery.reject', sessionId, { + code: 'not-ready', + stage: 'before-write', + registryHit: Boolean(entry), + reason: entry ? 'terminal-session' : this.everKnownSessionIds.has(sessionId) + ? 'entry-lost-after-owned' + : 'never-owned', + }) return { ok: false, stage: 'before-write', code: 'not-ready', retrySafe: true, disposition: 'session-unusable', @@ -1821,6 +2050,16 @@ export class SessionManager extends EventEmitter { if (recovery) recovery.cancelled = true const entry = this.sessions.get(sessionId) const generation = entry?.lifecycle.generation ?? recovery?.spawnGeneration ?? null + // Every backend death passes through here, so this is the one place that + // can answer "did something kill my agent, or did it never start?" — a + // question #596 took a bug report and a full source trace to answer once. + // `cause` separates the three shapes: killing a live entry, cancelling an + // in-flight recovery, and a no-op kill against an id main does not hold + // (which usually means the caller is operating on a stale id). + this.lifecycle.session('kill.request', sessionId, { + cause: entry ? 'live-entry' : recovery ? 'recovery-claim' : 'no-owner', + kind: entry?.kind ?? recovery?.kind ?? null, + }) // WHY registry visibility is severed now but the spawn-generation fence is // not: callers must stop routing input immediately, yet a replacement may diff --git a/src/preload/api/index.ts b/src/preload/api/index.ts index ecf4e568..45c54649 100644 --- a/src/preload/api/index.ts +++ b/src/preload/api/index.ts @@ -22,6 +22,7 @@ import { renderedContentApi } from '@preload/api/renderedContent.js' import { caffeinateApi } from '@preload/api/caffeinate.js' import { menuApi } from '@preload/api/menu.js' import { incidentApi } from '@preload/api/incident.js' +import { lifecycleApi } from '@preload/api/lifecycle.js' import { remoteApi } from '@preload/api/remote.js' import { usageApi } from '@preload/api/usage.js' import { cliUpdatesApi } from '@preload/api/cliUpdates.js' @@ -68,6 +69,7 @@ export const api = { ...caffeinateApi, ...menuApi, ...incidentApi, + ...lifecycleApi, ...remoteApi, ...usageApi, ...cliUpdatesApi, diff --git a/src/preload/api/lifecycle.ts b/src/preload/api/lifecycle.ts new file mode 100644 index 00000000..431f6dc5 --- /dev/null +++ b/src/preload/api/lifecycle.ts @@ -0,0 +1,27 @@ +import { ipcRenderer } from 'electron' + +import type { SessionLifecycleData, SessionLifecycleEventName } from '@shared/lifecycle/events.js' + +// Renderer -> main session-lifecycle breadcrumbs. +// +// One-way and fire-and-forget for the same reason as `incidentApi`: these are +// diagnostics, never product state, and every call site sits on a hot path +// (mount effects, submit handlers, the rehydrate loop). Nothing may wait on +// this, and nothing may branch on whether it succeeded. +// +// The preload stays a thin pass-through: name validation and payload +// allowlisting live in `@shared/lifecycle/events`, applied by the renderer +// helper before this is called and again by main after receipt. Duplicating +// that logic here would create a third copy that can drift. + +export type SessionLifecycleReport = { + name: SessionLifecycleEventName + sessionId?: string + data?: SessionLifecycleData +} + +export const lifecycleApi = { + reportSessionLifecycle: (report: SessionLifecycleReport): void => { + ipcRenderer.send('session:lifecycle-report', report) + }, +} diff --git a/src/providers/codex/runtime/codexSession.ts b/src/providers/codex/runtime/codexSession.ts index be04261a..7f3f7d6f 100644 --- a/src/providers/codex/runtime/codexSession.ts +++ b/src/providers/codex/runtime/codexSession.ts @@ -10,7 +10,11 @@ import { CodexHeadless, CodexResponsesAdapter, ResponsesProxy } from 'codex-head import type { CodexConditionSnapshot, CodexRolloutLine, CodexSemanticEvent } from 'codex-headless' import { canonicalizePath, sanitizePathSegment } from '@shared/runtime/projectDir.js' import type { BuiltInMcpServerConfig } from '@mcp/shared/types.js' -import type { AgentInputReadiness, PromptReadinessOutcome } from '@shared/types/session.js' +import type { + AgentInputReadiness, + PromptGateState, + PromptReadinessOutcome, +} from '@shared/types/session.js' import { isCodexReadyForPromptScreen } from '@providers/codex/runtime/codexReadyForPrompt.js' import { addCodexBuiltInMcpLaunchConfig } from '@providers/shared/runtime/builtInMcpLaunch.js' @@ -111,6 +115,13 @@ export type CodexScreenSnapshot = { export type CodexSessionEvents = { started: [{ projectDir: string; proxyUrl?: string }] 'input-readiness': [AgentInputReadiness] + // Declared, never emitted. This provider latches a coarse ready boolean and + // has no equivalent of Claude's detailed gate verdict, but the key must exist + // for the session to satisfy AgentSession — the same interface-merging shape + // the legacy Claude condition events use. A consumer simply never sees it + // fire, which is the honest representation of "this provider cannot tell you + // why it isn't ready". + 'prompt-gate': [PromptGateState] 'pty-data': [string] screen: [CodexScreenSnapshot] 'jsonl-entry': [CodexRolloutLine, string] diff --git a/src/renderer/src/features/feed/WorkIndicator.tsx b/src/renderer/src/features/feed/WorkIndicator.tsx index a58e658e..ba70b15f 100644 --- a/src/renderer/src/features/feed/WorkIndicator.tsx +++ b/src/renderer/src/features/feed/WorkIndicator.tsx @@ -27,6 +27,7 @@ import { memo, useEffect, useState } from 'react' import { MarkerRow } from '@renderer/features/feed/ui/MarkerRow' import type { StreamPhase } from '@renderer/session-runtime/state' +import { useElapsedSeconds } from '@renderer/lib/useElapsedSeconds' type Props = { phase: StreamPhase @@ -126,35 +127,6 @@ function phaseLabel(phase: StreamPhase, toolName: string | null): string | null } } -// --------------------------------------------------------------------------- -// Elapsed-time hook. -// --------------------------------------------------------------------------- -// -// Only mounts a timer when `since` is non-null. Returns null otherwise -// — caller renders the elapsed slot as empty. We use 1 Hz intentionally: -// sub-second updates are overkill for a "how long have I been waiting" -// readout, and the re-render cost in the feed (which contains -// potentially hundreds of already-mounted rows) is real. - -function useElapsedSeconds(since: number | null): number | null { - const [elapsed, setElapsed] = useState(() => - since === null ? null : Math.max(0, Math.floor((Date.now() - since) / 1000)), - ) - useEffect(() => { - if (since === null) { - setElapsed(null) - return - } - // Fire once immediately so the switch from null → number isn't - // a full second behind; then tick at 1 Hz. - const tick = () => setElapsed(Math.max(0, Math.floor((Date.now() - since) / 1000))) - tick() - const id = setInterval(tick, 1000) - return () => clearInterval(id) - }, [since]) - return elapsed -} - // --------------------------------------------------------------------------- // Elapsed formatter. // --------------------------------------------------------------------------- diff --git a/src/renderer/src/lib/useElapsedSeconds.ts b/src/renderer/src/lib/useElapsedSeconds.ts new file mode 100644 index 00000000..86337c47 --- /dev/null +++ b/src/renderer/src/lib/useElapsedSeconds.ts @@ -0,0 +1,36 @@ +import { useEffect, useState } from 'react' + +/** + * Seconds elapsed since `since`, ticking at 1 Hz. `null` in, `null` out. + * + * Extracted from `WorkIndicator`, which owned the only copy until the pane + * readiness line needed the identical behaviour. Two copies of a ticking hook + * is how one of them quietly drifts to a different interval and the UI starts + * disagreeing with itself about how long something has been happening. + * + * WHY 1 Hz and not requestAnimationFrame or 100ms: this answers "how long have + * I been waiting", where sub-second precision changes no decision, and every + * tick re-renders a subtree that can contain hundreds of already-mounted feed + * rows. The re-render cost is real and the extra precision is worth nothing. + * + * WHY no timer at all when `since` is null: a workspace of healthy panes must + * not hold a bank of intervals for status lines that are not being shown. + */ +export function useElapsedSeconds(since: number | null): number | null { + const [elapsed, setElapsed] = useState(() => + since === null ? null : Math.max(0, Math.floor((Date.now() - since) / 1000)), + ) + useEffect(() => { + if (since === null) { + setElapsed(null) + return + } + // Fire once immediately so the switch from null → number isn't a full + // second behind; then tick at 1 Hz. + const tick = (): void => setElapsed(Math.max(0, Math.floor((Date.now() - since) / 1000))) + tick() + const id = setInterval(tick, 1000) + return () => clearInterval(id) + }, [since]) + return elapsed +} diff --git a/src/renderer/src/lifecycle/report.ts b/src/renderer/src/lifecycle/report.ts new file mode 100644 index 00000000..6d318b2f --- /dev/null +++ b/src/renderer/src/lifecycle/report.ts @@ -0,0 +1,90 @@ +import { + pickLifecycleData, + type SessionLifecycleData, + type SessionLifecycleEventName, + type WakeCaller, +} from '@shared/lifecycle/events' + +// The renderer's one entry point for session-lifecycle breadcrumbs. +// +// ── WHY THIS IS A SINGLE TWO-LINE HELPER ── +// +// Slice 3 adds ~15 emit points spread across rehydrate, nine wake call sites, +// transcript loading, and composer submit. That is exactly the shape that turns +// instrumentation into the mess it was meant to diagnose — unless every call +// site is a single statement a reader's eye skips, with no import ceremony, no +// error handling, no await, and no return value anyone consumes. +// +// The properties that keep this from being new coupling: +// - It never throws. A diagnostic that can throw on a mount effect or a +// submit handler would turn "boot is slow" into "boot is broken". +// - It never awaits. No emit point may add a scheduling boundary to a +// lifecycle decision. +// - Nothing reads the result. Production control flow must never depend on a +// lifecycle event; the journal is a sink, never a decider. That is what +// makes this whole subsystem removable in one revert. +// +// If you ever want to branch on something recorded here, that is the signal +// that the fact belongs in real state (with the journal as its serialization), +// not that this helper should grow a return value. + +/** + * `window.api` is absent in unit tests, in the remote phone client bundle, and + * for a beat during early boot before preload has attached. Resolving it lazily + * per call — rather than capturing it at module scope — means an import of this + * module can never itself be the thing that breaks a non-Electron surface. + */ +type LifecycleBridge = { + reportSessionLifecycle?: (report: { + name: SessionLifecycleEventName + sessionId?: string + data?: SessionLifecycleData + }) => void +} + +function bridge(): LifecycleBridge | null { + if (typeof window === 'undefined') return null + return (window as { api?: LifecycleBridge }).api ?? null +} + +/** + * Record one renderer-observed lifecycle fact. + * + * Payload is allowlist-filtered here as well as in main. Filtering twice is + * deliberate: main cannot trust a renderer payload, and filtering renderer-side + * means a mistaken key fails a renderer unit test instead of silently producing + * an empty field in a file on someone's disk weeks later. + */ +export function reportLifecycle( + name: SessionLifecycleEventName, + sessionId?: string, + data?: SessionLifecycleData, +): void { + try { + const api = bridge() + if (!api?.reportSessionLifecycle) return + api.reportSessionLifecycle({ + name, + ...(sessionId === undefined ? {} : { sessionId }), + ...(data === undefined ? {} : { data: pickLifecycleData(data) }), + }) + } catch { + // Swallowed without logging. A console.warn here would fire once per emit + // point during exactly the degraded state the stream exists to capture. + } +} + +/** + * Record that something asked for a session to be woken, and which of the nine + * call sites asked. + * + * WHY `caller` is a required, closed-union argument rather than optional: + * decomposition §3 counts nine distinct wake call sites across seven files, and + * every historical incident (#596, #598, #590) is one of them behaving + * differently from the others. An untagged `wake.request` is nearly worthless — + * it says a wake happened, which we already knew. The tag is the entire + * diagnostic value, so the type system requires it. + */ +export function reportWake(caller: WakeCaller, sessionId: string, data?: SessionLifecycleData): void { + reportLifecycle('wake.request', sessionId, { ...data, caller }) +} diff --git a/src/renderer/src/session-runtime/state.ts b/src/renderer/src/session-runtime/state.ts index aafbad9d..9302eb7d 100644 --- a/src/renderer/src/session-runtime/state.ts +++ b/src/renderer/src/session-runtime/state.ts @@ -31,7 +31,9 @@ import type { WorktreeActivityState, } from '@shared/work-context/types' import type { ProviderConditionSnapshot } from '@shared/types/providerConditions' -import type { SessionRecoverFailureCode } from '@shared/types/session' +import type { SessionRecoverFailureCode, + SessionInputReadiness, +} from '@shared/types/session' import type { BuiltInMcpDomain } from '@mcp/shared/types' import type { SubAgentState } from '@preload/api/types' export type { SubAgentState, SubAgentToolCall } from '@preload/api/types' @@ -523,6 +525,42 @@ export type SessionRuntime = { /** Last main-owned readiness revision applied to this runtime. -1 means no * authoritative snapshot/event has arrived yet. */ inputReadinessRevision: number + /** + * The advisory reason accompanying the last applied readiness fact. + * + * Correctness gates on `inputReady` ONLY — this is display and diagnosis. + * It exists because a disabled composer with no stated cause is + * indistinguishable to the user from a broken app, which is how "the agent + * takes minutes to start" became a report with nothing attached to it. + * + * Known limitation, deliberate: the provider's DETAILED verdict (replay + * pending vs composer-unpainted vs human-draft) is collapsed to + * 'provider-not-ready' before it leaves main. Recovering that detail here + * means widening the SessionInputReadiness contract, which is Tier 3 + * transport this PR does not touch. The detail is in the lifecycle journal's + * `gate.eval` today. + */ + inputReadinessReason: SessionInputReadiness['reason'] | null + /** + * When the current readiness state began, for the elapsed display. + * + * This is the field that turns a status into evidence: "starting agent" says + * nothing, "starting agent · 94s" says the pane is wedged. Renderer clock, + * not a producer timestamp — it measures how long the USER has been looking + * at this state, which is exactly the quantity being reported. + */ + inputReadinessChangedAt: number | null + /** + * When `transcriptStatus` last changed, for the "loading transcript · Ns" + * elapsed readout. + * + * Separate from `inputReadinessChangedAt` because they measure different + * things: a pane can sit ready for ten minutes and only then begin a + * transcript load. Sharing one clock made that render as "loading transcript + * · 10m" immediately — fabricated evidence in the one place (#283) where the + * duration is the whole diagnostic. + */ + transcriptStatusChangedAt: number | null semantic: SemanticRuntimeState /** Current in-feed stream phase. Set by the `stream_phase` reducer * case from SemanticStreamPhaseEvent; additionally set by the @@ -725,6 +763,9 @@ export function emptyRuntime(): SessionRuntime { recoveryFailureCode: null, inputReady: false, inputReadinessRevision: -1, + inputReadinessReason: null, + inputReadinessChangedAt: null, + transcriptStatusChangedAt: null, semantic: emptySemanticRuntime(), streamPhase: 'idle', streamPhasePendingToolName: null, diff --git a/src/renderer/src/workspace/hook/actions/agentIndexNavigation.renderer.test.tsx b/src/renderer/src/workspace/hook/actions/agentIndexNavigation.renderer.test.tsx index b8d610c7..d3226f3c 100644 --- a/src/renderer/src/workspace/hook/actions/agentIndexNavigation.renderer.test.tsx +++ b/src/renderer/src/workspace/hook/actions/agentIndexNavigation.renderer.test.tsx @@ -103,7 +103,7 @@ describe('useAgentIndexNavigationActions', () => { expect(await harness.actions.focusAgentByPaneLabel('a2')).toBe(true) }) - expect(ensureSessionLive).toHaveBeenCalledWith('a2') + expect(ensureSessionLive).toHaveBeenCalledWith('a2', 'agent-index.navigate') expect(harness.getState().tabs[0].root).toEqual({ type: 'leaf', sessionId: 'a2' }) expect(harness.getState().detachedSessions.a1?.sessionId).toBe('a1') expect(harness.getState().detachedSessions.a2).toBeUndefined() diff --git a/src/renderer/src/workspace/hook/actions/agentIndexNavigation.ts b/src/renderer/src/workspace/hook/actions/agentIndexNavigation.ts index a4345336..0b7312e8 100644 --- a/src/renderer/src/workspace/hook/actions/agentIndexNavigation.ts +++ b/src/renderer/src/workspace/hook/actions/agentIndexNavigation.ts @@ -41,7 +41,7 @@ export function useAgentIndexNavigationActions( // first keystroke lands on a dead backend. ensureSessionLive is also // safe for an already-running detached agent, so this single branch // covers both fresh and restored workspaces. - await sessionActions.ensureSessionLive(initialTarget.sessionId) + await sessionActions.ensureSessionLive(initialTarget.sessionId, 'agent-index.navigate') } catch (error) { showToast( error instanceof Error && error.message.length > 0 diff --git a/src/renderer/src/workspace/hook/actions/initialHistory.ts b/src/renderer/src/workspace/hook/actions/initialHistory.ts index 3a19bbc9..6e2d426d 100644 --- a/src/renderer/src/workspace/hook/actions/initialHistory.ts +++ b/src/renderer/src/workspace/hook/actions/initialHistory.ts @@ -23,6 +23,7 @@ import type { WorkspaceSetRuntimes } from '@renderer/workspace/hook/context' import type { WorkspaceRefs } from '@renderer/workspace/hook/refs' import * as perf from '@renderer/performance/client' import { hasDurableProviderSession } from '@renderer/workspace/providerSessionIdentity' +import { reportLifecycle } from '@renderer/lifecycle/report' const INITIAL_HISTORY_CONCURRENCY = 2 let activeInitialHistoryLoads = 0 @@ -122,6 +123,29 @@ export async function loadInitialHistoryForSession({ // Mark in-flight BEFORE the 'loading' write so the reconciler never sees a // window where status is 'loading' but the load looks idle. inFlightInitialLoads.add(sessionId) + // #283 was "startup/resume stuck at 'loading transcript' until a manual + // reload", caused by an ASYMMETRIC state write: 'loading' set unconditionally, + // but the terminal 'ready'/'error' writes guarded by `if (!current) return + // prev`. A dropped runtime key therefore stranded the pane forever. Bracketing + // the load with start/end makes that asymmetry directly observable — a + // history.load.start with no matching end IS the bug, with no inference + // required. + const historyStartedAt = Date.now() + reportLifecycle('history.load.start', sessionId, { kind }) + // Default is deliberately 'no-terminal-write'. That value surviving to the + // finally block means neither the ready nor the error write ran at all — the + // #283 "marked-but-never-loaded" half. `dropped-*` means the write RAN but + // its runtime key was gone — the "dropped write" half. Two distinct defects + // that presented identically as a pane spinning on 'loading transcript'. + // WHY a mutable local rather than reading state back: this is set from inside + // the setRuntimes updaters below, which is safe ONLY because the workspace + // store invokes updaters synchronously. If runtimes ever move behind a + // deferred setter, `history.load.end` would silently report + // 'no-terminal-write' forever — and that value is the #283 fingerprint, so a + // false positive here is worse than no signal. Flagged in review; the + // synchronous contract is asserted by the test below rather than assumed. + let loadOutcome = 'no-terminal-write' + let loadedEntryCount = 0 setRuntimes(prev => { const current = prev[sessionId] if (!current) return prev @@ -130,6 +154,7 @@ export async function loadInitialHistoryForSession({ [sessionId]: { ...current, transcriptStatus: 'loading', + transcriptStatusChangedAt: Date.now(), transcriptError: null, }, } @@ -151,8 +176,10 @@ export async function loadInitialHistoryForSession({ setRuntimes(prev => { const current = prev[sessionId] if (!current) { + loadOutcome = 'dropped-ready' return prev } + loadOutcome = 'ready' const seen = (refs.seenUuidsRef.current[sessionId] ??= new Set()) seedSeenFromRuntime(current, seen) @@ -226,6 +253,12 @@ export async function loadInitialHistoryForSession({ // newer than every loaded entry (the // "JSONL-stopped-mid-turn before the previous run died" case) // surfaces as expected. + // Captured for the history.load.end breadcrumb. Plain statement rather + // than an assignment folded into the object literal below: this value is + // read by a diagnostic, and a diagnostic must never be the reason a + // production expression is hard to read. + const resolvedTotalEntries = chunk.totalEntries ?? initialEntries.length + loadedEntryCount = resolvedTotalEntries let lastJsonlEntryAt = current.lastJsonlEntryAt for (const entry of initialEntries) { const ts = (entry as { timestamp?: unknown }).timestamp @@ -250,10 +283,11 @@ export async function loadInitialHistoryForSession({ // Falls back to the visible-buffer length when the loader // didn't supply a count — e.g. when initial-history was // called for a session with no on-disk transcript yet. - totalEntries: chunk.totalEntries ?? initialEntries.length, + totalEntries: resolvedTotalEntries, historyOldestMarker: initialOldestMarker ?? current.historyOldestMarker, hasOlderHistory: chunk.hasMore, transcriptStatus: 'ready', + transcriptStatusChangedAt: Date.now(), transcriptError: null, workActivity, workContext, @@ -291,13 +325,16 @@ export async function loadInitialHistoryForSession({ setRuntimes(prev => { const current = prev[sessionId] if (!current) { + loadOutcome = 'dropped-error' return prev } + loadOutcome = 'error' return { ...prev, [sessionId]: { ...current, transcriptStatus: 'error', + transcriptStatusChangedAt: Date.now(), transcriptError: message, }, } @@ -308,6 +345,12 @@ export async function loadInitialHistoryForSession({ // load is genuinely done, so the reconciler must be allowed to see it as // idle-and-stuck and re-kick it. inFlightInitialLoads.delete(sessionId) + reportLifecycle('history.load.end', sessionId, { + kind, + status: loadOutcome, + entryCount: loadedEntryCount, + durationMs: Date.now() - historyStartedAt, + }) } } diff --git a/src/renderer/src/workspace/hook/actions/pane.ts b/src/renderer/src/workspace/hook/actions/pane.ts index 25661092..069186dc 100644 --- a/src/renderer/src/workspace/hook/actions/pane.ts +++ b/src/renderer/src/workspace/hook/actions/pane.ts @@ -909,7 +909,7 @@ export function usePaneActions( const attachDetachedToGrid = useCallback( async (sessionId: SessionId, targetTabId: string, target: PlacementTarget) => { try { - await sessionActions.ensureSessionLive(sessionId) + await sessionActions.ensureSessionLive(sessionId, 'pane.attach-detached') } catch (err) { showToast( err instanceof Error && err.message.length > 0 @@ -996,7 +996,7 @@ export function usePaneActions( const liveIds: SessionId[] = [] for (const sessionId of detachedIds) { try { - await sessionActions.ensureSessionLive(sessionId) + await sessionActions.ensureSessionLive(sessionId, 'pane.attach-all-detached') liveIds.push(sessionId) } catch (err) { console.warn('[workspace] failed to wake detached session before bulk attach:', err) @@ -1797,7 +1797,7 @@ export function usePaneActions( const initialEntry = refs.stateRef.current.buried.find(item => item.id === buriedId) if (!initialEntry) return try { - await sessionActions.ensureSessionLive(initialEntry.sessionId) + await sessionActions.ensureSessionLive(initialEntry.sessionId, 'pane.revive-buried') } catch (err) { showToast( err instanceof Error && err.message.length > 0 diff --git a/src/renderer/src/workspace/hook/actions/providerSwitchCore.renderer.test.ts b/src/renderer/src/workspace/hook/actions/providerSwitchCore.renderer.test.ts index 43fa12bd..0b171f0c 100644 --- a/src/renderer/src/workspace/hook/actions/providerSwitchCore.renderer.test.ts +++ b/src/renderer/src/workspace/hook/actions/providerSwitchCore.renderer.test.ts @@ -83,7 +83,7 @@ describe('switchAgentProvider', () => { targetKind: 'codex', }) - expect(ensureSessionLive).toHaveBeenCalledWith('source-pane') + expect(ensureSessionLive).toHaveBeenCalledWith('source-pane', 'provider-switch.wake-source') expect(switchProvider).toHaveBeenCalledWith({ sourceKind: 'claude', targetKind: 'codex', diff --git a/src/renderer/src/workspace/hook/actions/providerSwitchCore.ts b/src/renderer/src/workspace/hook/actions/providerSwitchCore.ts index 1e8e028a..2da1a27c 100644 --- a/src/renderer/src/workspace/hook/actions/providerSwitchCore.ts +++ b/src/renderer/src/workspace/hook/actions/providerSwitchCore.ts @@ -187,7 +187,7 @@ export async function switchAgentProvider(params: { // recovery is a real mid-transaction ownership change, not ordinary pane // hibernation. `ensureSessionLive` is idempotent for an already-live owner // and main's recovery claim serializes concurrent wake attempts. - const wakeResult = await sessionActions.ensureSessionLive(sessionId) + const wakeResult = await sessionActions.ensureSessionLive(sessionId, 'provider-switch.wake-source') // The translated target transcript must be created BEFORE we replace the // live pane. If translation fails, the current provider process should stay diff --git a/src/renderer/src/workspace/hook/actions/session.ts b/src/renderer/src/workspace/hook/actions/session.ts index 382dc121..adf7a685 100644 --- a/src/renderer/src/workspace/hook/actions/session.ts +++ b/src/renderer/src/workspace/hook/actions/session.ts @@ -49,6 +49,8 @@ import { collectUnownedSessionIds, pickOwnedSessions, } from '@renderer/workspace/sessionOwnership' +import { reportLifecycle, reportWake } from '@renderer/lifecycle/report' +import type { WakeCaller } from '@shared/lifecycle/events' // ----------------------------------------------------------------------------- // Session lifecycle actions. @@ -78,7 +80,7 @@ export type SessionActions = { builtInMcpDomains?: BuiltInMcpDomain[] }, ) => Promise - ensureSessionLive: (sessionId: SessionId) => Promise + ensureSessionLive: (sessionId: SessionId, caller: WakeCaller) => Promise killSession: (sessionId: SessionId) => Promise replaceSession: ( cwd: string, @@ -184,6 +186,7 @@ function softReloadRuntime(current: SessionRuntime, hasProviderSession: boolean) submittedAt: current.submittedAt, hasOlderHistory: true, transcriptStatus: 'loading', + transcriptStatusChangedAt: Date.now(), transcriptError: null, } } @@ -420,9 +423,17 @@ export function useSessionActions( ) const ensureSessionLive = useCallback( - async (sessionId: SessionId): Promise => { + async (sessionId: SessionId, caller: WakeCaller): Promise => { const inFlight = wakeInFlightRef.current.get(sessionId) - if (inFlight) return await inFlight + // WHY the joined caller is still recorded: a remount storm shows up as + // many wake.request events collapsing onto ONE recovery, and that ratio + // is the fingerprint of the #596 class (every pane remount arming its own + // wake). Reporting only the winner would hide it. + if (inFlight) { + reportWake(caller, sessionId, { reason: 'joined-in-flight' }) + return await inFlight + } + reportWake(caller, sessionId) const wake = (async (): Promise => { const snapshot = refs.stateRef.current @@ -443,6 +454,8 @@ export function useSessionActions( processError: message, recoveryFailureCode: 'start-failed', inputReady: false, + inputReadinessReason: null, + inputReadinessChangedAt: Date.now(), }, } }) @@ -506,7 +519,13 @@ export function useSessionActions( // wait below is meaningful and whether the kill on its timeout is // legitimate. Main already answers it; this used to be discarded. let recoveryDisposition: 'adopted' | 'spawned' | null = null + const recoverStartedAt = Date.now() try { + reportLifecycle('recover.request', sessionId, { + kind, + caller, + hasResumeId: Boolean(resumeSessionId), + }) const recovery = await window.api.recoverSession({ sessionId, kind, @@ -519,6 +538,12 @@ export function useSessionActions( }) if (!recovery.ok) { readyError = new Error(recovery.message) + reportLifecycle('recover.request', sessionId, { + caller, + ok: false, + code: recovery.code, + durationMs: Date.now() - recoverStartedAt, + }) recoveryFailureCode = priorRecoveryFailureCode === 'ownership-conflict' ? 'ownership-conflict' : recovery.code @@ -527,6 +552,18 @@ export function useSessionActions( recoverySnapshot = recovery.snapshot recoveredTmuxName = recovery.tmuxName recoveryDisposition = recovery.disposition + // disposition + readiness together are the #596 fingerprint: an + // ADOPTED backend reporting ready:false is the state whose 30s + // timeout used to kill a healthy busy agent. + reportLifecycle('recover.request', sessionId, { + caller, + ok: true, + disposition: recovery.disposition, + lifecycle: recovery.snapshot.lifecycle, + ready: recovery.snapshot.input.ready, + reason: recovery.snapshot.input.reason ?? null, + durationMs: Date.now() - recoverStartedAt, + }) setRuntimes(prev => { const current = prev[sessionId] if (!current) return prev @@ -554,6 +591,16 @@ export function useSessionActions( ? { inputReady: recovery.snapshot.input.ready, inputReadinessRevision: recovery.snapshot.input.revision, + // WHY the reason and clock are seeded here too: + // main's setInputReadiness DEDUPES, so a backend + // that was already non-ready before this wake + // will never emit another readiness event. Without + // seeding, the pane falls back to a generic + // "starting agent" with no elapsed time — + // precisely the wedged case the readout exists + // for. The reason is already on the wire. + inputReadinessReason: recovery.snapshot.input.reason ?? null, + inputReadinessChangedAt: Date.now(), } : {}), exited: null, @@ -646,6 +693,19 @@ export function useSessionActions( const message = readyError instanceof Error && readyError.message.length > 0 ? readyError.message : `Could not wake session ${sessionId}` + // WHY this is here and not beside the recovery result: recovery + // succeeding is NOT the wake succeeding. After a successful recover + // this function still waits on readiness, and on timeout it kills a + // spawned backend and fails the pane. Recording ok:true at the + // recovery boundary meant the #548/#596 path — the exact incident + // this instrumentation exists for — was journaled as a success. + reportLifecycle('wake.result', sessionId, { + caller, + ok: false, + disposition: recoveryDisposition, + code: recoveryFailureCode ?? 'start-failed', + durationMs: Date.now() - recoverStartedAt, + }) setRuntimes(prev => { const current = prev[sessionId] if (!current) return prev @@ -659,6 +719,8 @@ export function useSessionActions( ? 'start-failed' : recoveryFailureCode ?? priorRecoveryFailureCode ?? 'start-failed', inputReady: false, + inputReadinessReason: null, + inputReadinessChangedAt: Date.now(), }, } }) @@ -686,6 +748,17 @@ export function useSessionActions( : {}), ...(recoveredTmuxName ? { tmuxName: recoveredTmuxName } : {}), } + // The wake genuinely succeeded: recovery resolved, readiness either + // arrived or was legitimately skipped for an adopted live backend, and + // nothing killed the pane on the way through. + reportLifecycle('wake.result', sessionId, { + caller, + ok: true, + disposition: recoveryDisposition, + ready: recoverySnapshot?.input.ready ?? null, + durationMs: Date.now() - recoverStartedAt, + }) + setState(prev => { const current = prev.sessions[sessionId] if (!current) return prev diff --git a/src/renderer/src/workspace/hook/actions/sessionRecovery.renderer.test.tsx b/src/renderer/src/workspace/hook/actions/sessionRecovery.renderer.test.tsx index ea0f7b46..e7d63ac7 100644 --- a/src/renderer/src/workspace/hook/actions/sessionRecovery.renderer.test.tsx +++ b/src/renderer/src/workspace/hook/actions/sessionRecovery.renderer.test.tsx @@ -169,7 +169,7 @@ describe('useSessionActions recovery retry', () => { let wakeResult: Awaited> | undefined await act(async () => { - wakeResult = await result.current.ensureSessionLive(sessionId) + wakeResult = await result.current.ensureSessionLive(sessionId, 'tile-leaf.send') }) expect(recoverSession).toHaveBeenCalledTimes(1) diff --git a/src/renderer/src/workspace/hook/actions/streaming.ts b/src/renderer/src/workspace/hook/actions/streaming.ts index 5de01833..2d2e85d8 100644 --- a/src/renderer/src/workspace/hook/actions/streaming.ts +++ b/src/renderer/src/workspace/hook/actions/streaming.ts @@ -109,6 +109,7 @@ export function codexPromptsMatchForOwnership( export function useStreamingActions(setRuntimes: WorkspaceSetRuntimes): { setStreamingBaseline: (sessionId: SessionId, baseline: string | null) => void + unwindStreamingBaseline: (sessionId: SessionId) => void clearPendingRewindUndo: (sessionId: SessionId) => void addOptimisticCodexUserEntry: (sessionId: SessionId, text: string) => void removeOptimisticCodexUserEntry: (sessionId: SessionId, text: string) => void @@ -138,6 +139,84 @@ export function useStreamingActions(setRuntimes: WorkspaceSetRuntimes): { [setRuntimes], ) + /** + * Undo the optimistic submit state when the prompt provably never reached the + * provider. + * + * ── THE BUG THIS FIXES ── + * + * `setStreamingBaseline` sets `streamPhase: 'submitting'` BEFORE the delivery + * attempt. When delivery failed, the catch in `useComposerKeybinds` recorded + * the failure and showed a toast — but never touched the phase. And nothing + * else could: there are exactly three paths back to `'idle'`, and under a + * before-write failure none of them can fire. + * + * 1. `onSessionExit` needs a real exit event. Main holds no registry entry + * to exit — that IS the failure. + * 2. `emptyRuntime()` only happens on a fresh runtime, i.e. an agent + * reload. This is why reloading was the only escape. + * 3. `reduceStreamPhase` needs a provider semantic event. Nothing was + * written, so none will arrive — and `streamPhaseMachine` deliberately + * refuses to stomp `'submitting'` from screen-derived signals anyway. + * + * So `WorkIndicator` rendered `Sending` and `useElapsedSeconds` counted up + * forever: `Sending · 17s`, `Sending · 4m`, until the agent was reloaded. + * + * ── WHY THIS IS NOT THE CONDITIONAL TRAP ── + * + * The repeated failure mode in this subsystem is a guard added to protect one + * path becoming the weapon on another (#548's kill-timeout became #596; + * TileLeaf's `!inputReady` gate became #598). Both were guards that INFERRED + * state. This does not infer: the caller unwinds only when main REPORTS that + * neither the body nor Enter was written. Nothing written means no turn can + * start, so the optimistic phase is provably a lie — not probably one. + * + * The `uncertain` case (something WAS written) is deliberately untouched. + * There a turn may genuinely be starting and unwinding could hide it. + * + * Equally deliberate: this does NOT relax the `submitting`/`requesting` guard + * in `streamPhaseMachine`. That guard is a shipped regression's tombstone. + * The unwind belongs at the site that OWNS the optimistic set. + */ + const unwindStreamingBaseline = useCallback( + (sessionId: SessionId) => { + setRuntimes(prev => { + const current = prev[sessionId] + if (!current) return prev + // Only unwind what this submit actually set. A provider event that + // arrived between the optimistic write and the failure is real, and + // stomping it would trade a stuck spinner for a lost turn — the exact + // suppress-before-replace shape the rendering pipeline is built to + // avoid. + if (current.streamPhase !== 'submitting') return prev + return { + ...prev, + [sessionId]: withDerivedSessionStatus( + appendFeedDebugLog( + { + ...current, + streamPhase: 'idle', + streamPhasePendingToolName: null, + streamPhasePendingToolUseId: null, + submittedAt: null, + turnStartedAt: null, + phaseChangedAt: null, + awaitingAssistant: false, + streamingBaseline: null, + }, + { + layer: 'STATE', + kind: 'submit', + summary: 'submit unwound: nothing was written to the provider', + }, + ), + ), + } + }) + }, + [setRuntimes], + ) + const setStreamingBaseline = useCallback( (sessionId: SessionId, baseline: string | null) => { const now = Date.now() @@ -315,6 +394,7 @@ export function useStreamingActions(setRuntimes: WorkspaceSetRuntimes): { return { setStreamingBaseline, + unwindStreamingBaseline, clearPendingRewindUndo, addOptimisticCodexUserEntry, removeOptimisticCodexUserEntry, diff --git a/src/renderer/src/workspace/hook/actions/streamingUnwind.renderer.test.tsx b/src/renderer/src/workspace/hook/actions/streamingUnwind.renderer.test.tsx new file mode 100644 index 00000000..7d25091a --- /dev/null +++ b/src/renderer/src/workspace/hook/actions/streamingUnwind.renderer.test.tsx @@ -0,0 +1,109 @@ +import { act, renderHook } from '@testing-library/react' +import { describe, expect, it } from 'vitest' + +import { emptyRuntime, type SessionRuntime } from '@renderer/session-runtime/state' +import type { SessionId } from '@renderer/workspace/types' + +import { useStreamingActions } from './streaming' + +// Covers `unwindStreamingBaseline` — the actual repair for the reported bug: +// +// "Cannot deliver prompt: is not a live agent session", then the pane +// shows `Sending · 17s` counting up forever until the agent is reloaded. +// +// An earlier version of this suite asserted a predicate defined inside the test +// file (`!promptWritten && !enterWritten`), which imported nothing from +// production and could not fail if the fix regressed. These tests drive the +// real hook against real runtime state instead. + +function harness(initial: Record) { + let runtimes = initial + const view = renderHook(() => + useStreamingActions(updater => { + runtimes = typeof updater === 'function' ? updater(runtimes) : updater + }), + ) + return { view, get: (id: SessionId) => runtimes[id], all: () => runtimes } +} + +function submitting(overrides: Partial = {}): SessionRuntime { + return { + ...emptyRuntime(), + processStatus: 'started', + streamPhase: 'submitting', + submittedAt: 1_000_000, + turnStartedAt: 1_000_000, + phaseChangedAt: 1_000_000, + awaitingAssistant: true, + streamingBaseline: 'previous assistant text', + ...overrides, + } +} + +describe('unwindStreamingBaseline', () => { + it('clears every field the optimistic submit set, so the spinner stops', () => { + // WorkIndicator renders 'submitting' as `Sending` and times it from + // submittedAt. Leaving either behind reproduces the bug. + const h = harness({ s1: submitting() }) + + act(() => { + h.view.result.current.unwindStreamingBaseline('s1' as SessionId) + }) + + const runtime = h.get('s1' as SessionId) + expect(runtime.streamPhase).toBe('idle') + expect(runtime.submittedAt).toBeNull() + expect(runtime.turnStartedAt).toBeNull() + expect(runtime.phaseChangedAt).toBeNull() + expect(runtime.awaitingAssistant).toBe(false) + expect(runtime.streamingBaseline).toBeNull() + }) + + it('preserves the draft, because a failed submit must not eat the prompt', () => { + const h = harness({ s1: submitting({ draftInput: 'the prompt I just typed' }) }) + + act(() => { + h.view.result.current.unwindStreamingBaseline('s1' as SessionId) + }) + + expect(h.get('s1' as SessionId).draftInput).toBe('the prompt I just typed') + }) + + it('refuses to unwind a phase this submit did not set', () => { + // A real provider event can land between the optimistic write and the + // failure. Stomping it would trade a stuck spinner for a LOST turn — the + // suppress-before-replace shape the rendering pipeline exists to prevent. + const running = submitting({ streamPhase: 'responding' }) + const h = harness({ s1: running }) + + act(() => { + h.view.result.current.unwindStreamingBaseline('s1' as SessionId) + }) + + const runtime = h.get('s1' as SessionId) + expect(runtime.streamPhase).toBe('responding') + expect(runtime.submittedAt).toBe(1_000_000) + }) + + it('is a no-op for a session that no longer exists', () => { + // The pane can be closed while a failed delivery is unwinding. + const h = harness({}) + + act(() => { + h.view.result.current.unwindStreamingBaseline('gone' as SessionId) + }) + + expect(h.all()).toEqual({}) + }) + + it('leaves other sessions untouched', () => { + const h = harness({ s1: submitting(), s2: submitting() }) + + act(() => { + h.view.result.current.unwindStreamingBaseline('s1' as SessionId) + }) + + expect(h.get('s1' as SessionId).streamPhase).toBe('idle') + expect(h.get('s2' as SessionId).streamPhase).toBe('submitting') + }) +}) diff --git a/src/renderer/src/workspace/hook/actions/streamingUnwind.test.ts b/src/renderer/src/workspace/hook/actions/streamingUnwind.test.ts new file mode 100644 index 00000000..9bc84116 --- /dev/null +++ b/src/renderer/src/workspace/hook/actions/streamingUnwind.test.ts @@ -0,0 +1,56 @@ +import { describe, expect, it } from 'vitest' + +import { emptyRuntime, type SessionRuntime } from '@renderer/session-runtime/state' +import { reduceStreamPhase } from '@renderer/session-runtime/semantic/streamPhaseMachine' + +// Reproduces the reported failure as a state-level assertion: +// +// "Cannot deliver prompt: is not a live agent session" +// ...then the pane shows `Sending · 17s`, counting up forever, and only an +// agent reload clears it. +// +// This file pins ONE thing: that nothing else in the system can clear the +// stuck phase, which is why the repair has to live at the submit site. +// +// The unwind itself is covered by streamingUnwind.renderer.test.tsx, which +// drives the real hook. An earlier version of this file also "tested" a +// predicate defined in the test file itself — it imported nothing from +// production and could not fail if the fix regressed. Deleted rather than kept +// for the count. + +function submittingRuntime(): SessionRuntime { + return { + ...emptyRuntime(), + processStatus: 'started', + streamPhase: 'submitting', + submittedAt: 1_000_000, + turnStartedAt: 1_000_000, + phaseChangedAt: 1_000_000, + awaitingAssistant: true, + streamingBaseline: 'previous assistant text', + } +} + +describe('stuck-submitting: why nothing else can clear the phase', () => { + it('the stream-phase machine refuses to stomp submitting from screen signals', () => { + // This guard is a shipped regression's tombstone and must NOT be relaxed to + // fix the stuck spinner — which is exactly why the repair has to live at + // the submit site that owns the optimistic write instead. + const runtime = submittingRuntime() + + const next = reduceStreamPhase( + { + streamPhase: runtime.streamPhase, + streamPhasePendingToolName: runtime.streamPhasePendingToolName, + streamPhasePendingToolUseId: runtime.streamPhasePendingToolUseId, + turnStartedAt: runtime.turnStartedAt, + phaseChangedAt: runtime.phaseChangedAt, + submittedAt: runtime.submittedAt, + }, + { type: 'screen' }, + null, + ) + + expect(next.streamPhase).toBe('submitting') + }) +}) diff --git a/src/renderer/src/workspace/hook/index.ts b/src/renderer/src/workspace/hook/index.ts index f861fef7..f4078b6a 100644 --- a/src/renderer/src/workspace/hook/index.ts +++ b/src/renderer/src/workspace/hook/index.ts @@ -236,6 +236,7 @@ export function useWorkspace( ) const { setStreamingBaseline, + unwindStreamingBaseline, clearPendingRewindUndo, addOptimisticCodexUserEntry, removeOptimisticCodexUserEntry, @@ -439,7 +440,7 @@ export function useWorkspace( sessionId: request.sessionId, maxMessages: 1, }) - await ensureSessionLiveRef.current(request.sessionId) + await ensureSessionLiveRef.current(request.sessionId, 'orchestration.read-agent') const agent = readOrchestrationAgent({ state: refs.stateRef.current, runtimes: refs.latestRuntimesRef.current, @@ -694,7 +695,7 @@ export function useWorkspace( // Sending is the one operation that intentionally wakes a parked // target. Re-authorize after the await because the user can move or // close a pane while the provider is starting. - await ensureSessionLiveRef.current(request.sessionId) + await ensureSessionLiveRef.current(request.sessionId, 'orchestration.send-prompt') assertManagedTarget({ state: refs.stateRef.current, callerSessionId: request.callerSessionId, @@ -909,6 +910,7 @@ export function useWorkspace( setSplitRatio, setSplitRatioInTab, setStreamingBaseline, + unwindStreamingBaseline, clearPendingRewindUndo, acknowledgeSession, appendFeedDebug, diff --git a/src/renderer/src/workspace/hook/ipc/useIpcSubscriptions.ts b/src/renderer/src/workspace/hook/ipc/useIpcSubscriptions.ts index 528eb8b9..2bab5976 100644 --- a/src/renderer/src/workspace/hook/ipc/useIpcSubscriptions.ts +++ b/src/renderer/src/workspace/hook/ipc/useIpcSubscriptions.ts @@ -631,6 +631,14 @@ export function useIpcSubscriptions( ...current, inputReady: input.ready, inputReadinessRevision: input.revision, + inputReadinessReason: input.reason ?? null, + // Only restamped when the state actually changes, so a repeated + // identical verdict does not keep resetting the clock and hide a + // long stall behind a permanently small number. + inputReadinessChangedAt: + current.inputReady === input.ready && current.inputReadinessReason === (input.reason ?? null) + ? current.inputReadinessChangedAt + : Date.now(), }, { layer: 'STATE', @@ -823,6 +831,11 @@ export function useIpcSubscriptions( processStatus: 'exited', processError: null, inputReady: false, + // Restamped on exit for the same reason as every other readiness + // write: without it the pane would report how long ago the DEAD + // backend became ready. + inputReadinessReason: null, + inputReadinessChangedAt: Date.now(), // Clear phase on exit. The WorkIndicator renders // nothing for `idle`; letting a pre-exit phase // linger would leave the in-feed indicator saying diff --git a/src/renderer/src/workspace/hook/persistence/rehydrate.ts b/src/renderer/src/workspace/hook/persistence/rehydrate.ts index 872f255c..dd11bcad 100644 --- a/src/renderer/src/workspace/hook/persistence/rehydrate.ts +++ b/src/renderer/src/workspace/hook/persistence/rehydrate.ts @@ -43,6 +43,7 @@ import type { import type { WorkspaceRefs } from '@renderer/workspace/hook/refs' import { resolveSessionBuiltInMcpDomains } from '@renderer/workspace/mcpDomains' import * as perf from '@renderer/performance/client' +import { reportLifecycle } from '@renderer/lifecycle/report' import { loadInitialHistoryForSession } from '@renderer/workspace/hook/actions/initialHistory' import { resumableProviderSessionId, @@ -135,6 +136,19 @@ export async function rehydrateWorkspace( detachedSessions: Object.keys(persisted.detachedSessions ?? {}).length, buried: persisted.buried?.length ?? 0, }) + // The always-on twin of the perf mark above. The perf channel is gated behind + // AGENT_CODE_PERF and is off by default, which is exactly why no cold boot has + // ever been measured. Shape matters here: #258's fork bomb (49 persisted, 9 + // visible, 40 detached → 40 claude + 40 mitmdump, loadavg 906) is a specific + // ratio between these counts, and this is the first record of that ratio at + // the moment restore begins. + reportLifecycle('rehydrate.start', undefined, { + tabs: persisted.tabs.length, + leaves: Object.keys(persisted.sessions).length, + detached: Object.keys(persisted.detachedSessions ?? {}).length, + buried: persisted.buried?.length ?? 0, + }) + const rehydrateStartedAt = Date.now() const idMap = new Map() const freshSessions: Record = {} const ownedIds = collectOwnedSessionIds(persisted) @@ -409,6 +423,8 @@ export async function rehydrateWorkspace( processError: failure, recoveryFailureCode: failureCode ?? 'start-failed', inputReady: false, + inputReadinessReason: null, + inputReadinessChangedAt: Date.now(), } } if (backend && !preserveObservedTerminalProcess) { @@ -422,6 +438,15 @@ export async function rehydrateWorkspace( ? { inputReady: backend.input.ready, inputReadinessRevision: backend.input.revision, + // WHY the reason and clock are seeded on cold restore: main's + // setInputReadiness dedupes, so a backend already sitting in a + // non-ready state emits no further event after restore. Without + // this, a pane that comes back wedged shows a generic "starting + // agent" with no elapsed time — exactly the case the readout was + // built for. Date.now() is honest here: the renderer genuinely + // has not observed this state for any longer than it has existed. + inputReadinessReason: backend.input.reason ?? null, + inputReadinessChangedAt: Date.now(), } : {}), } @@ -791,6 +816,17 @@ export async function rehydrateWorkspace( expectedSessions, hibernatedSessions: ownedIds.size - liveProcessIds.size, }) + // `ok` is the load-bearing field: restore is "complete" when every visible + // leaf received an OUTCOME, including a retained failure — not when every + // provider started. A run whose rehydrate.start has no matching complete is a + // restore that never resolved, which pins autosave off and is invisible today + // apart from a console.warn. + reportLifecycle('rehydrate.complete', undefined, { + expectedCount: expectedSessions, + resolvedCount: resolvedIds.size, + ok: resolvedIds.size === expectedSessions, + durationMs: Date.now() - rehydrateStartedAt, + }) return { restoredSessions, expectedSessions, diff --git a/src/renderer/src/workspace/tile-tree/AgentTerminalLeaf.tsx b/src/renderer/src/workspace/tile-tree/AgentTerminalLeaf.tsx index d5f5101c..7fb761ab 100644 --- a/src/renderer/src/workspace/tile-tree/AgentTerminalLeaf.tsx +++ b/src/renderer/src/workspace/tile-tree/AgentTerminalLeaf.tsx @@ -288,10 +288,14 @@ export function AgentTerminalLeaf({ if (await tryAttach()) { // Already live and showing. Still wake if the runtime says the // backend is gone — tryAttach only proves an entry existed. - if (needsWake) await ensureSessionLiveRef.current(sessionId) + // Attach already succeeded; this wake is secondary. Tagged `mount` + // because no retry follows it — the tags were swapped in review. + if (needsWake) await ensureSessionLiveRef.current(sessionId, 'agent-terminal-leaf.mount') return } - if (needsWake) await ensureSessionLiveRef.current(sessionId) + // Attach failed, so wake and RETRY the attach below. This is the site + // the `attach-retry` tag describes. + if (needsWake) await ensureSessionLiveRef.current(sessionId, 'agent-terminal-leaf.attach-retry') if (await tryAttach()) return if (disposed) return // Wake reported success but there is still nothing to attach to. Say diff --git a/src/renderer/src/workspace/tile-tree/TerminalLeaf.tsx b/src/renderer/src/workspace/tile-tree/TerminalLeaf.tsx index 86355f2a..81c762f5 100644 --- a/src/renderer/src/workspace/tile-tree/TerminalLeaf.tsx +++ b/src/renderer/src/workspace/tile-tree/TerminalLeaf.tsx @@ -295,7 +295,7 @@ export function TerminalLeaf({ // for helper identity churn would destroy scrollback and re-open the // attach race that the subscribe/attach/drain sequence below exists to // avoid. - void ensureSessionLiveRef.current(sessionId) + void ensureSessionLiveRef.current(sessionId, 'terminal-leaf.mount') .then(() => { if (disposed || termRef.current !== term) return null return window.api.attachTerminal(sessionId) diff --git a/src/renderer/src/workspace/tile-tree/TileLeaf.tsx b/src/renderer/src/workspace/tile-tree/TileLeaf.tsx index 0e4b710c..9b121bb1 100644 --- a/src/renderer/src/workspace/tile-tree/TileLeaf.tsx +++ b/src/renderer/src/workspace/tile-tree/TileLeaf.tsx @@ -33,7 +33,7 @@ import { usePasteToFocus } from '@renderer/workspace/tile-tree/TileLeaf/usePaste import { usePromptHistory } from '@renderer/workspace/tile-tree/TileLeaf/usePromptHistory' import { useClaudeImagePaste } from '@renderer/workspace/tile-tree/TileLeaf/useClaudeImagePaste' import { registerComposerEnterTarget } from '@renderer/workspace/tile-tree/TileLeaf/composerEnterRegistry' -import { resolveReadinessText } from '@renderer/workspace/tile-tree/TileLeaf/readiness' +import { readinessStatusSince, resolveReadinessText } from '@renderer/workspace/tile-tree/TileLeaf/readiness' import { recordHtmlTraceSnapshot } from '@renderer/features/debug/renderTrace' import { isSessionExited } from '@renderer/workspace/providerSessionIdentity' import { useLedgerFeedItems } from '@renderer/features/feed/ledger/useLedgerFeedItems' @@ -41,6 +41,7 @@ import { collectWorkflowRunReferences } from '@renderer/features/workflows/model import { useSessionWorkflowViews } from '@renderer/features/workflows/model/useSessionWorkflowViews' import { WorkflowRunView } from '@renderer/features/workflows/ui/WorkflowRunRow' import { WorkflowViewSelector } from '@renderer/features/workflows/ui/WorkflowViewSelector' +import { useElapsedSeconds } from '@renderer/lib/useElapsedSeconds' // Claude paste-state-machine constants + helpers moved to // ./TileLeaf/claudePaste.ts. Image helpers moved to @@ -298,7 +299,7 @@ export function TileLeaf({ // recovery protocol is explicitly retryable. The draft stays intact // while ensureSessionLive replaces only the backend generation. try { - await workspace.ensureSessionLive(sessionId) + await workspace.ensureSessionLive(sessionId, 'tile-leaf.send') } catch (err) { const message = err instanceof Error && err.message.length > 0 ? err.message @@ -310,7 +311,7 @@ export function TileLeaf({ let ok = await feed.sendInput(sessionId, data, pasteId) if (!ok) { try { - await workspace.ensureSessionLive(sessionId) + await workspace.ensureSessionLive(sessionId, 'tile-leaf.send-retry') ok = await feed.sendInput(sessionId, data, pasteId) } catch (err) { workspace.showPaneToast( @@ -562,7 +563,32 @@ export function TileLeaf({ }, [input, submitCurrentDraft]) const isSessionLive = runtime.sessionStatus === 'running' - const readinessText = resolveReadinessText(runtime) + // WHY the text is resolved TWICE: + // + // `inputReadinessChangedAt` is non-null for a HEALTHY pane too — the reducer + // stamps it on the false→true transition as well. Ticking on that alone + // mounted a permanent 1 Hz interval per pane, re-rendering this component + // (and its composer/feed subtrees) once a second, forever, while + // `resolveReadinessText` returned null and nothing was displayed. Fifteen + // panes meant fifteen idle timers and fifteen renders a second. + // + // So: resolve without a clock first. That answers "is a line shown at all" + // for free, and only then does the timer mount. This is the invariant + // useElapsedSeconds documents — no timers for status lines that are not + // being shown — which the first version violated. + const readinessBaseText = resolveReadinessText(runtime) + const readinessSince = readinessBaseText === null + ? null + : readinessStatusSince(runtime) + const readinessElapsedSeconds = useElapsedSeconds(readinessSince) + const readinessText = readinessBaseText === null + ? null + : resolveReadinessText( + runtime, + readinessSince === null || readinessElapsedSeconds === null + ? null + : readinessSince + readinessElapsedSeconds * 1000, + ) const canRetryBackend = runtime.processStatus === 'failed' || runtime.processStatus === 'exited' @@ -758,7 +784,7 @@ export function TileLeaf({ type="button" className="flex-shrink-0 text-accent hover:underline" onClick={() => { - void workspace.ensureSessionLive(sessionId).catch(err => { + void workspace.ensureSessionLive(sessionId, 'tile-leaf.retry').catch(err => { workspace.showPaneToast( sessionId, err instanceof Error && err.message.length > 0 diff --git a/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.test.ts b/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.test.ts index 25cd41b3..c4f86073 100644 --- a/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.test.ts +++ b/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.test.ts @@ -2,7 +2,7 @@ import { describe, expect, it } from 'vitest' import { emptyRuntime } from '@renderer/session-runtime/state' -import { resolveReadinessText } from './readiness' +import { formatReadinessElapsed, resolveReadinessText } from './readiness' describe('resolveReadinessText', () => { it('does not present a deliberately parked backend as starting', () => { @@ -47,4 +47,125 @@ describe('resolveReadinessText', () => { transcriptStatus: 'ready', })).toBe('agent exited (code 7)') }) + + it('names the readiness reason instead of a generic starting label', () => { + // Before this, EVERY non-ready state rendered 'starting agent'. A wedged + // pane and a healthy one looked identical, which is a large part of why + // "the agent takes minutes to start" was never actionable. + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: false, + transcriptStatus: 'ready', + inputReadinessReason: 'replaying-history', + })).toBe('replaying transcript') + + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: false, + transcriptStatus: 'ready', + inputReadinessReason: 'provider-not-ready', + })).toBe('waiting for agent') + }) + + it('appends elapsed time, which is what separates wedged from normal', () => { + const since = 1_000_000 + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: false, + transcriptStatus: 'ready', + inputReadinessReason: 'provider-not-ready', + inputReadinessChangedAt: since, + }, since + 94_000)).toBe('waiting for agent · 1m 34s') + }) + + it('omits elapsed when the caller supplies no clock', () => { + // Non-ticking callers must not be forced to mount a timer. + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: false, + transcriptStatus: 'ready', + inputReadinessReason: 'provider-not-ready', + inputReadinessChangedAt: 1_000_000, + })).toBe('waiting for agent') + }) + + it('falls back to a generic label rather than rendering an unknown raw token', () => { + // A newer build could send a reason this one has never heard of; the status + // line must not turn into a protocol dump. + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: false, + transcriptStatus: 'ready', + inputReadinessReason: 'something-a-newer-build-sends' as never, + })).toBe('starting agent') + }) + + it('appends the typed recovery code to a failed pane', () => { + // 'ownership-conflict' (another backend owns this id) and 'start-failed' + // (the provider would not launch) need completely different responses from + // the user, and both previously rendered as one undifferentiated string. + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'failed', + processError: 'Session failed to start. Check provider setup and retry.', + recoveryFailureCode: 'ownership-conflict', + inputReady: false, + transcriptStatus: 'ready', + })).toBe('Session failed to start. Check provider setup and retry. (ownership-conflict)') + }) + + it('times a stuck transcript load — the #283 signature', () => { + const since = 5_000 + expect(resolveReadinessText({ + ...emptyRuntime(), + transcriptStatus: 'loading', + transcriptStatusChangedAt: since, + }, since + 30_000)).toBe('loading transcript · 30s') + }) + + it('times the transcript line on the TRANSCRIPT clock, not the readiness clock', () => { + // Regression test for a defect found in review. Feeding + // inputReadinessChangedAt here made a pane whose readiness settled ten + // minutes ago render "loading transcript · 10m" the instant a load began — + // fabricating the exact evidence this line exists to provide. + const now = 1_000_000 + expect(resolveReadinessText({ + ...emptyRuntime(), + transcriptStatus: 'loading', + inputReadinessChangedAt: now - 600_000, + transcriptStatusChangedAt: now - 2_000, + }, now)).toBe('loading transcript · 2s') + }) + + it('reports no clock for a healthy pane, so no timer is mounted for it', () => { + // readinessStatusSince is what decides whether TileLeaf mounts a 1 Hz + // interval. Returning a timestamp for a healthy pane put a permanent + // per-pane timer and re-render on an idle workspace. + expect(resolveReadinessText({ + ...emptyRuntime(), + processStatus: 'started', + inputReady: true, + transcriptStatus: 'ready', + })).toBeNull() + }) +}) + +describe('formatReadinessElapsed', () => { + it('suppresses sub-second noise', () => { + expect(formatReadinessElapsed(400)).toBe('') + }) + + it('reads seconds below a minute and minutes above it', () => { + // The number exists to answer "is this normal or wedged?" — 3s vs 4s never + // changes that answer, 3s vs 4m always does. + expect(formatReadinessElapsed(3_000)).toBe('3s') + expect(formatReadinessElapsed(59_000)).toBe('59s') + expect(formatReadinessElapsed(60_000)).toBe('1m') + expect(formatReadinessElapsed(3_723_000)).toBe('62m 3s') + }) }) diff --git a/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.ts b/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.ts index 013d1fe4..9899748f 100644 --- a/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.ts +++ b/src/renderer/src/workspace/tile-tree/TileLeaf/readiness.ts @@ -1,8 +1,67 @@ import type { SessionRuntime } from '@renderer/session-runtime/state' import { isSessionExited } from '@renderer/workspace/providerSessionIdentity' -export function resolveReadinessText(runtime: SessionRuntime): string | null { - if (runtime.transcriptStatus === 'loading') return 'loading transcript' +/** + * Human-readable text for the readiness reasons that cross the wire. + * + * WHY a map and not inline strings: these are the words a user reads when the + * composer will not accept their prompt, and the previous behaviour — a single + * unconditional `'starting agent'` for every non-ready state — is a large part + * of why "the agent takes minutes to start" was never actionable. A stuck pane + * and a healthy one looked identical. + * + * KNOWN GAP, deliberate: the provider's detailed verdict (replay pending vs + * composer-unpainted vs human-draft) is collapsed to 'provider-not-ready' + * before it leaves main, so it cannot be shown here yet. Recovering it means + * widening the SessionInputReadiness contract — Tier 3 transport this change + * does not touch. The detail is recorded in the lifecycle journal's `gate.eval` + * in the meantime; see docs/decomposition/agent-boot-readiness.md. + */ +const READINESS_REASON_TEXT: Record = { + starting: 'starting agent', + 'replaying-history': 'replaying transcript', + 'provider-not-ready': 'waiting for agent', + ready: 'starting agent', +} + +/** + * Render an elapsed duration for a status line. + * + * WHY seconds and then minutes rather than a precise clock: the number exists + * to answer one question — "is this normal, or is it wedged?" — and 3s versus + * 4s never changes that answer, while 3s versus 4m always does. + */ +export function formatReadinessElapsed(ms: number): string { + if (ms < 1000) return '' + const seconds = Math.floor(ms / 1000) + if (seconds < 60) return `${seconds}s` + const minutes = Math.floor(seconds / 60) + const remainder = seconds % 60 + return remainder === 0 ? `${minutes}m` : `${minutes}m ${remainder}s` +} + +/** + * The status line under a pane whose composer is not accepting input. + * + * `now` is injected rather than read from the clock so the elapsed suffix is + * testable and so the caller controls the tick rate. Passing `null` (the + * default) omits elapsed entirely, which is what non-ticking callers want. + */ +export function resolveReadinessText( + runtime: SessionRuntime, + now: number | null = null, +): string | null { + if (runtime.transcriptStatus === 'loading') { + // #283's signature state. Elapsed matters more here than anywhere else: a + // transcript load that never terminates is invisible without it, and used + // to require a manual agent reload to escape. + // + // It reads the TRANSCRIPT clock, not the readiness clock. Feeding + // `inputReadinessChangedAt` here made a pane whose readiness settled ten + // minutes ago render "loading transcript · 10m" the instant a load began — + // fabricating the exact evidence this line exists to provide. + return withElapsed('loading transcript', runtime.transcriptStatusChangedAt, now) + } if (runtime.transcriptStatus === 'error') { return `transcript unavailable${runtime.transcriptError ? `: ${runtime.transcriptError}` : ''}` } @@ -10,7 +69,13 @@ export function resolveReadinessText(runtime: SessionRuntime): string | null { return `transcript disconnected${runtime.transcriptError ? `: ${runtime.transcriptError}` : ''}` } if (runtime.processStatus === 'failed') { - return runtime.processError ?? 'agent failed to start' + // WHY the typed recovery code is appended: `processError` is a stable, + // payload-free message, but it does not say WHICH failure mode occurred. + // 'ownership-conflict' (another backend owns this id) and 'start-failed' + // (the provider would not launch) need completely different responses from + // the user, and both previously rendered as 'agent failed to start'. + const base = runtime.processError ?? 'agent failed to start' + return runtime.recoveryFailureCode ? `${base} (${runtime.recoveryFailureCode})` : base } if (isSessionExited(runtime)) { return `agent exited${runtime.exited !== null ? ` (code ${runtime.exited})` : ''}` @@ -24,7 +89,30 @@ export function resolveReadinessText(runtime: SessionRuntime): string | null { // evidence of work in progress. Showing a permanent startup warning made a // resource-saving implementation detail look like failed recovery. Reserve // the label for a backend that actually exists and is becoming ready. - if (runtime.processStatus === 'spawning') return 'starting agent' - if (runtime.processStatus === 'started' && !runtime.inputReady) return 'starting agent' + if (runtime.processStatus === 'spawning' || (runtime.processStatus === 'started' && !runtime.inputReady)) { + const reason = runtime.inputReadinessReason + const label = (reason && READINESS_REASON_TEXT[reason]) ?? 'starting agent' + return withElapsed(label, runtime.inputReadinessChangedAt, now) + } return null } + +/** + * The timestamp whose elapsed time belongs beside the status line, or null when + * no line is shown. + * + * Exists so the caller can decide whether to mount a 1 Hz timer WITHOUT + * duplicating the branch order of `resolveReadinessText` — the two must agree + * about which clock is being displayed, and encoding that twice is how they + * silently diverge. + */ +export function readinessStatusSince(runtime: SessionRuntime): number | null { + if (runtime.transcriptStatus === 'loading') return runtime.transcriptStatusChangedAt + return runtime.inputReadinessChangedAt +} + +function withElapsed(label: string, since: number | null, now: number | null): string { + if (since === null || now === null) return label + const elapsed = formatReadinessElapsed(now - since) + return elapsed ? `${label} · ${elapsed}` : label +} diff --git a/src/renderer/src/workspace/tile-tree/TileLeaf/useComposerKeybinds.ts b/src/renderer/src/workspace/tile-tree/TileLeaf/useComposerKeybinds.ts index a2a5f812..cd9d8d36 100644 --- a/src/renderer/src/workspace/tile-tree/TileLeaf/useComposerKeybinds.ts +++ b/src/renderer/src/workspace/tile-tree/TileLeaf/useComposerKeybinds.ts @@ -22,6 +22,7 @@ import { useAppStore } from '@renderer/app-state/hooks' import { useSessionFeed } from '@renderer/features/sessionFeed/SessionFeedContext' import type { PromptDeliveryResult } from '@shared/types/providerConfig' import { draftAfterAcceptance, imagesAfterAcceptance } from './promptDeliveryDraft' +import { reportLifecycle } from '@renderer/lifecycle/report' // The big onKeyDown handler for the composer textarea. // @@ -220,6 +221,19 @@ export function useComposerKeybinds({ : DEFAULT_PROVIDER const caps = getRendererProviderCapabilities(submitProvider) const baseline = extractAssistantInProgress(screen, submitProvider) + // Emitted BEFORE the optimistic streaming state is set, so a recorded + // ladder shows the exact ordering that produces the stuck-`Sending` bug: + // submit.begin → (optimistic streamPhase 'submitting') → submit.result + // ok:false. Today nothing follows that, and the pane counts up forever. + const submitStartedAt = Date.now() + let sendsThatWrote = 0 + reportLifecycle('submit.begin', sessionId, { + provider: submitProvider, + // `source` and NOT `ok`. Every other event uses `ok` for an outcome, so + // overloading it here to mean "has images" would have made the summarizer + // and any future ok:false filter bucket every image submit as a failure. + source: draftImages.length > 0 ? 'with-images' : 'text-only', + }) workspace.setStreamingBaseline(sessionId, baseline) if (caps.usesOptimisticUserEcho) { // Codex does not reliably give us a structured user @@ -242,7 +256,23 @@ export function useComposerKeybinds({ sessionId, input, draftImages: caps.supportsImageAttachments ? draftImages : [], - send, + // WHY successful sends are counted rather than trusting the thrown + // error: Codex never goes through `deliverPrompt` at all — its submit + // is a sequence of raw `send` calls (bracketed paste chunks, then + // Enter) that throw plain Errors carrying no write evidence. So the + // delivery-result gate below covers Claude and opencode but left the + // ENTIRE Codex path unfixed, reproducing the reported bug byte for + // byte on a Codex pane. + // + // A blanket unwind on any plain error would be wrong for the same + // reason: if the paste succeeded and only the Enter threw, something + // DID reach the provider. `send` throws on failure and returns on + // success, so a count of returns is exactly "how many writes landed". + send: async (...args: Parameters) => { + const result = await send(...args) + sendsThatWrote += 1 + return result + }, deliverPrompt: (prompt, imagePaths) => feed.deliverPrompt(sessionId, prompt, imagePaths, pasteId), pasteId, @@ -276,6 +306,11 @@ export function useComposerKeybinds({ layer: 'OUTCOME', event: 'submit:returned', }) + reportLifecycle('submit.result', sessionId, { + provider: submitProvider, + ok: true, + durationMs: Date.now() - submitStartedAt, + }) } catch (err) { // Keep the draft visible if main no longer has a live // session for this pane. Clearing the composer on a @@ -286,6 +321,49 @@ export function useComposerKeybinds({ } const delivery = (err as { promptDeliveryResult?: PromptDeliveryResult }) .promptDeliveryResult + // `bodyWritten`/`enterWritten` are the fields that decide whether this + // failure is recoverable. NOTE the rename: the journal's redactor drops + // any key matching /prompt|content|text|env|token|secret|key/i, so a + // field called `promptWritten` would record NOTHING while looking correct + // in review. See the trap comment in @shared/lifecycle/events. + // Narrowed once: PromptDeliveryResult is a union and the write-evidence + // fields exist only on the failure branch. + const failed = delivery && !delivery.ok ? delivery : null + // THE UNWIND. Gated on main's own evidence that neither the prompt body + // nor Enter reached the provider — not on an inference about why delivery + // failed. Nothing written means no turn can start, so the optimistic + // `submitting` phase set before the attempt is provably stale and would + // otherwise count up forever (see unwindStreamingBaseline for the three + // reasons nothing else can clear it). + // + // The `uncertain` case — something WAS written — is intentionally left + // alone: a turn may genuinely be running and unwinding could hide it. + // Two independent proofs that nothing reached the provider, one per + // submit protocol. Claude/opencode report it in the delivery result; + // Codex has no delivery result, so the evidence is that not a single + // `send` returned successfully. + const nothingWasWritten = failed !== null + ? !failed.promptWritten && !failed.enterWritten + : sendsThatWrote === 0 + if (nothingWasWritten) { + workspace.unwindStreamingBaseline(sessionId) + reportLifecycle('submit.unwound', sessionId, { + provider: submitProvider, + code: failed?.code ?? 'threw', + stage: failed?.stage ?? null, + source: failed !== null ? 'delivery-result' : 'no-successful-send', + }) + } + reportLifecycle('submit.result', sessionId, { + provider: submitProvider, + ok: false, + code: failed ? failed.code : 'threw', + stage: failed ? failed.stage : null, + bodyWritten: failed ? failed.promptWritten : null, + enterWritten: failed ? failed.enterWritten : null, + retryable: failed ? failed.retrySafe : null, + durationMs: Date.now() - submitStartedAt, + }) workspace.updateRuntime(sessionId, { promptDelivery: delivery && !delivery.ok && !delivery.retrySafe ? { diff --git a/src/shared/lifecycle/events.ts b/src/shared/lifecycle/events.ts new file mode 100644 index 00000000..6b9b8a38 --- /dev/null +++ b/src/shared/lifecycle/events.ts @@ -0,0 +1,322 @@ +// The session-lifecycle event vocabulary. +// +// WHY this file exists at all — read `docs/decomposition/agent-boot-readiness.md` +// §0 before changing anything here. Agent boot has been patched ~30 times since +// 2026-04-11 and has never converged, for one measured reason: **no boot event +// has ever been recorded.** Every fix was authored from source reading against a +// failure nobody had captured. This vocabulary is the instrument that ends that. +// +// WHY the vocabulary is CLOSED (a union, not `string`): +// An open event name is how a diagnostic channel rots into noise nobody reads. +// A closed set means a human — or a summarizer script — can enumerate every +// event the system can emit by reading this one file top to bottom. Adding a +// name is a deliberate contract change, reviewed like any other. +// +// WHY the data keys are an ALLOWLIST and not "whatever the call site passes": +// This stream is always on and lands on disk. An open payload is how a debug +// channel becomes a privacy incident (a caller adds `{ prompt }` "just for +// now"). The allowlist inverts the default: unknown keys are dropped, so a +// careless call site loses a field instead of leaking one. This is the same +// posture as the rendering fixture redactor, which is hard-gated rather than +// best-effort. +// +// This module must remain Node- and DOM-free: main, preload, and the renderer +// all import it (the renderer needs the same name/key validation main applies, +// so a bad renderer event is rejected at BOTH ends rather than trusted). + +/** + * `AppRunJournalEvent.area` for every event in this vocabulary. + * + * WHY these ride the existing incident journal instead of a new store: see + * `SessionLifecycleJournal`. Short version — `AppRunJournal` is already + * always-on, byte-capped, redacting, and degrades to a no-op on an unwritable + * `~/.config`. Re-earning that scar tissue in a second store would be strictly + * worse, and co-locating with heap/crash breadcrumbs means a stall can be + * correlated against main-process health in ONE file. + */ +export const SESSION_LIFECYCLE_AREA = 'session.lifecycle' + +/** + * Every event this subsystem can emit. + * + * Grouped by the question each group answers. If you find yourself wanting an + * event that answers a NEW question, that is a signal worth pausing on — the + * decomposition's Stage 4 catalog is where new questions are supposed to come + * from, derived from recordings, not from imagination. + */ +export const SESSION_LIFECYCLE_EVENT_NAMES = [ + // "What did restore try to do, and did every pane get an answer?" + 'rehydrate.start', + 'rehydrate.complete', + + // "Who owns this pane's backend, and how did that get decided?" + 'recover.request', + 'recover.claim', + 'recover.join', + 'recover.adopted', + 'recover.spawned', + 'recover.conflict', + 'recover.cancelled', + 'recover.failed', + + // "How long did actually starting a provider process take?" + // spawn.begin without a spawn.end on purpose: the terminal fact is already + // recover.spawned/recover.failed, which carry the same duration. What this + // rung adds that nothing else does is the GAP to provider.start.begin — the + // time spent in spawn setup (MCP registration, proxy launch) before the + // provider binary is even asked to start. A crash between them strands here. + 'spawn.begin', + 'provider.start.begin', + 'provider.start.end', + + // "Why is the composer not accepting input?" + // + // `gate.eval` is the single most important name here, and it is worth being + // precise about what it does and does not do. + // + // `publishPromptGate` (claudeSession.ts) already deduplicates: it returns + // early when the derived state equals the previous one, so the `prompt-gate` + // event this rides is edge-triggered at the source. `gate.eval` therefore + // records TRANSITIONS, not every evaluation — an earlier version of this + // comment claimed otherwise and was simply wrong. + // + // What makes it valuable is the pairing with `readiness.publish`. That path + // collapses the verdict to 'ready' | 'provider-not-ready' before it leaves + // the provider, so a session that never becomes ready emits nothing + // informative after the initial `{ready:false, reason:'starting'}`. Recording + // the detailed verdict AND re-sampling it while it persists is what turns + // "stuck at composer-unpainted for 90s" into a fact instead of a guess. + 'gate.eval', + 'readiness.publish', + + // "Who asked for this session to be woken, and what happened?" + // + // There are nine distinct wake call sites across seven files (decomposition + // §3, Tier 4). Every historical incident is one of them behaving differently + // from the others. `caller` is what will finally tell us WHICH of them + // actually differ — which is why this PR instruments them in place rather + // than consolidating them on a guess. + 'wake.request', + 'wake.result', + + // "Did the transcript ever finish loading?" (#283's stuck-at-loading class) + 'history.load.start', + 'history.load.end', + + // "Did the prompt reach the provider?" + 'submit.begin', + 'submit.result', + // The Bug B repair firing. Recorded so we can measure how often a submit + // failed with nothing written — i.e. how often the old build would have + // wedged the pane until an agent reload. + 'submit.unwound', + 'delivery.reject', + + // "Did something kill this backend, and who?" + 'kill.request', + + // "Is this recording complete, or did I lose events?" + // + // Its own name rather than folding the count onto a nearby lifecycle event: + // a reader reconstructing a ladder must be able to tell "this pane emitted + // nothing" from "this pane's events were dropped". Attaching the count to, + // say, `rehydrate.complete` would silently corrupt exactly the analysis this + // stream exists to support. + 'report.suppressed', +] as const + +export type SessionLifecycleEventName = (typeof SESSION_LIFECYCLE_EVENT_NAMES)[number] + +const EVENT_NAME_SET: ReadonlySet = new Set(SESSION_LIFECYCLE_EVENT_NAMES) + +export function isSessionLifecycleEventName(value: unknown): value is SessionLifecycleEventName { + return typeof value === 'string' && EVENT_NAME_SET.has(value) +} + +/** + * Identifies which of the nine wake call sites issued a `wake.request`. + * + * WHY a closed union rather than a free string: the whole point of tagging the + * caller is to compare sites against each other in the Stage 4 catalog. Free + * strings drift (`'TileLeaf'` vs `'tileleaf-send'`) and a drifted tag silently + * splits one shape into two, which is worse than no tag at all. + */ +// Enumerated by making `caller` a REQUIRED parameter of `ensureSessionLive` and +// letting the compiler find every call site. That forcing function turned up +// **13**, not the nine a grep had suggested — which is itself a small lesson +// about why this instrumentation exists at all. +export const WAKE_CALLERS = [ + // TileLeaf.send: the composer path. Wakes when the pane is not started/ready + // or a raw write bounced. This is the site whose `!inputReady` gate caused + // #598 — a live provider condition is *precisely* the state that clears + // inputReady, so every click on a trust modal took the wake path. + 'tile-leaf.send', + 'tile-leaf.send-retry', + // The Retry affordance under a failed pane's readiness banner. + 'tile-leaf.retry', + // Mount-time wake. Unconditional until #597; the site that made every + // Spotlight/Reader/Settings/tab-switch remount arm a 30s kill timer. + 'agent-terminal-leaf.mount', + 'agent-terminal-leaf.attach-retry', + 'terminal-leaf.mount', + // Dispatch → grid placement, one per attached session. + 'pane.attach-detached', + 'pane.attach-all-detached', + // Buried pane revival. + 'pane.revive-buried', + 'agent-index.navigate', + // Wake the source pane before provider-switch compaction (#590). + 'provider-switch.wake-source', + // MCP-driven: reading a child agent, and sending it a prompt. The only wake + // callers that are not a direct human gesture — worth separating, because a + // storm here means an orchestration loop rather than a UI remount. + 'orchestration.read-agent', + 'orchestration.send-prompt', +] as const + +export type WakeCaller = (typeof WAKE_CALLERS)[number] + +/** + * The allowlisted top-level payload keys. + * + * ──────────────────────────────────────────────────────────────────────────── + * TRAP — READ BEFORE ADDING A KEY. + * + * `AppRunJournal.createEvent` runs every payload through + * `sanitizePerformanceData`, which DROPS any top-level key matching + * + * /prompt|content|text|env|token|secret|key/i + * + * ...silently. That regex is a privacy control and is deliberately not being + * relaxed. But it means a naively-named field vanishes with no error: + * + * - `promptWritten` → dropped (matches `prompt`) → use `bodyWritten` + * - `context` → dropped (matches `text`) → use a specific noun + * - `envKind` → dropped (matches `env`) → rename + * + * Every key below has been checked against that regex. If you add one, check + * it too, or you will ship an event that records nothing and looks fine in + * review. + * ──────────────────────────────────────────────────────────────────────────── + * + * WHY metadata only: this stream is always on and retained on disk. It records + * ids, kinds, phases, reasons, counts, durations and booleans — never prompts, + * assistant output, tool payloads, file contents, commands, MCP URLs, or + * tokens. The allowlist is what makes that a structural guarantee rather than a + * convention someone eventually forgets. + */ +export const SESSION_LIFECYCLE_DATA_KEYS = [ + // identity / classification + 'kind', + 'caller', + 'disposition', + 'lifecycle', + 'provider', + // Free-form sub-classification for events whose variant is not an outcome. + // Exists so `ok` is never overloaded to mean something other than success. + 'source', + + // outcome + 'ok', + 'code', + 'reason', + 'stage', + 'status', + 'retryable', + 'cause', + + // readiness + 'ready', + 'revision', + 'gate', + 'resolvable', + 'conditionKind', + + // delivery evidence (see the trap above — NOT `promptWritten`) + 'bodyWritten', + 'enterWritten', + 'registryHit', + 'hasResumeId', + + // shape / volume + 'tabs', + 'leaves', + 'detached', + 'buried', + 'expectedCount', + 'resolvedCount', + 'entryCount', + 'suppressed', + + // timing + 'durationMs', + 'elapsedMs', +] as const + +export type SessionLifecycleDataKey = (typeof SESSION_LIFECYCLE_DATA_KEYS)[number] + +const DATA_KEY_SET: ReadonlySet = new Set(SESSION_LIFECYCLE_DATA_KEYS) + +/** + * A lifecycle payload. Every value is a primitive: the journal's sanitizer only + * inspects TOP-LEVEL keys, so a nested object would sail past the allowlist + * carrying whatever it liked. Keeping values flat makes the allowlist total. + */ +export type SessionLifecycleData = Partial< + Record +> + +/** + * Drop every key that is not allowlisted, and every value that is not a + * primitive. + * + * Applied at BOTH ends of the renderer→main bridge on purpose. Main cannot + * trust a renderer payload (the sender may itself be misbehaving — the same + * reasoning `ipc/incident.ts` already applies), and the renderer filtering + * first means a mistake shows up in a renderer unit test rather than only in a + * file on someone's disk. + */ +export function pickLifecycleData(data: unknown): SessionLifecycleData | undefined { + if (!data || typeof data !== 'object' || Array.isArray(data)) return undefined + const out: Record = {} + for (const [key, value] of Object.entries(data as Record)) { + if (!DATA_KEY_SET.has(key)) continue + if (value === null) { + out[key] = null + continue + } + const t = typeof value + if (t === 'string' || t === 'number' || t === 'boolean') { + out[key] = value as string | number | boolean + } + // Anything else (object, array, function, undefined) is dropped rather than + // stringified: a stringified object is exactly how payload text sneaks into + // a metadata-only stream. + } + return Object.keys(out).length > 0 ? out : undefined +} + +/** + * Severity is derived from the event name, not passed by callers. + * + * WHY: severity is a property of WHAT HAPPENED, not of who is reporting it. Two + * call sites emitting `recover.failed` at different severities would make the + * stream un-filterable, and "which severity do I pass here?" is a decision no + * instrumentation call site should have to make — every such decision is one + * more way for an emit point to be subtly wrong. + */ +const SEVERITY_BY_NAME: Partial> = { + 'recover.conflict': 'warn', + 'recover.cancelled': 'warn', + 'recover.failed': 'warn', + 'delivery.reject': 'warn', + 'submit.unwound': 'warn', + // Not a session failure, but a gap in the recording — which for a stream + // whose entire purpose is reconstructing what happened is worth surfacing at + // the same level as one. + 'report.suppressed': 'warn', +} + +export function severityForLifecycleEvent(name: SessionLifecycleEventName): 'info' | 'warn' { + return SEVERITY_BY_NAME[name] ?? 'info' +} diff --git a/src/shared/types/session.ts b/src/shared/types/session.ts index 4cee5061..d635d5b0 100644 --- a/src/shared/types/session.ts +++ b/src/shared/types/session.ts @@ -234,6 +234,22 @@ export type AgentPermissionPromptState = { export type AgentSessionEvents = { started: [{ projectDir?: string; proxyUrl?: string }] 'input-readiness': [AgentInputReadiness] + /** + * Optional, diagnostic-only companion to `input-readiness`. + * + * `input-readiness` is the CONTRACT — a boolean plus a coarse reason, and the + * only thing correctness may gate on. This carries the provider's detailed + * verdict (replay pending, composer unpainted, human draft, blocked on a + * condition), which `publishPromptGate` otherwise collapses away before main + * can see it. Those distinctions are three different problems that are + * indistinguishable in every log we have. + * + * Declared optional-by-convention: only Claude emits it today. A provider + * that doesn't simply never fires the callback, exactly like the legacy + * condition events below. Nothing may branch on it — a consumer that needs a + * decision must use `input-readiness`. + */ + 'prompt-gate': [PromptGateState] 'pty-data': [string] screen: [AgentScreenSnapshot] 'jsonl-entry': [AgentTranscriptEntry, string]