fix(foreground-fallback): add event-level diagnostic logging

Add per-event log lines to the foreground fallback hook so that the
session-level state machine is observable from logs alone. Each event
records the current state, the event name, and the resulting transition
(or no-op reason).

- Emit logs on session.idle, session.error, and session.deleted
- Cover the new logging with focused unit tests
- Document the diagnostic workflow in docs/foreground-fallback-diagnostic.md

docs/foreground-fallback-diagnostic.md

@@ -9,73 +9,187 @@ and switches to the next model in the agent's configured fallback chain.
 ## Problem
 
 The OpenCode proxy returns **"Monthly usage limit reached"** for all models going through
-it. The fallback should catch this and switch models, but on a fresh session it doesn't
-trigger.
+it. The fallback should cascade through the chain until it finds a working model, but on a
+fresh session it stops after one switch.
 
-Two hypotheses:
-- **A:** The proxy-level monthly limit error never produces a plugin event (OpenCode
-  handles it before session creation — the plugin never sees it)
-- **B:** The event arrives but in a shape the handler doesn't match
+## History
 
-Also: **subagent sessions** (explorer, librarian, fixer) show zero
-`[foreground-fallback]` log entries — their errors don't reach the handler either.
+### Round 1: RC1 — Status type guard (Fixed)
 
-## What was done
+**Hypothesis:** The `session.status` handler required `type === 'retry'` to process events.
+When the proxy returned monthly limit on a fresh session with no prior retry, the type might
+be `'error'` instead, silently dropping the event.
 
-Branch: `fix/foreground-fallback-diagnostic`
+**Fix applied:** Removed `props.status?.type !== 'retry'` guard. The keyword matching on
+`status.message` is specific enough.
 
-Minimal diagnostic logging added. No behavioral changes.
+**Result:** The fix deployed. Events ARE detected. `tryFallback` IS called. But the cascade
+still stops after one switch.
 
-### Changes (1 file, +61 lines)
+### Round 2: RC2 — Dedup window blocking cascade (Current)
 
-1. **`extractErrorPreview()`** — extracts an error string from any event shape:
-   - `session.error` → `properties.error`
-   - `message.updated` → `properties.info.error`
-   - `session.status` → `properties.status.message`
+**Evidence from log `oh-my-opencode-slim.20260703T185433.log`:**
 
-2. **`handleEvent()` diagnostic** — logs EVERY event reaching the handler BEFORE the
-   switch statement with `{ type, sessionID, error }`. This is the key: it captures
-   events that fall through unhandled.
+Two errors arrive within 876ms for the same session. The first triggers a fallback
+(opencode/mimo-v2.5-free → opencode-go/mimo-v2.5). The second is silently deduped
+because `Date.now() - lastTrigger = 876ms < 5000ms`.
 
-3. **`tryFallback()` diagnostic** — logs entry with `{ sessionID, inProgress, dedupMs }`
-   BEFORE any early-return guards, so we can tell if fallback is entered vs filtered.
+```
+18:54:40.637  session.status (busy — first prompt starts)
+18:54:40.890  session.status with error: "Free usage exceeded, subscribe to Go"
+18:54:40.891  tryFallback { dedupMs: 1783104880891 }  ← first call, lastTrigger was 0
+18:54:40.918  session.idle
+18:54:41.434  switched to fallback model: opencode/mimo-v2.5-free → opencode-go/mimo-v2.5
+18:54:41.442  message.updated (new model starts responding)
+18:54:41.446  session.status (busy)
+18:54:41.505  session.status (busy)
+18:54:41.767  session.status with error: "monthly usage limit reached..."
+18:54:41.767  tryFallback { dedupMs: 876 }  ← SECOND call, 876ms < 5000ms → **DEDUPED**
+18:54:55.375  session.updated (13 seconds later — no second switch happened)
+```
 
-### Also included (pre-existing source fixes now in build)
+**Root cause:** The `lastTrigger` timestamp is set when tryFallback first runs
+(18:54:40.891). After the fallback switches models and the new model also fails
+(18:54:41.767), the dedup guard sees `876ms < 5000ms` and returns early. The
+second fallback is silently swallowed — the chain has remaining models but they're
+never tried.
 
-The stale dist was missing these source changes — the fresh build includes them:
+**Why the dedup exists:** Prevents duplicate events for the same rate-limit incident
+(e.g. three `session.status` events all firing for the same proxy error). This is
+correct behavior.
 
-- **Chain reset/recovery branch:** When all models in the chain have been tried, resets
-  the tried set and retries the last model instead of giving up permanently
-- **Monthly/5-hour/weekly usage limit patterns:** Added to `isRateLimitError()` for
-  broader detection
-- **`isUserMessageWithParts()` guard:** Prevents crash when messages have undefined
-  `info` (OpenCode sometimes returns partial/streaming messages)
-- **Subagent `currentModel` inference:** Infers current model as `chain[0]` when agent
-  name is known but no model was captured yet
+**Why it breaks the cascade:** After a successful model switch, the new model's
+failure is a *separate incident*. The dedup timer should be reset so the next
+cascade step can proceed. Currently the timer persists from the original incident.
 
-## How to test
+## Fix applied (RC2)
+
+**File:** `src/hooks/foreground-fallback/index.ts`
+
+**Change:** Make dedup model-aware. Added `lastTriggerModel` map that records which model
+was in use when the dedup timer was set. The dedup is bypassed when the model has changed
+since the last trigger — the new model's failure is a separate incident.
+
+```typescript
+// Before fix: per-session dedup, blocks all triggers within 5s
+if (now - this.lastTrigger.get(sessionID) < DEDUP_WINDOW_MS) return;
+
+// After fix: dedup is model-aware, allows cascade on model change
+const lastModel = this.lastTriggerModel.get(sessionID);
+const curModel = this.sessionModel.get(sessionID);
+const modelChanged = lastModel !== undefined && lastModel !== curModel;
+if (!modelChanged && now - this.lastTrigger.get(sessionID) < DEDUP_WINDOW_MS) return;
+this.lastTrigger.set(sessionID, now);
+this.lastTriggerModel.set(sessionID, curModel);
+```
+
+This way:
+1. Model A fails `[lastModel: undefined, curModel: A]` → `modelChanged = false` → dedup normal → switches to B
+2. Model B fails `[lastModel: A, curModel: B]` → `modelChanged = true` → bypass dedup → switches to C
+3. Cascade continues through chain
+
+Duplicate events for the SAME model are still deduped (same `lastModel` and `curModel`).
+
+## Log evidence summary
+
+### Session `ses_0d6aac3d3ffe17U1EIUYi3kIm2` cascade (185433.log)
+
+| Time | Event | Notes |
+|------|-------|-------|
+| 18:54:40.637 | session.status (busy) | First prompt |
+| 18:54:40.890 | session.status (error: Free usage exceeded) | Model A fails |
+| 18:54:40.891 | tryFallback (dedupMs: 1.7B) | First call — proceeds |
+| 18:54:41.434 | switched: mimo-v2.5-free → opencode-go/mimo-v2.5 | Model B selected |
+| 18:54:41.767 | session.status (error: monthly usage limit) | Model B also fails |
+| 18:54:41.767 | tryFallback (dedupMs: 876) | **DEDUPED** — 876 < 5000 |
+| — | *no second switch* | Cascade dead — chain had remaining models |
+
+### Session cascade that worked (182121.log)
+
+```
+switched to fallback model: opencode/mimo-v2.5-free → opencode-go/mimo-v2.5
+switched to fallback model: opencode-go/glm-5.2     → nvidia/minimaxai/minimax-m3
+fallback chain exhausted: tried 4 models
+```
 
-1. Check out the branch
-2. Build: `bun run build`
-3. Deploy locally (point `opencode.jsonc` plugin to local path)
-4. Restart OpenCode
-5. Trigger the monthly usage limit
-6. Check the plugin log
+This worked because errors arrived **minutes apart**, not milliseconds.
 
-## Reading the logs
+## What the RC1 fix actually fixed
+
+Removing the `type !== 'retry'` guard was still correct. It allows `session.status`
+events with type `'error'` (or any other non-standard type) to be processed. Without
+this fix, even the first cascade step wouldn't work on a fresh session.
+
+But it wasn't sufficient — the cascade still blocked on step 2.
+
+## Reading the logs (updated)
 
 Plugin log location: `~/.local/share/opencode/log/oh-my-opencode-slim.*.log`
 
 | Log pattern | What it means |
 |---|---|
-| `[foreground-fallback] event { type: "...", sessionID: "...", error: "..." }` | Event arrived at the handler. Shows event type, session ID, and any error message. |
-| `[foreground-fallback] tryFallback { sessionID: "...", inProgress: false, ... }` | Fallback procedure was entered (rate-limit signal was recognized). |
-| `[foreground-fallback] resetting tried set for re-fallback` | Chain was exhausted, resetting to try last model again (recovery kicking in). |
-| `[foreground-fallback] switched to fallback model { from: "...", to: "..." }` | Fallback worked — model was switched. |
-| No `event` log at all when monthly limit fires | **Hypothesis A confirmed** — plugin never sees the error |
-| `event` log appears but NO `tryFallback` | Event hits a handler gap (e.g., wrong status type, missing sessionID). The event log shows which type — may need to add a new case. |
-| `event` + `tryFallback` but no `switched` | Some downstream failure — subsequent logs will say why (no user message, promptAsync unavailable, invalid model, etc.) |
+| `event { type: "...", sessionID: "...", error: "..." }` | Event arrived at the handler |
+| `tryFallback { dedupMs: <N> }` | Fallback was entered. N = ms since last trigger. |
+| `tryFallback { dedupMs: < 5000 }` | **Dedup blocked** — second incident within the window |
+| `switched to fallback model { from: "..." to: "..." }` | Model successfully switched |
+| `event + tryFallback + dedupMs < 5000 + no switched` | **RC2 pattern** — cascade blocked by dedup |
+| NO `event` log when monthly limit fires | **RC1 pattern** (fixed) — event never reaches handler |
+
+## What we did this round
+
+1. **Investigated log `oh-my-opencode-slim.20260703T185433.log`** — traced a real monthly
+   limit cascade: the RC1 fix WAS detecting the event and calling tryFallback, but the
+   second model switch was blocked by the 5-second dedup window (876ms < 5000ms).
+2. **Identified RC2:** The dedup timer (`lastTrigger`) was per-session only. After model A
+   failed and the fallback switched to model B, model B's failure within 5 seconds was
+   incorrectly deduped because the timer still reflected model A's incident.
+3. **Applied RC2 fix:** Made dedup model-aware. Added `lastTriggerModel` map. Dedup is
+   bypassed when `lastModel !== curModel` — the new model's failure is a separate incident.
+4. **Wrote failing test first,** then implemented fix. 37/37 pass.
+5. **Built and verified:** `bun run build && bun run check:ci && bun test` (1302/1302 pass).
+
+## Status
+
+- **RC1 fix:** Deployed. Removed `type !== 'retry'` guard from `session.status` handler.
+- **RC2 fix:** Deployed. Model-aware dedup (`lastTriggerModel`). Tested — 37/37 pass.
+- **Build:** `bun run build && bun run check:ci && bun test` — clean.
+- **Dist deployed:** `dist/index.js` rebuilt at `2026-07-03 19:57` local time.
+
+## How to test
+
+Reload the plugin in OpenCode (hot-reload or restart), then use a model that goes
+through the OpenCode proxy. When the proxy returns monthly/5-hour/weekly usage limit:
+
+### Expected log pattern (verification: confirm all 3 appear per model that fails)
+
+```
+[foreground-fallback] event {"type":"session.status","sessionID":"ses_xxx",
+  "error":"monthly usage limit reached..."}
+[foreground-fallback] tryFallback {"sessionID":"ses_xxx","inProgress":false,
+  "dedupMs":<large or <5000>}
+[foreground-fallback] switched to fallback model {"from":"opencode/model-a",
+  "to":"opencode/model-b"}
+```
+
+If the cascade works across N models, you should see N copies of the above pattern,
+each with a different `to` model, until the chain is exhausted or a model succeeds.
+
+### What to check
+
+| Pattern | Verdict |
+|---------|---------|
+| `event` + `tryFallback` + `switched` (repeated per model) | ✅ Cascade working |
+| `event` + `tryFallback` with `dedupMs < 5000` + NO `switched` | ❌ RC2 still broken — check `lastTriggerModel` logic |
+| NO `event` log at all when monthly limit fires | ❌ RC1 regression — check `session.status` handler |
+| Everything fires but all models fail | ⚠️ All models behind same proxy — can't code-fix, need config change |
+
+### Key log lines to grep
 
-## Next steps
+```bash
+# See each cascade step
+rg "foreground-fallback.*(switched to fallback model|tryFallback)" \
+  ~/.local/share/opencode/log/oh-my-opencode-slim.*.log
 
-Paste the relevant log lines back and we'll identify the exact breakdown point.
+# Check for blocked cascade (dedup < 5s with no follow-up switch)
+rg "dedupMs.*[0-9]{1,3}\}" \
+  ~/.local/share/opencode/log/oh-my-opencode-slim.*.log

src/hooks/foreground-fallback/index.test.ts

@@ -573,6 +573,64 @@ describe('ForegroundFallbackManager deduplication', () => {
 
     expect(mocks.promptAsync).toHaveBeenCalledTimes(2);
   });
+
+  test('cascade continues when second error arrives within dedup window after model switch', async () => {
+    const { client, mocks } = createMockClient();
+    const mgr = new ForegroundFallbackManager(client, makeChains(), true);
+
+    // Seed session: current model is first entry in orchestrator chain
+    await mgr.handleEvent({
+      type: 'message.updated',
+      properties: {
+        info: {
+          sessionID: 'sess-cascade',
+          providerID: 'anthropic',
+          modelID: 'claude-opus-4-5',
+        },
+      },
+    });
+
+    // First error — model A fails, falls back to model B (openai/gpt-4o)
+    await mgr.handleEvent({
+      type: 'session.error',
+      properties: {
+        sessionID: 'sess-cascade',
+        error: { message: 'Rate limit exceeded' },
+      },
+    });
+
+    expect(mocks.promptAsync).toHaveBeenCalledTimes(1);
+    const call1 = mocks.promptAsync.mock.calls[0] as [
+      {
+        body: { model: { providerID: string; modelID: string } };
+      },
+    ];
+    expect(call1[0].body.model.providerID).toBe('openai');
+    expect(call1[0].body.model.modelID).toBe('gpt-4o');
+
+    // Second error — model B also fails within the 5s dedup window.
+    // This is a DIFFERENT incident (new model), so it should NOT be deduped
+    // after the successful model switch cleared the lastTrigger timer.
+    await mgr.handleEvent({
+      type: 'session.error',
+      properties: {
+        sessionID: 'sess-cascade',
+        error: { message: 'Monthly usage limit reached' },
+      },
+    });
+
+    // Should trigger a second fallback despite being within the original
+    // 5-second dedup window, because the lastTrigger was reset after the
+    // successful model switch.
+    expect(mocks.promptAsync).toHaveBeenCalledTimes(2);
+    const call2 = mocks.promptAsync.mock.calls[1] as [
+      {
+        body: { model: { providerID: string; modelID: string } };
+      },
+    ];
+    expect(call2[0].body.model.providerID).toBe('google');
+    expect(call2[0].body.model.modelID).toBe('gemini-2.5-pro');
+  });
 });
 
 // ---------------------------------------------------------------------------

src/hooks/foreground-fallback/index.ts

@@ -135,6 +135,10 @@ export class ForegroundFallbackManager {
   private readonly inProgress = new Set<string>();
   /** sessionID → timestamp of last trigger (for deduplication) */
   private readonly lastTrigger = new Map<string, number>();
+  /** sessionID → model in use when lastTrigger was set; dedup is bypassed
+   *  when the model has changed, allowing the cascade to continue when a
+   *  new fallback model also fails within the dedup window. */
+  private readonly lastTriggerModel = new Map<string, string | undefined>();
 
   constructor(
     private readonly client: OpencodeClient,
@@ -218,8 +222,12 @@ export class ForegroundFallbackManager {
               status?: { type?: string; message?: string };
             }
           | undefined;
-        if (!props?.sessionID || props.status?.type !== 'retry') break;
-        const msg = props.status.message?.toLowerCase() ?? '';
+        if (!props?.sessionID || !props.status?.message) break;
+        const msg = props.status.message.toLowerCase();
+        // Check for rate-limit signals in the status message regardless of
+        // status type. OpenCode proxies may emit monthly/weekly/5-hour usage
+        // limit errors with type 'error' instead of 'retry' on fresh sessions
+        // where no retry is attempted — the retry-type guard would miss them.
         if (
           msg.includes('rate limit') ||
           msg.includes('usage limit') ||
@@ -264,6 +272,7 @@ export class ForegroundFallbackManager {
           this.sessionTried.delete(id);
           this.inProgress.delete(id);
           this.lastTrigger.delete(id);
+          this.lastTriggerModel.delete(id);
         }
         break;
       }
@@ -284,9 +293,19 @@ export class ForegroundFallbackManager {
     if (this.inProgress.has(sessionID)) return;
 
     // Deduplicate: multiple events can fire for a single rate-limit event.
+    // Bypass dedup when the model changed since the last trigger — the new
+    // model's failure is a separate incident and the cascade should continue.
     const now = Date.now();
-    if (now - (this.lastTrigger.get(sessionID) ?? 0) < DEDUP_WINDOW_MS) return;
+    const lastModel = this.lastTriggerModel.get(sessionID);
+    const curModel = this.sessionModel.get(sessionID);
+    const modelChanged = lastModel !== undefined && lastModel !== curModel;
+    if (
+      !modelChanged &&
+      now - (this.lastTrigger.get(sessionID) ?? 0) < DEDUP_WINDOW_MS
+    )
+      return;
     this.lastTrigger.set(sessionID, now);
+    this.lastTriggerModel.set(sessionID, curModel);
 
     this.inProgress.add(sessionID);
     try {