From 0540dc68e29fd8d24fb61e006fc4e60e0e1be3b8 Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Tue, 27 Oct 2026 17:56:07 -0400 Subject: [PATCH 1/8] CLUE-731: design and implementation plan for AI chat timeouts Spec and plan for giving every AI surface a client-side deadline: a 45s reply deadline in the chat, a 45s "taking longer than usual" line ahead of Ideas' existing 120s expiry, and a visible failure message in the AI tile. Also records that the ticket's own analysis is out of date -- the client already ignores a stale parent `generating` status, so the real wedge is a user message that never gets an assistant document written at all. Co-Authored-By: Claude Opus 5 (1M context) --- .../2026-10-27-clue-731-ai-chat-timeout.md | 565 ++++++++++++++++++ ...6-10-27-clue-731-ai-chat-timeout-design.md | 202 +++++++ 2 files changed, 767 insertions(+) create mode 100644 docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md create mode 100644 docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md diff --git a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md new file mode 100644 index 0000000000..cb34ea4b6d --- /dev/null +++ b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md @@ -0,0 +1,565 @@ +# CLUE-731: AI Chats Should Time Out — Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever. The chat gets a 45s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, and the AI tile reports a failed request instead of silently restoring its old text. + +**Architecture:** The chat deadline lives in `useChat`, the single place `pending` is derived, so it covers both transports without touching `FirestoreTransport.emitStatus`'s status precedence. The Ideas interim line is a second timer inside `queueRemoteComment`, clearing through the existing `wrappedDispose` so `removePendingComments` stays the only path an entry leaves the queue by. Separately, `FirestoreTransport` stops recording the last-sent workspace hash in completion order. + +**Tech Stack:** TypeScript, React 18, MobX / MobX State Tree, Jest + @testing-library/react with fake timers. + +**Spec:** `docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md` + +--- + +## File Structure + +| File | Responsibility | +|---|---| +| `src/components/chat-tutor/use-chat.ts` *(modify)* | The 45s reply deadline, `timedOut` in the result, the timeout message constant | +| `src/components/chat-tutor/use-chat.test.ts` *(create)* | Deadline fires, restarts per message, clears on a late reply and on transport swap | +| `src/components/chat-tutor/chat.tsx` *(modify)* | Render the timeout row; keep the live region from re-announcing the previous reply | +| `src/components/chat-tutor/chat-timeout.test.tsx` *(create)* | `Chat` renders the timeout row and no typing dots | +| `src/components/chat-tutor/chat-highlights.test.tsx` *(modify)* | Its `chatResult` helper gains `timedOut` | +| `src/components/chat-tutor/firestore-transport.ts` *(modify)* | Record `lastSentRightHash` in send order, with rollback on a failed write | +| `src/components/chat-tutor/firestore-transport.test.ts` *(modify)* | Send-order tests plus the in-flight-edit regression guard | +| `src/models/document/ai-evaluation-messages.ts` *(modify)* | `IDEAS_SLOW_MESSAGE`, `AI_TILE_REQUEST_FAILED_MESSAGE` | +| `src/models/document/document-comments-manager.ts` *(modify)* | `kSlowRemoteCommentMs`, the slow-entry timer and id set | +| `src/models/document/document-comments-manager.test.ts` *(modify)* | Slow set set/cleared on resolve, expiry and dispose | +| `src/models/document/base-document-content.ts` *(modify)* | `isRemoteCommentSlow` view | +| `src/components/chat/waiting-message.tsx` *(modify)* | Pick the interim message when the entry is slow | +| `src/components/chat/waiting-message.test.tsx` *(modify)* | Interim message rendering | +| `src/plugins/ai/ai-tile.tsx` *(modify)* | Write the failure message on a real failure | +| `src/plugins/ai/ai-tile.test.tsx` *(modify)* | Failure writes the message; a superseded run restores | + +No Cypress spec, so no `.github/workflows/manual-regression.yml` change. No functions, rules or index changes, so **no Deploy timing callout** on the PR. No authorable config, so no `docs/unit-configuration.md` update. + +--- + +## Task 1: The chat reply deadline + +**Files:** +- Modify: `src/components/chat-tutor/use-chat.ts` +- Test: `src/components/chat-tutor/use-chat.test.ts` *(create)* + +- [ ] **Step 1: Write the failing tests** + +Create `src/components/chat-tutor/use-chat.test.ts`. Drive it with a controllable stub transport +whose `subscribe` captures the emitters so the test can push turns and status at will: + +```ts +import { act, renderHook } from "@testing-library/react"; +import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; +import { kReplyDeadlineMs, useChat } from "./use-chat"; + +function stubTransport() { + let emitTurns: (turns: ChatTurn[]) => void = () => undefined; + let emitStatus: (status: ChatStatus) => void = () => undefined; + const transport: ChatTransport = { + subscribe(onTurns, onStatus) { + emitTurns = onTurns; + emitStatus = onStatus; + onTurns([]); + onStatus("idle"); + return () => undefined; + }, + sendUserMessage: jest.fn(async () => undefined), + }; + return { + transport, + turns: (t: ChatTurn[]) => act(() => emitTurns(t)), + status: (s: ChatStatus) => act(() => emitStatus(s)), + }; +} + +const userTurn = (id: string): ChatTurn => ({ id, sender: "user", text: "help" }); +``` + +Cases to assert: + +1. **No timeout while idle** — advance past `kReplyDeadlineMs` with `status: "idle"`; + `timedOut` stays false. +2. **Fires at the deadline** — emit a user turn and `status: "generating"`, advance + `kReplyDeadlineMs`; `pending` is false and `timedOut` is true. Also assert `pending` was still + true one millisecond earlier, so the test pins the boundary rather than just "eventually." +3. **Restarts on a new message** — go pending, advance 40s, emit a second user turn, advance 40s; + `timedOut` is still false (total elapsed 80s, but only 40s since the newest message). This is + the case a `waiting`-only dependency list gets wrong. +4. **A late reply clears it** — let it time out, then emit an assistant turn and `status: "idle"`; + `timedOut` returns to false and the turn is in `turns`. +5. **Transport swap resets** — rerender the hook with a second transport while timed out; + `timedOut` is false and no timer from the old transport can fire afterwards. + +Use `jest.useFakeTimers()` in `beforeEach` and `jest.useRealTimers()` in `afterEach`, matching +`document-comments-manager.test.ts`'s `expiry` block. + +- [ ] **Step 2: Implement** + +In `use-chat.ts`, add the constants near the existing message string: + +```ts +// How long the client waits for a reply before it stops claiming Ada is working. Nothing on the +// client can tell a dead turn from a slow one — the drain writes its assistant document and its +// cursor in one batch, so a drain that died writes neither — which is why this is a deadline and +// not a smarter reading of status. A reply carrying document context routinely takes 10-25s. +export const kReplyDeadlineMs = 45_000; + +// Deliberately distinct from the status:"error" message below: the backend reporting an error and +// the backend reporting nothing are different failures, and support cannot tell them apart if +// they read the same. +export const kTimeoutMessage = "Ada didn't answer. Please try again."; +``` + +Add `timedOut: boolean` to `UseChatResult`, then: + +```ts +const [timedOut, setTimedOut] = useState(false); + +const waiting = status === "generating"; +const newestTurnId = turns.length ? turns[turns.length - 1].id : undefined; + +// Keyed on the newest turn as well as `waiting`: a second message sent mid-wait must start its own +// clock, not inherit the first one's and be cut off seconds after the student sent it. The id is +// minted client-side by messagesRef().add(), so the optimistic turn and its confirmation share one +// id and this changes exactly once per message. +useEffect(() => { + setTimedOut(false); + if (!waiting) return; + const timer = setTimeout(() => setTimedOut(true), kReplyDeadlineMs); + return () => clearTimeout(timer); +}, [waiting, newestTurnId]); + +const pending = waiting && !timedOut; +``` + +Return `timedOut` from the hook. The existing re-subscribe effect already resets status and turns, +which drives this effect through both of its dependencies, so a transport swap needs no extra +reset here. + +Do **not** fold the timeout into `error`. `error` is also set by send failures; one field carrying +three unrelated causes makes both the component and its tests guess which one it is holding. + +- [ ] **Step 3: Verify** + +```bash +npm test -- src/components/chat-tutor/use-chat.test.ts +``` + +--- + +## Task 2: Render the timeout in the chat + +**Files:** +- Modify: `src/components/chat-tutor/chat.tsx` +- Test: `src/components/chat-tutor/chat-timeout.test.tsx` *(create)* +- Modify: `src/components/chat-tutor/chat-highlights.test.tsx` + +- [ ] **Step 1: Find every `UseChatResult` literal** + +```bash +grep -rn "UseChatResult" --include="*.ts" --include="*.tsx" src +``` + +Adding `timedOut` makes every object literal typed as `UseChatResult` fail to compile until it is +added. `chat-highlights.test.tsx`'s `chatResult` helper is the known one; confirm there are no +others before editing. + +- [ ] **Step 2: Write the failing test** + +Create `src/components/chat-tutor/chat-timeout.test.tsx`, following `chat-highlights.test.tsx`'s +pattern of rendering `` against a hand-built `UseChatResult` (no timers needed — the hook's +timing is Task 1's subject; this file is about what the component draws): + +```ts +const chatResult = (over: Partial = {}): UseChatResult => ({ + turns: [], status: "idle", error: null, pending: false, timedOut: false, + sendMessage: jest.fn(async () => undefined), header: "Doc · 1.1", ...over +}); +``` + +Assert: + +1. `timedOut: true` renders `chat-error` containing `kTimeoutMessage`. +2. `timedOut: true` renders **no** `chat-row-typing` — the dots are the thing the ticket is about. +3. `error` wins over `timedOut` when both are set, so a real send failure is never masked by the + deadline that follows it. +4. **`timedOut: true` leaves `chat-live` empty** even with a previous assistant turn in `turns`. + This is the regression the change would otherwise introduce — see Step 3. +5. Neither set renders no `chat-error`. + +- [ ] **Step 3: Implement** + +Destructure `timedOut` from `chat`, import `kTimeoutMessage` from `./use-chat`, and replace the +error row: + +```tsx +{(error || timedOut) && +
{error ?? kTimeoutMessage}
} +``` + +`role="alert"` already announces it, so the timeout needs no live region of its own. Reuses the +existing `.chat-error` rule — no SCSS change. + +**Then fix the live region.** It currently reads: + +```tsx +{!pending && lastAssistantText ? `Ada said: ${lastAssistantText}` : ""} +``` + +`pending` going false is what tells it a reply completed. The deadline also flips `pending` false, +so without a guard a timeout would announce the *previous* reply as if it had just arrived — +telling a screen-reader user that Ada answered at the exact moment Ada failed to. Guard it: + +```tsx +{!pending && !timedOut && lastAssistantText ? `Ada said: ${lastAssistantText}` : ""} +``` + +The typing indicator needs no change: it reads `pending`, which already excludes the timeout. + +- [ ] **Step 4: Add `timedOut: false` to `chat-highlights.test.tsx`'s `chatResult` helper** + +- [ ] **Step 5: Verify** + +```bash +npm test -- src/components/chat-tutor +npm run check:types +``` + +--- + +## Task 3: Record the workspace hash in send order + +**Files:** +- Modify: `src/components/chat-tutor/firestore-transport.ts` +- Test: `src/components/chat-tutor/firestore-transport.test.ts` + +- [ ] **Step 1: Write the failing tests** + +`fakeFirestore()` in the existing test file resolves `add` immediately, which cannot express +overlap. Add a deferred variant beside it: + +```ts +function deferredFirestore() { + const added: Record[] = []; + const resolvers: Array<(v?: unknown) => void> = []; + const rejecters: Array<(e: unknown) => void> = []; + const messages = { + add: (doc: Record) => { + added.push(doc); + return new Promise((resolve, reject) => { resolvers.push(resolve); rejecters.push(reject); }); + } + }; + const firestore = { collection: () => ({ doc: () => ({ collection: () => messages }) }) }; + return { added, resolvers, rejecters, firestore: firestore as any }; +} +``` + +Build the transport with a mutable summary source so the test controls the hash: + +```ts +let summary = { markdown: "W1", hash: "H1" }; +// ... getRightSummary: () => summary +``` + +Cases: + +1. **Overlapping sends record in send order.** Send A (hash `H1`), change `summary` to `H2`, send + B, resolve B's write then A's. A third send with the document still at `H2` must **not** + re-attach the workspace. Before the fix it does, because A's late resolution overwrote the + recorded hash with `H1`. +2. **A failed write rolls back.** Send A with `H1`, reject it, catch the rejection, send again + with the document still at `H1`: the workspace must be attached, because it never reached the + server. +3. **A superseded failed write does not roll back.** Send A (`H1`), change to `H2`, send B, + resolve B, then reject A. A third send at `H2` must not re-attach — A's rollback must not undo + B's successful delivery. +4. **An unchanged send that fails does not clear the record.** With `attachRight` false (document + unchanged since the last successful send), reject the write and confirm `lastSentRightHash` + still reflects the earlier delivery. This is the case the rollback guard has to get right: the + hashes match precisely *because* nothing was attached, so a match alone is not evidence this + send claimed the slot. + +- [ ] **Step 2: Implement** + +Replace the tail of `sendUserMessage`: + +```ts +// Recorded before the write, not after. Two overlapping sends would otherwise record in +// completion order, leaving the client believing an older workspace was the last one sent and +// re-attaching one the server already has — up to kMaxAttachedWorkspace of document JSON on the +// ForeverLearning path. The composer stays open during a pending reply so a student can escape a +// wedged turn, so overlapping sends are expected, not exotic. +const claimedRight = decision.attachRight && right ? right : undefined; +const previousRightHash = this.lastSentRightHash; +if (claimedRight) { + this.lastSentRightHash = claimedRight.hash; +} + +try { + await this.messagesRef().add(message); +} catch (e) { + // The workspace never left the client, so the record has to go back — but only if this send is + // still the one holding it. `claimedRight` is what distinguishes this from an unchanged send, + // whose hash matches precisely because it attached nothing. + if (claimedRight && this.lastSentRightHash === claimedRight.hash) { + this.lastSentRightHash = previousRightHash; + } + throw e; +} +``` + +Delete the old post-await `if (decision.attachRight && right) { this.lastSentRightHash = right.hash; }`. + +- [ ] **Step 3: Verify** + +```bash +npm test -- src/components/chat-tutor/firestore-transport.test.ts +``` + +--- + +## Task 4: Pin the in-flight-edit guarantee + +**Files:** +- Test: `src/components/chat-tutor/firestore-transport.test.ts` + +- [ ] **Step 1: Write the regression test** + +An edit made while Ada is thinking already cannot reach that turn — `sendUserMessage` computes its +workspace payload before its write. Nothing is being changed here; the test exists so the +guarantee is not quietly lost later. + +Using `deferredFirestore()` from Task 3: send a message with the summary at `H1`, mutate the +summary source to `H2` **before** resolving the write, then resolve it. Assert the captured +document still carries `W1`, and that no second document was written. Name it so the intent +survives: something like `"a document edit during an in-flight send does not change what that +message carried"`. + +- [ ] **Step 2: Verify** + +```bash +npm test -- src/components/chat-tutor/firestore-transport.test.ts +``` + +--- + +## Task 5: The Ideas interim message + +**Files:** +- Modify: `src/models/document/ai-evaluation-messages.ts` +- Modify: `src/models/document/document-comments-manager.ts` +- Modify: `src/models/document/base-document-content.ts` +- Modify: `src/components/chat/waiting-message.tsx` +- Tests: `src/models/document/document-comments-manager.test.ts`, `src/components/chat/waiting-message.test.tsx` + +- [ ] **Step 1: Write the failing manager tests** + +Add to the existing `expiry` describe (or a sibling `slow` describe) in +`document-comments-manager.test.ts`, following its `jest.useFakeTimers()` / +`advanceTimersByTimeAsync` style: + +1. Not slow before 45s; slow at 45s. +2. An entry resolved by its comment before 45s never becomes slow, and its timer does not fire + afterwards. +3. An entry that becomes slow and then resolves is no longer slow. +4. The 120s expiry still fires and still shows `IDEAS_REQUEST_FAILED_MESSAGE` — the new timer must + not disturb it. +5. `dispose()` while slow leaves nothing behind (no slow ids, no pending entries). + +- [ ] **Step 2: Implement the manager change** + +In `ai-evaluation-messages.ts`: + +```ts +export const IDEAS_SLOW_MESSAGE = "Ada is taking longer than usual..."; +``` + +In `document-comments-manager.ts`, beside `kRemoteCommentExpiryMs`: + +```ts +// When a pending request stops looking normal and starts looking stuck. Well short of the expiry +// below, which is pinned to the evaluation function's own 120s budget and so cannot be lowered +// without reporting failure on evaluations that are merely slow. +const kSlowRemoteCommentMs = 45_000; +``` + +Track slowness as a set of pending-entry ids on the manager: + +```ts +/** Pending remote entries that have passed kSlowRemoteCommentMs. A set rather than a flag: a flag + * would only be correct while canRequestIdeas allows one remote entry at a time, and would desync + * silently the day that gate changes. */ +slowRemoteCommentIds = new Set(); + +get hasSlowRemoteComment() { + return this.slowRemoteCommentIds.size > 0; +} +``` + +In `queueRemoteComment`, add a second timer and fold it into `wrappedDispose` so teardown stays in +one place: + +```ts +const slowTimer = setTimeout(() => { + runInAction(() => { this.slowRemoteCommentIds = new Set(this.slowRemoteCommentIds).add(id); }); +}, kSlowRemoteCommentMs); + +const wrappedDispose = () => { + clearTimeout(timer); + clearTimeout(slowTimer); + dispose?.(); +}; +``` + +Replace the set rather than mutating it in place — `makeAutoObservable` does not make a plain +`Set`'s contents observable, so a mutation would not re-render the waiting message. + +Clear the id in `removePendingComments` (the single exit path) and in `dispose()`. + +- [ ] **Step 3: Expose it on the content model** + +In `base-document-content.ts`, beside `isAwaitingRemoteComment`: + +```ts +// True once a pending remote comment has been waiting long enough to look stuck rather than slow. +get isRemoteCommentSlow() { + const doc = getParentWithTypeName(self, "Document"); + return !!doc?.commentsManager?.hasSlowRemoteComment; +} +``` + +- [ ] **Step 4: Use it in the waiting message** + +In `waiting-message.tsx`, add the slow text beside `waitingMessageText` and pick between them: + +```tsx +{content?.isAwaitingRemoteComment && + } +``` + +The existing `role="status"` / `aria-live="polite"` region re-announces on the swap, which is the +point: the student is told the wait has become unusual. + +- [ ] **Step 5: Test the rendering** + +In `waiting-message.test.tsx`, following its existing `{ ... } as any` content stubs: assert the +thinking message when `isRemoteCommentSlow` is false, and `IDEAS_SLOW_MESSAGE` when it is true. + +- [ ] **Step 6: Verify** + +```bash +npm test -- src/models/document/document-comments-manager.test.ts src/components/chat/waiting-message.test.tsx +``` + +--- + +## Task 6: The AI tile failure message + +**Files:** +- Modify: `src/models/document/ai-evaluation-messages.ts` +- Modify: `src/plugins/ai/ai-tile.tsx` +- Test: `src/plugins/ai/ai-tile.test.tsx` + +- [ ] **Step 1: Read the existing test file first** + +`ai-tile.test.tsx` already mounts the tile with a mocked `getAiContent_v2`. Read how it stubs +`useFirebaseFunction` and the stores before writing anything — reuse that harness rather than +building a second one. + +- [ ] **Step 2: Write the failing tests** + +1. A rejected request writes `AI_TILE_REQUEST_FAILED_MESSAGE` into the tile. +2. A resolved response carrying `data.error` does the same — the function reports server-side + failure by resolving with a truthy `error`, not by rejecting, and both already route through + this catch. +3. A **superseded** run still restores the previous text rather than reporting a failure. A newer + refresh taking over is not a failure and must not look like one. This is the case the change + can most easily break. + +- [ ] **Step 3: Implement** + +In `ai-evaluation-messages.ts`: + +```ts +export const AI_TILE_REQUEST_FAILED_MESSAGE = "Something went wrong getting tips. Please try again"; +``` + +In the tile's catch, report instead of silently restoring: + +```ts +} catch (error) { + // Restoring the old text looks to the student exactly like a refresh that did nothing, so a + // current run says what happened. A superseded run is not a failure: the newer run's own + // restore at the top of the effect handles it, which is why this is gated on isCurrent(). + // Unlike the Ideas status message this is document content, so it persists and syncs — the + // same tradeoff AI_TILE_EMPTY_MESSAGE already makes above, and a later refresh overwrites it. + if (isCurrent() && isAlive(content)) { + content.setText(AI_TILE_REQUEST_FAILED_MESSAGE); + previousTextRef.current = undefined; + } + console.error("Failed to query AI", error); +} +``` + +`isAlive(content)` stays: writing to a destroyed node throws and would hide the error being +reported. The `previousTextRef.current !== undefined` condition goes — the message should appear +whether or not this run had already blanked the text. + +- [ ] **Step 4: Verify** + +```bash +npm test -- src/plugins/ai +``` + +--- + +## Task 7: Full verification + +- [ ] **Step 1: Types and lint** + +```bash +npm run check:types +npm run lint:build +``` + +`lint:build` rather than `lint` — it also flags unnecessarily disabled rules, and it is what has to +pass before committing. + +- [ ] **Step 2: Jest across everything touched** + +```bash +npm test -- src/components/chat-tutor src/components/chat src/models/document src/plugins/ai +``` + +Report the actual pass/fail counts. Do not claim completion from a partial run. + +- [ ] **Step 3: Hand-check in the browser** + +The deadline is the one behavior worth seeing. Restart `npm start` first and confirm a clean +compile — a long-lived dev server that has seen branch switches serves a stale bundle that looks +current (see CLAUDE.md). + +Open the chat and send a message with the network offline (DevTools → Network → Offline) or with +the chat trigger disabled, then watch: the dots stop at 45s and the message appears, the composer +still accepts a message, and sending again restarts the dots. + +- [ ] **Step 4: Run `/code-self-review` over the full diff** + +Four lenses: comment quality, pattern consistency, copy/paste, and structure that exists only for +tests. + +- [ ] **Step 5: Hold for the user before pushing** + +Commit locally. Do not push until the user has checked it on localhost or said to go ahead. + +--- + +## Risks + +| Risk | Handling | +|---|---| +| 45s cuts off a legitimately slow reply | The reply still renders when it arrives; the message row clears with it. Nothing is discarded. If real traffic shows 45s is too tight, the constant is one line — but do not make it authorable without evidence. | +| The live region announces a stale reply on timeout | Explicitly covered: Task 2 Step 3 guards it, Task 2 Step 2 case 4 tests it. | +| The slow-entry set desyncs from `pendingComments` | Both the 45s and 120s timers clear through `wrappedDispose`, and `removePendingComments` stays the single exit path. Task 5 Step 1 case 5 tests `dispose()` while slow. | +| The AI tile failure message persists in document content | Stated and accepted in the spec; follows `AI_TILE_EMPTY_MESSAGE`'s existing precedent. Revisit only if a student reports a stuck error in a saved document. | +| The hash rollback fires on a send that attached nothing | `claimedRight` distinguishes the two; Task 3 Step 1 case 4 is exactly this. | diff --git a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md new file mode 100644 index 0000000000..e971058ba7 --- /dev/null +++ b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md @@ -0,0 +1,202 @@ +# CLUE-731: AI Chats Should Time Out — Design + +**Jira:** CLUE-731 (epic CLUE-606, "Collaboration AI vs. Assist AI") + +## Goal + +No AI surface in CLUE may leave a student staring at a progress indicator forever. Every place +that shows "Ada is working" gets a client-side deadline after which the indicator stops and the +student is told what happened, so a request that died server-side is visible rather than silent. + +## Why + +A student cannot distinguish "the tutor is thinking" from "the tutor is never going to answer." +The chat's typing dots have no client-side deadline at all: if the drain function dies before +writing its assistant document, the dots run until the student reloads. The ticket's repro +(`?appMode=demo&demoName=CLUE&fakeClass=1&fakeUser=student:5&problem=0.1&unit=vibe`) is a +conversation wedged exactly this way. There is an escape — sending another message — but nothing +tells the student it exists. + +## Correcting the ticket's analysis + +The ticket says the stuck indicator is "the client reading status: `generating` on the parent," so +a stale parent flag wedges the spinner. **That is no longer true.** `FirestoreTransport.emitStatus` +already ignores a stale parent `generating`: + +```ts +const effective: ChatStatus = + this.parentStatus === "error" ? "error" + : this.awaitingReply ? "generating" : "idle"; +``` + +Only `awaitingReply` — newest `user` document newer than newest `assistant` document, computed +from the raw document stream — drives the dots. A stale parent flag on its own is already inert on +the client. + +What actually wedges the dots is the case underneath that observation: **a user message for which +no assistant document is ever written**, because the drain died before its batch commit. The +client cannot tell that apart from a slow reply by reading any state, which is precisely why the +fix is a deadline rather than better status reading. + +The server-side half (`STALE_LOCK_MS`, the 5-minute lock reclaim) is correct as written and is not +touched here. It governs whether a *later* trigger may re-enter a conversation; it has never +governed what this student sees now. + +## Scope + +**In** + +- A 45-second client-side reply deadline for the Ada chat sidebar, with a visible message. +- Send-order (not completion-order) bookkeeping of the last-sent workspace hash in + `FirestoreTransport`. +- A regression test pinning the existing guarantee that a document edit cannot reach an in-flight + chat turn. +- A 45-second "taking longer than usual" interim line for the Ideas / document-evaluation waiting + message, with the existing 120s hard expiry unchanged. +- A visible failure message in the AI tile when its request fails. + +**Out** + +- **Lowering the Ideas 120s expiry.** It is pinned to a real server budget — the evaluation + function sets `functionTimeoutSeconds = 120` and allows Shutterbug 45s inside it + (`functions-v2/src/on-analysis-document-pending.ts`). A shorter client expiry reports failure on + healthy-but-slow evaluations, and the real comment then lands behind the failure message. +- **Any change to `STALE_LOCK_MS` or the drain.** See "Correcting the ticket's analysis." +- **A Retry button in the chat.** The composer is already enabled during a pending reply, so + retrying costs a retype, not a dead end. A real retry button has to decide what happens when the + first turn lands late, which is a bigger question than this story. +- **Making the chat timeout authorable per unit.** One constant until there is evidence 45s is + wrong for some unit. +- **The teacher-facing AI class summary** (`src/components/navigation/ai-summary.tsx`). It has its + own `checking`/`generating` status machine and no reported wedge. Separate story if it needs one. + +## Design + +### 1. Chat reply deadline + +**Where.** [`src/components/chat-tutor/use-chat.ts`](../../../src/components/chat-tutor/use-chat.ts) +— the single place `pending` is derived. Putting it here covers `FirestoreTransport` and +`DebugTransport` alike and leaves the transport's status logic untouched. + +**Why not in the transport.** The transport reports what the backend says. "How long a student +should be made to wait" is a UI judgment, and `emitStatus`'s three-way precedence is subtle enough +that threading a fourth state through it would cost more than it buys. + +**Restart condition.** The timer restarts when the hook starts waiting **and whenever the newest +turn changes** — not on `waiting` alone. A student who sends a second message at 40s would +otherwise inherit the first message's clock and be told "Ada didn't answer" five seconds later, +about a message sent moments ago. Keying on the newest turn's id works because the id comes from +`messagesRef().add()`, which mints it client-side; the optimistic snapshot and the confirmed one +carry the same id, so the id changes exactly once per message. + +**Value.** 45 seconds. A real reply carrying document context routinely takes 10–25s, so the +ticket's literal 20s would cut off healthy turns. 45s is unambiguously abnormal without being a +wait. + +**On expiry.** `pending` goes false — the dots stop and the "Ada is typing" live region clears. +A message row appears reading *"Ada didn't answer. Please try again."* The composer needs no +change; it is already enabled during a pending reply. + +**Wording.** Deliberately distinct from the existing `status:"error"` line ("Ada is currently +unavailable. Please try again."). Those are different failures — one is the backend reporting an +error, one is the backend reporting nothing — and support cannot tell them apart if they read the +same. + +**Clearing.** The timed-out state clears when the reply finally lands, when the student sends +again, and when the transport swaps (the existing re-subscribe effect already resets status, +turns and error). **A late reply is never discarded** — it renders normally when it arrives, and +the message row goes away with it. + +**Surface.** `useChat` returns a `timedOut: boolean` alongside `error` rather than folding the +timeout into `error`. `error` is also set by send failures; one field carrying three unrelated +causes makes both the component and its tests guess. `chat.tsx` renders one message row, choosing +`error` first and the timeout message otherwise. + +### 2. In-flight history + +**The guarantee already holds.** An edit made while Ada is thinking cannot reach that turn: +`sendUserMessage` computes its workspace payload before its write, so what a turn carries is +frozen at send time, and the drain reads only what is on the message documents. This is pinned +with a regression test rather than changed. + +**The real defect beside it.** `lastSentRightHash` is assigned *after* the `await`: + +```ts +await this.messagesRef().add(message); +if (decision.attachRight && right) { + this.lastSentRightHash = right.hash; +} +``` + +Two overlapping sends therefore record in completion order, not send order. Send A (hash `H1`) +and send B (`H2`) can resolve B-then-A, leaving the client believing `H1` was last sent when the +server has `H2`. The next message re-attaches a workspace the server already has — on the +ForeverLearning path that is up to 900 KB of document JSON per message. Overlapping sends are not +hypothetical: the composer is open during a pending reply precisely so a student can escape a +wedged turn. + +**Fix.** Assign in send order, before the await. On a failed write, restore the previous value +unless a newer send has already superseded it — otherwise a failed send would mark a workspace as +delivered that never left the client, and the student's retry would omit it. + +### 3. Ideas interim line + +`queueRemoteComment` gains a second timer at 45s that marks its pending entry slow. +`WaitingMessage` then shows *"Ada is taking longer than usual..."* in place of *"Ada is thinking +about it..."*. The 120s expiry and its failure message are unchanged. + +Slowness is tracked as a set of pending-entry ids on the manager, not a bare boolean. Today +`canRequestIdeas` allows only one remote `"ai"` entry at a time, so a boolean would work — but it +would be a boolean whose correctness depends on a gate in a different file, and it desyncs +silently the day that gate changes. The set cannot. + +Both timers clear through the existing `wrappedDispose`, so `removePendingComments` remains the +single path by which an entry leaves the queue and nothing is left dangling. + +### 4. AI tile failure + +The tile's catch currently restores the previous text and only `console.error`s, so a failed +refresh looks to the student like a refresh that did nothing. It will write a failure message into +the tile instead, keeping the existing restore as the superseded-run path (a newer run taking over +is not a failure and must not report one). + +**Tradeoff, stated.** The tile's text *is* document content, so this message persists and syncs — +unlike the Ideas status message, which is deliberately client-only. This follows the precedent +`AI_TILE_EMPTY_MESSAGE` already sets two lines away in the same function, and a message the +student can see is worth more than one that vanishes on reload. A later refresh overwrites it +normally. + +## Constants + +| Constant | Value | Home | +|---|---|---| +| `kReplyDeadlineMs` | `45_000` | `src/components/chat-tutor/use-chat.ts` | +| `kTimeoutMessage` | "Ada didn't answer. Please try again." | `src/components/chat-tutor/use-chat.ts` | +| `kSlowRemoteCommentMs` | `45_000` | `src/models/document/document-comments-manager.ts` | +| `IDEAS_SLOW_MESSAGE` | "Ada is taking longer than usual..." | `src/models/document/ai-evaluation-messages.ts` | +| `AI_TILE_REQUEST_FAILED_MESSAGE` | "Something went wrong getting tips. Please try again" | `src/models/document/ai-evaluation-messages.ts` | + +The two chat values sit beside the existing "Ada is currently unavailable" message in `use-chat.ts` +rather than moving to `ai-evaluation-messages.ts`: that module is about AI *evaluation* of a +document (Ideas and the AI tile), and the chat is a different feature with a different message +already living in the hook. + +## Testing + +| Test | Covers | +|---|---| +| `use-chat.test.ts` *(new)* | Deadline fires at 45s; `pending` goes false; `timedOut` set. Timer restarts on a new turn. Late reply clears the timeout and renders. Transport swap resets. No timeout while idle. | +| `firestore-transport.test.ts` | Overlapping sends record the hash in send order; a failed write restores the prior hash; a failed write superseded by a newer send does not. | +| `firestore-transport.test.ts` | Regression: a document mutated between send and write resolution does not change what that message carried. | +| `document-comments-manager.test.ts` | Slow set populated at 45s, cleared on resolve, on expiry, and on `dispose`. | +| `waiting-message.test.tsx` | Interim message replaces the thinking message when the entry is slow. | +| `ai-tile.test.tsx` | Failure writes the message; a superseded run restores instead. | + +No Cypress work: all four behaviors are timer-driven and are exercised honestly with Jest fake +timers. A Cypress spec would have to wait 45 real seconds to prove anything. + +## Delivery + +- **No Deploy timing callout.** Nothing under `functions-v1/`, `functions-v2/`, `authoring-api/`, + `shared/`, `firestore.rules`, `database.rules.json` or `firestore.indexes.json` is touched. +- **No `docs/unit-configuration.md` update.** No authorable `config` property is added or changed. From c3d407c05630c3c93a0af587d63832cb5f992a8d Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 11:31:14 -0400 Subject: [PATCH 2/8] CLUE-731: log every AI failure, with a denominator The chat emits no log events at all today, Ideas logs the click but not the outcome, and a caught error that reaches only console.error never gets to Rollbar -- so "how often does Ada fail?" is currently unanswerable. Adds a failure event on each of the four paths, plus AI_CHAT_MESSAGE_SENT so the chat failure counts have something to be a rate of. Payloads are identifiers and a reason only: no message text, prompt text, document content or raw server error string, since these reach a research database and Rollbar. Also records the decision not to cross-post a failure from one surface into another -- the chat transcript is fed back to the model as history, and the comments panel cannot name which tile failed. Co-Authored-By: Claude Opus 5 (1M context) --- .../2026-10-27-clue-731-ai-chat-timeout.md | 123 +++++++++++++++++- ...6-10-27-clue-731-ai-chat-timeout-design.md | 74 +++++++++++ 2 files changed, 191 insertions(+), 6 deletions(-) diff --git a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md index cb34ea4b6d..abfb3b7bf5 100644 --- a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md +++ b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md @@ -2,9 +2,9 @@ > **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. -**Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever. The chat gets a 45s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, and the AI tile reports a failed request instead of silently restoring its old text. +**Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever, and no AI failure is invisible to the team. The chat gets a 45s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, the AI tile reports a failed request instead of silently restoring its old text, and every one of those failures emits a log event. -**Architecture:** The chat deadline lives in `useChat`, the single place `pending` is derived, so it covers both transports without touching `FirestoreTransport.emitStatus`'s status precedence. The Ideas interim line is a second timer inside `queueRemoteComment`, clearing through the existing `wrappedDispose` so `removePendingComments` stays the only path an entry leaves the queue by. Separately, `FirestoreTransport` stops recording the last-sent workspace hash in completion order. +**Architecture:** The chat deadline lives in `useChat`, the single place `pending` is derived, so it covers both transports without touching `FirestoreTransport.emitStatus`'s status precedence. The Ideas interim line is a second timer inside `queueRemoteComment`, clearing through the existing `wrappedDispose` so `removePendingComments` stays the only path an entry leaves the queue by. Logging reaches the static `Logger.log`, which queues until the logger initializes, so the chat needs no store access; the comments manager stays free of document/store coupling by taking an `onFailure` callback rather than logging itself. Separately, `FirestoreTransport` stops recording the last-sent workspace hash in completion order. **Tech Stack:** TypeScript, React 18, MobX / MobX State Tree, Jest + @testing-library/react with fake timers. @@ -29,8 +29,11 @@ | `src/models/document/base-document-content.ts` *(modify)* | `isRemoteCommentSlow` view | | `src/components/chat/waiting-message.tsx` *(modify)* | Pick the interim message when the entry is slow | | `src/components/chat/waiting-message.test.tsx` *(modify)* | Interim message rendering | -| `src/plugins/ai/ai-tile.tsx` *(modify)* | Write the failure message on a real failure | -| `src/plugins/ai/ai-tile.test.tsx` *(modify)* | Failure writes the message; a superseded run restores | +| `src/plugins/ai/ai-tile.tsx` *(modify)* | Write the failure message on a real failure; log it | +| `src/plugins/ai/ai-tile.test.tsx` *(modify)* | Failure writes the message and logs; a superseded run restores and logs nothing | +| `src/lib/logger-types.ts` *(modify)* | `AI_CHAT_MESSAGE_SENT`, `AI_CHAT_TIMEOUT`, `AI_CHAT_UNAVAILABLE`, `IDEAS_REQUEST_FAILED` | +| `src/components/chat-tutor/chat-sidebar.tsx` *(modify)* | Hoist the conversation id out of the transport memo; pass log context to `useChat` | +| `src/components/document/document.tsx` *(modify)* | Log the two client-side Ideas failure paths; supply `onFailure` to the manager | No Cypress spec, so no `.github/workflows/manual-regression.yml` change. No functions, rules or index changes, so **no Deploy timing callout** on the PR. No authorable config, so no `docs/unit-configuration.md` update. @@ -513,7 +516,102 @@ npm test -- src/plugins/ai --- -## Task 7: Full verification +## Task 7: Logging + +Do this **after** Tasks 1–6, so every failure path it hooks into already exists and is tested. + +**Files:** +- Modify: `src/lib/logger-types.ts` +- Modify: `src/components/chat-tutor/use-chat.ts`, `src/components/chat-tutor/chat-sidebar.tsx` +- Modify: `src/models/document/document-comments-manager.ts`, `src/components/document/document.tsx` +- Modify: `src/plugins/ai/ai-tile.tsx` +- Tests: `use-chat.test.ts`, `document-comments-manager.test.ts`, `ai-tile.test.tsx` + +**What never goes in a payload:** the student's message text, their authored prompt, any document +content, or the raw server error string. Identifiers and a reason only. These logs reach a research +database and Rollbar. + +- [ ] **Step 1: Add the event names** + +In `src/lib/logger-types.ts`, add `AI_CHAT_MESSAGE_SENT`, `AI_CHAT_TIMEOUT` and +`AI_CHAT_UNAVAILABLE` near `CHAT_PANEL_HIDE`/`CHAT_PANEL_SHOW`, and `IDEAS_REQUEST_FAILED` beside +`REQUEST_IDEA`. + +Insertion mid-enum is safe: `formatAndSend` serializes with `LogEventName[event]`, so the **name** +travels, not the numeric value. Confirm no test pins the enum's length before relying on that. + +- [ ] **Step 2: Chat — hoist the conversation id** + +`chat-sidebar.tsx` currently computes `conversationDocId(...)` inline inside the transport +`useMemo`. Lift it into its own `useMemo` and pass the result into both the transport and the log +context. `conversationDocId` is pure, so this changes no behavior. + +This id is what joins a log row to the Firestore conversation — the ticket links to one specific +wedged document, and that is exactly the lookup it enables. `problemPath` is already on every log +message (`createLogMessage`), so the context needs only `{ conversationId, documentKey }`. + +- [ ] **Step 3: Chat — write the failing tests** + +In `use-chat.test.ts`, mock the logger (`jest.mock("../../lib/logger", ...)`) and assert: + +1. The deadline firing logs `AI_CHAT_TIMEOUT` **exactly once**, including after further renders — + a log inside a render body rather than the timer callback would fire repeatedly. +2. `status: "error"` logs `AI_CHAT_UNAVAILABLE` once per transition, not once per snapshot. Emit + `"error"` twice in a row and assert a single call. +3. A successful send logs `AI_CHAT_MESSAGE_SENT`; a send whose transport rejects logs nothing. +4. No payload contains the message text. Send a recognizable string and assert it appears in no + logged argument. + +- [ ] **Step 4: Chat — implement** + +Add the optional log context to `UseChatOptions`, log the send in `sendMessage` after the +transport call resolves, log the timeout inside the `setTimeout` callback, and log the unavailable +case in the existing `status === "error"` effect (which already fires once per transition). + +Make the context optional so `DebugTransport` callers and the existing tests need not supply it. +Debug dry-run sends being loggable is not a concern in practice: `chatDebug` is a developer URL +param and the logger is inert outside authed mode. + +- [ ] **Step 5: Ideas — implement and test** + +The manager has no document reference and should keep none. Add an optional +`onFailure?: () => void` to `IQueueRemoteCommentParams`, store it on the pending entry, and call it +from a small private `reportFailure()` alongside the two existing +`showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE)` calls — the 120s expiry and the `"failed"` +outcome in `applyEvaluationStatus`. `"skipped-empty"` is not a failure and logs nothing. + +In `document.tsx`, supply `onFailure` (the document is already in scope there) and log +`IDEAS_REQUEST_FAILED` at the two client-side paths as well: the 15s foreground deadline and +`guardedAttempt`'s catch. Carry a `reason` field distinguishing the four so the data can tell a +dead server from a dead connection. + +Test in `document-comments-manager.test.ts` that each in-manager path calls `onFailure` once, and +that an expiry superseded by a newer click calls it **not at all** — matching the existing +"shows nothing when an older request's entry expires after a newer click" case, which is the +precedent for that rule. + +- [ ] **Step 6: AI tile — implement and test** + +`ai-tile.test.tsx` already mocks `logTileChangeEvent` and asserts against it, so reuse that. + +In the tile's catch, beside the failure message from Task 6: + +```ts +logAiEvent(content, "requestFailed", {}); +``` + +Inside the same `isCurrent()` guard — a superseded run is not a failure and must log nothing. No +error string in the payload. + +- [ ] **Step 7: Verify** + +```bash +npm test -- src/components/chat-tutor src/models/document src/plugins/ai src/components/document +``` + +--- + +## Task 8: Full verification - [ ] **Step 1: Types and lint** @@ -528,11 +626,21 @@ pass before committing. - [ ] **Step 2: Jest across everything touched** ```bash -npm test -- src/components/chat-tutor src/components/chat src/models/document src/plugins/ai +npm test -- src/components/chat-tutor src/components/chat src/models/document src/plugins/ai src/components/document ``` Report the actual pass/fail counts. Do not claim completion from a partial run. +- [ ] **Step 2b: Confirm no student text reaches a log payload** + +```bash +grep -n "Logger.log\|logAiEvent\|logDocumentEvent" -r src/components/chat-tutor src/components/document/document.tsx src/plugins/ai/ai-tile.tsx +``` + +Read each payload and confirm it carries identifiers and a reason only — no message text, prompt +text, document content or raw server error string. The tests assert this, but it is worth one +pair of eyes, since a log that leaks student writing is not something a later test catches. + - [ ] **Step 3: Hand-check in the browser** The deadline is the one behavior worth seeing. Restart `npm start` first and confirm a clean @@ -563,3 +671,6 @@ Commit locally. Do not push until the user has checked it on localhost or said t | The slow-entry set desyncs from `pendingComments` | Both the 45s and 120s timers clear through `wrappedDispose`, and `removePendingComments` stays the single exit path. Task 5 Step 1 case 5 tests `dispose()` while slow. | | The AI tile failure message persists in document content | Stated and accepted in the spec; follows `AI_TILE_EMPTY_MESSAGE`'s existing precedent. Revisit only if a student reports a stuck error in a saved document. | | The hash rollback fires on a send that attached nothing | `claimedRight` distinguishes the two; Task 3 Step 1 case 4 is exactly this. | +| A failure event logs on every render instead of once | Every log sits in a timer callback, a transition-keyed effect, or a resolved promise — never a render body. Task 7 Step 3 cases 1 and 2 assert the counts rather than just the calls. | +| Student-written text reaches the research logs | Payloads are identifiers and a reason only. Task 7 Step 3 case 4 asserts it, Task 8 Step 2b re-reads every call site by hand. | +| Chat failure counts have no denominator | `AI_CHAT_MESSAGE_SENT` ships in the same change, so a rate is computable from day one rather than after a follow-up. | diff --git a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md index e971058ba7..e30d8760f3 100644 --- a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md +++ b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md @@ -8,6 +8,9 @@ No AI surface in CLUE may leave a student staring at a progress indicator foreve that shows "Ada is working" gets a client-side deadline after which the indicator stops and the student is told what happened, so a request that died server-side is visible rather than silent. +And it is visible to more than the student: every AI failure emits a log event, so the team can +answer "how often does Ada fail?" from data rather than from complaints. + ## Why A student cannot distinguish "the tutor is thinking" from "the tutor is never going to answer." @@ -54,6 +57,8 @@ governed what this student sees now. - A 45-second "taking longer than usual" interim line for the Ideas / document-evaluation waiting message, with the existing 120s hard expiry unchanged. - A visible failure message in the AI tile when its request fails. +- A log event for every AI failure: chat timeout, chat unavailable, Ideas failure, AI tile + failure — plus a chat "message sent" event, so a failure count has a denominator. **Out** @@ -69,6 +74,11 @@ governed what this student sees now. wrong for some unit. - **The teacher-facing AI class summary** (`src/components/navigation/ai-summary.tsx`). It has its own `checking`/`generating` status machine and no reported wedge. Separate story if it needs one. +- **Cross-posting a failure from one surface into another.** The AI tile's failure does not raise + a comments-panel message, and neither the tile nor Ideas writes into the chat. See "Each surface + reports its own failure." +- **Full chat event coverage** — replies received, panel open/close, highlight use. Only what a + failure rate needs goes in here; instrumenting the chat properly is its own story. ## Design @@ -166,6 +176,53 @@ unlike the Ideas status message, which is deliberately client-only. This follows student can see is worth more than one that vanishes on reload. A later refresh overwrites it normally. +### 5. Each surface reports its own failure + +The tile reports in the tile, the chat reports in the chat, Ideas reports in the comments panel. +No failure is copied into another surface. + +Two reasons, one per candidate. The **chat transcript is persisted in Firestore and fed back to +the model as conversation history**, so an injected "something went wrong" turn would become part +of what the model reads on the next turn — a client-only row avoids that but is still a message in +a conversation the student may never have opened. The **comments panel cannot say which tile +failed**; a document may hold several AI tiles with different prompts, and the panel's status line +has no tile to name. + +The general point: cross-posting puts an error in front of people who were not there. A student +who clicked Update on a tile is looking at that tile. The audience that needs the cross-surface +view is the team, and logging serves them better than a duplicated message does. + +### 6. Logging + +**Why this is load-bearing, not an afterthought.** The chat emits **no log events at all** today — +not sends, not replies, not errors. "How often does Ada fail to answer?" is currently unanswerable. +Ideas logs `REQUEST_IDEA` on the click and nothing about the outcome, so attempts are countable +and failures are not. And a caught error that reaches only `console.error` goes nowhere: Rollbar +captures uncaught errors, while CLUE log events reach both the research log database and Rollbar +as info (`Logger.registerLogListener` in `src/lib/misc.ts`). The console.error in the AI tile's +catch today is, in practice, writing to nowhere. + +**The denominator.** A failure event on its own yields a number nobody can interpret — forty chat +timeouts is a crisis out of two hundred and a rounding error out of forty thousand. Since the chat +logs nothing, a successful-send event goes in alongside the timeout so a rate can be computed. +This is the only non-failure event in scope. + +**Reaching the logger.** `Logger.log` is static and queues messages until the logger initializes, +so the chat can call it without holding stores. It serializes the event by **name** +(`LogEventName[event]` in `formatAndSend`), not by its numeric enum value, so inserting new entries +mid-enum does not renumber anything downstream. + +**What is logged, and what is not.** Identifiers and a reason: document key, problem path, +conversation id, tile id, and which failure it was. **Never the student's message text, their +authored prompt, or any document content.** These logs go to a research database and to Rollbar; +student-written text does not belong in either, and a failure rate does not need it. The raw +server error string is also left out — it can be long and can echo request content. + +**Event names.** The chat gets three new ones, since it has none to reuse. Ideas gets one. The AI +tile reuses its existing `AI_TOOL_CHANGE` with `operation: "requestFailed"`, matching the +convention already in `ai-content.ts` (`requestRefresh` is logged the same way) rather than +introducing a fourth name for researchers to learn. + ## Constants | Constant | Value | Home | @@ -181,6 +238,19 @@ rather than moving to `ai-evaluation-messages.ts`: that module is about AI *eval document (Ideas and the AI tile), and the chat is a different feature with a different message already living in the hook. +## Log events + +| Event | Fires when | Payload | +|---|---|---| +| `AI_CHAT_MESSAGE_SENT` | a user message reaches Firestore | conversation id, document key, problem path | +| `AI_CHAT_TIMEOUT` | the 45s reply deadline fires | conversation id, document key, problem path | +| `AI_CHAT_UNAVAILABLE` | the transport reports `status: "error"` | conversation id, document key, problem path | +| `IDEAS_REQUEST_FAILED` | the 15s foreground deadline, the 120s expiry, or a `"failed"` server outcome | document key, problem path, request id, which of the three | +| `AI_TOOL_CHANGE` *(existing)* | the AI tile's request fails | tile id, `operation: "requestFailed"` | + +`AI_CHAT_MESSAGE_SENT` is the denominator for the two chat failure events. No event carries +message text, prompt text, document content or the raw server error string. + ## Testing | Test | Covers | @@ -191,6 +261,10 @@ already living in the hook. | `document-comments-manager.test.ts` | Slow set populated at 45s, cleared on resolve, on expiry, and on `dispose`. | | `waiting-message.test.tsx` | Interim message replaces the thinking message when the entry is slow. | | `ai-tile.test.tsx` | Failure writes the message; a superseded run restores instead. | +| `use-chat.test.ts` | Timeout and unavailable each log once per episode, not once per render. A successful send logs; a failed send does not. | +| `document-comments-manager.test.ts` | Each of the three Ideas failure paths logs, and an expiry superseded by a newer click does not. | +| `ai-tile.test.tsx` | A failed request logs `requestFailed`; a superseded run logs nothing. | +| all of the above | No logged payload contains message text, prompt text or document content. | No Cypress work: all four behaviors are timer-driven and are exercised honestly with Jest fake timers. A Cypress spec would have to wait 45 real seconds to prove anything. From 5f673cae9b89965cd9f9ad182ca73a86a3eac07a Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 12:32:33 -0400 Subject: [PATCH 3/8] CLUE-731: give every AI surface a deadline and a log The chat had no client-side deadline at all: a user message whose assistant document is never written (the drain writes reply and cursor in one batch, so a drain that died writes neither) left the dots running until reload. Adds a 45s reply deadline in useChat, restarting per message so a student who sends again mid-wait gets their own clock. A late reply still renders. The live region keys on `pending` going false to announce a reply, and the deadline flips `pending` false too, so it is now guarded -- otherwise a timeout would announce the previous reply at the moment Ada failed to answer. Ideas keeps its 120s expiry, which is pinned to the evaluation function's own 120s budget, and gains a 45s "taking longer than usual" line ahead of it. The AI tile reports a failed request instead of restoring its old text, which looked like a refresh that did nothing. Logging: the chat emitted no events at all, Ideas logged the click but not the outcome, and a caught error reaching only console.error never gets to Rollbar. Adds a failure event on each path plus AI_CHAT_MESSAGE_SENT, so the chat failure counts have something to be a rate of. Payloads are identifiers and a reason only -- no message text, prompt text, document content or raw server error string. Also fixes lastSentRightHash being recorded after the write, so two overlapping sends recorded in completion order and the next message re-attached a workspace the server already had. Co-Authored-By: Claude Opus 5 (1M context) --- .../chat-tutor/chat-highlights.test.tsx | 2 +- src/components/chat-tutor/chat-sidebar.tsx | 28 ++- .../chat-tutor/chat-timeout.test.tsx | 48 ++++ src/components/chat-tutor/chat.tsx | 9 +- .../chat-tutor/firestore-transport.test.ts | 122 ++++++++++ .../chat-tutor/firestore-transport.ts | 23 +- src/components/chat-tutor/use-chat.test.ts | 212 ++++++++++++++++++ src/components/chat-tutor/use-chat.ts | 55 ++++- src/components/chat/waiting-message.test.tsx | 6 + src/components/chat/waiting-message.tsx | 4 +- src/components/document/document.tsx | 18 +- src/lib/logger-types.ts | 6 + src/models/document/ai-evaluation-messages.ts | 4 + src/models/document/base-document-content.ts | 5 + .../document-comments-manager.test.ts | 163 +++++++++++++- .../document/document-comments-manager.ts | 55 ++++- src/plugins/ai/ai-tile.test.tsx | 87 +++++-- src/plugins/ai/ai-tile.tsx | 17 +- 18 files changed, 803 insertions(+), 61 deletions(-) create mode 100644 src/components/chat-tutor/chat-timeout.test.tsx create mode 100644 src/components/chat-tutor/use-chat.test.ts diff --git a/src/components/chat-tutor/chat-highlights.test.tsx b/src/components/chat-tutor/chat-highlights.test.tsx index f241a3a70c..8402b3c8c0 100644 --- a/src/components/chat-tutor/chat-highlights.test.tsx +++ b/src/components/chat-tutor/chat-highlights.test.tsx @@ -13,7 +13,7 @@ const turn: ChatTurn = { }; const chatResult = (turns: ChatTurn[]): UseChatResult => ({ - turns, status: "idle", error: null, pending: false, + turns, status: "idle", error: null, pending: false, timedOut: false, sendMessage: jest.fn(async () => undefined), header: "Doc · 1.1" }); diff --git a/src/components/chat-tutor/chat-sidebar.tsx b/src/components/chat-tutor/chat-sidebar.tsx index fe8da96a9f..4506386d32 100644 --- a/src/components/chat-tutor/chat-sidebar.tsx +++ b/src/components/chat-tutor/chat-sidebar.tsx @@ -58,7 +58,12 @@ export const ChatTutorSidebar: React.FC = observer((props) => { // path. Rebuilding on documentKey/problemPath change is the hard conversation swap; // the unit's authored prompt overrides and the effective unit-summary slice are both // mixed into the conversation id so a change to either starts a fresh conversation. - const transport: ChatTransport = useMemo(() => { + // The conversation id comes back with the transport because it is derived from values that only + // exist in here. It travels into the failure logs, where it joins a log row to the conversation + // a report of one stuck chat points at. The debug transport has none. + const { transport, conversationId } = useMemo((): { + transport: ChatTransport; conversationId?: string; + } => { const getLeftContext = () => problemSectionsLoaded(problem) ? buildLeftContext(problem) : undefined; // Rides the same install-eligible sends as LEFT (see unit-context.ts). Computed fresh per // transport, same as getLeftContext -- unit.config is authored data, not expected to change @@ -66,7 +71,9 @@ export const ChatTutorSidebar: React.FC = observer((props) => { const getUnitContext = () => buildUnitContext(unit, problem); const tutorPrompts = normalizeTutorPrompts(appConfig.chatTutorPrompts); if (urlParams.chatDebug) { - return new DebugTransport({ getLeftContext, getUnitContext, getRightSummary, tutorPrompts }); + return { + transport: new DebugTransport({ getLeftContext, getUnitContext, getRightSummary, tutorPrompts }) + }; } const promptsKey = tutorPrompts && tutorPromptsKey(tutorPrompts); // Resolved once per transport. Undefined for the default provider, which is what keeps it @@ -78,11 +85,12 @@ export const ChatTutorSidebar: React.FC = observer((props) => { // never fork on it either. const unitContext = providerInstallsProblem(provider) ? getUnitContext() : undefined; const unitKey = unitContext ? hashString(unitContext) : undefined; - return new FirestoreTransport({ + const docId = conversationDocId( + user.id, documentKey, user.network, problemPath, promptsKey, provider, unitKey + ); + return { conversationId: docId, transport: new FirestoreTransport({ firestore: db.firestore, - conversationId: conversationDocId( - user.id, documentKey, user.network, problemPath, promptsKey, provider, unitKey - ), + conversationId: docId, uid: user.id, contextId: user.classHash, problemPath, @@ -95,13 +103,17 @@ export const ChatTutorSidebar: React.FC = observer((props) => { getRightContent: () => content ? serializeRight(content) : undefined, tutorPrompts, provider, - }); + }) }; }, [documentKey, problemPath, problem, getRightSummary, content, appConfig, db, user, unit]); + const logContext = useMemo( + () => conversationId ? { conversationId, documentKey } : undefined, + [conversationId, documentKey]); + // The drawer header makes the conversation scope legible: this conversation is bound // to one workspace document within one problem, and swaps when either changes. const header = `${documentTitle} · ${problemPath}`; - const chat = useChat({ transport, header }); + const chat = useChat({ transport, header, logContext }); // Display-only persona intro (never part of the AI context). An unset value uses the built-in // default; an authored empty string suppresses the intro entirely (?? keeps "" distinct from unset). diff --git a/src/components/chat-tutor/chat-timeout.test.tsx b/src/components/chat-tutor/chat-timeout.test.tsx new file mode 100644 index 0000000000..c12aea7887 --- /dev/null +++ b/src/components/chat-tutor/chat-timeout.test.tsx @@ -0,0 +1,48 @@ +import React from "react"; +import { render, screen } from "@testing-library/react"; +import { Chat } from "./chat"; +import { ChatTurn } from "./transport"; +import { kTimeoutMessage, UseChatResult } from "./use-chat"; + +const chatResult = (over: Partial = {}): UseChatResult => ({ + turns: [], status: "idle", error: null, pending: false, timedOut: false, + sendMessage: jest.fn(async () => undefined), header: "Doc · 1.1", ...over +}); + +const reply: ChatTurn = { id: "a1", sender: "assistant", text: "Try the sensor block." }; + +describe("Chat reply timeout", () => { + it("shows the timeout message when the deadline has passed", () => { + render(); + expect(screen.getByTestId("chat-error")).toHaveTextContent(kTimeoutMessage); + }); + + it("stops the typing indicator", () => { + render(); + expect(screen.queryByTestId("chat-typing")).not.toBeInTheDocument(); + }); + + // A real send failure must not be masked by the deadline that follows it. + it("prefers a send error over the timeout message", () => { + render(); + expect(screen.getByTestId("chat-error")).toHaveTextContent("Failed to send your message."); + }); + + // The live region keys on `pending` going false to announce a completed reply, and the deadline + // flips `pending` false too — so without a guard a timeout announces the PREVIOUS reply as if it + // had just arrived, telling a screen-reader user Ada answered at the moment Ada failed to. + it("does not announce the previous reply when the deadline fires", () => { + render(); + expect(screen.getByTestId("chat-live")).toHaveTextContent(""); + }); + + it("announces a reply normally when nothing has timed out", () => { + render(); + expect(screen.getByTestId("chat-live")).toHaveTextContent("Ada said: Try the sensor block."); + }); + + it("shows no message row when there is neither an error nor a timeout", () => { + render(); + expect(screen.queryByTestId("chat-error")).not.toBeInTheDocument(); + }); +}); diff --git a/src/components/chat-tutor/chat.tsx b/src/components/chat-tutor/chat.tsx index 5df8662d83..a6a6fdcfdd 100644 --- a/src/components/chat-tutor/chat.tsx +++ b/src/components/chat-tutor/chat.tsx @@ -1,7 +1,7 @@ import React, { FormEvent, useEffect, useMemo, useRef, useState } from "react"; import classNames from "classnames"; import { v4 as uuidv4 } from "uuid"; -import { UseChatResult } from "./use-chat"; +import { kTimeoutMessage, UseChatResult } from "./use-chat"; import { ChatTurn } from "./transport"; import "./chat.scss"; @@ -119,7 +119,7 @@ const DebugTurn: React.FC<{ turn: ChatTurn }> = ({ turn }) => { export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTitle, introText, onHighlightHover, onHighlightToggle, activeHighlightKey, enableHighlights = false }) => { - const { turns, error, pending, sendMessage, header } = chat; + const { turns, error, pending, timedOut, sendMessage, header } = chat; const [input, setInput] = useState(""); const [sending, setSending] = useState(false); const [copied, setCopied] = useState(false); @@ -338,7 +338,7 @@ export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTi {/* single polite live region announcing the completed assistant reply */}
- {!pending && lastAssistantText ? `Ada said: ${lastAssistantText}` : ""} + {!pending && !timedOut && lastAssistantText ? `Ada said: ${lastAssistantText}` : ""}
{/* Pinning a highlight moves a ring onto an object elsewhere in the document, where nothing @@ -360,7 +360,8 @@ export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTi {activeHighlightLabel ? `Highlighting ${activeHighlightLabel}` : ""} } - {error &&
{error}
} + {(error || timedOut) && +
{error ?? kTimeoutMessage}
}
diff --git a/src/components/chat-tutor/firestore-transport.test.ts b/src/components/chat-tutor/firestore-transport.test.ts index c00fa0ebb7..7a75c54e8a 100644 --- a/src/components/chat-tutor/firestore-transport.test.ts +++ b/src/components/chat-tutor/firestore-transport.test.ts @@ -285,3 +285,125 @@ describe("FirestoreTransport measures the workspace in bytes", () => { expect(added[0]).not.toHaveProperty("rightContent"); }); }); + + +// The composer stays open while a reply is pending — that is the student's only escape from a +// wedged turn — so two sends can be in flight at once. `lastSentRightHash` therefore has to track +// what was SENT, not what happened to resolve last. +describe("FirestoreTransport workspace bookkeeping under overlapping sends", () => { + // Unlike fakeFirestore above, each add() hands back a promise the test settles by hand, which is + // the only way to express one send resolving while another is still open. + function deferredFirestore() { + const added: Record[] = []; + const settle: Array<{ resolve: () => void; reject: (e: unknown) => void }> = []; + const messages = { + add: (doc: Record) => { + added.push(doc); + return new Promise((resolve, reject) => settle.push({ resolve, reject })); + } + }; + const firestore = { collection: () => ({ doc: () => ({ collection: () => messages }) }) }; + return { added, settle, firestore: firestore as any }; + } + + function transportWithMutableWorkspace() { + const { added, settle, firestore } = deferredFirestore(); + let summary = { markdown: "W1", hash: "H1" }; + const transport = new FirestoreTransport({ + firestore, conversationId: "conv1", uid: "123", contextId: "class1", + problemPath: "sas/1/2", getLeftContext: () => "{}", + getRightSummary: () => summary, + }); + const edit = (markdown: string, hash: string) => { summary = { markdown, hash }; }; + return { added, settle, transport, edit }; + } + + it("records the hash in send order, not completion order", async () => { + const { added, settle, transport, edit } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); + edit("W2", "H2"); + const second = transport.sendUserMessage("two"); + + // B's write lands before A's, which is what put the client's record behind the server's. + settle[1].resolve(); + settle[0].resolve(); + await Promise.all([first, second]); + + const third = transport.sendUserMessage("three"); + settle[2].resolve(); + await third; + + expect(added[1].rightContext).toBe("W2"); + expect(added[2]).not.toHaveProperty("rightContext"); + }); + + it("re-attaches a workspace whose write failed", async () => { + const { added, settle, transport } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); + settle[0].reject(new Error("offline")); + await expect(first).rejects.toThrow("offline"); + + const second = transport.sendUserMessage("two"); + settle[1].resolve(); + await second; + + expect(added[1].rightContext).toBe("W1"); + }); + + // A's rollback must not undo B's successful delivery of the same workspace. + it("does not roll back over a newer send that succeeded", async () => { + const { added, settle, transport, edit } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); + edit("W2", "H2"); + const second = transport.sendUserMessage("two"); + + settle[1].resolve(); + await second; + settle[0].reject(new Error("offline")); + await expect(first).rejects.toThrow("offline"); + + const third = transport.sendUserMessage("three"); + settle[2].resolve(); + await third; + + expect(added[2]).not.toHaveProperty("rightContext"); + }); + + // The hashes match precisely BECAUSE this send attached nothing, so a hash match alone is not + // evidence that this send is the one holding the record. + it("does not clear the record when an unchanged send fails", async () => { + const { added, settle, transport } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); + settle[0].resolve(); + await first; + + const second = transport.sendUserMessage("two"); // attaches nothing: workspace unchanged + settle[1].reject(new Error("offline")); + await expect(second).rejects.toThrow("offline"); + + const third = transport.sendUserMessage("three"); + settle[2].resolve(); + await third; + + expect(added[0].rightContext).toBe("W1"); + expect(added[2]).not.toHaveProperty("rightContext"); + }); + + // Nothing retroactively tells an in-flight turn about an edit: the payload is computed before + // the write. Pinned here because the guarantee is load-bearing and invisible from the call site. + it("does not change what a message carried when the document is edited mid-send", async () => { + const { added, settle, transport, edit } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); + edit("W2", "H2"); + settle[0].resolve(); + await first; + + expect(added).toHaveLength(1); + expect(added[0].rightContext).toBe("W1"); + }); +}); diff --git a/src/components/chat-tutor/firestore-transport.ts b/src/components/chat-tutor/firestore-transport.ts index 9b884e46de..c6788186c1 100644 --- a/src/components/chat-tutor/firestore-transport.ts +++ b/src/components/chat-tutor/firestore-transport.ts @@ -230,10 +230,27 @@ export class FirestoreTransport implements ChatTransport { message[right.field] = right.value; } - await this.messagesRef().add(message); + // Recorded before the write, not after. Two overlapping sends would otherwise record in + // completion order, leaving the client believing an older workspace was the last one sent and + // re-attaching one the server already has — up to kMaxAttachedWorkspace of document JSON on + // the ForeverLearning path. The composer stays open during a pending reply so a student can + // escape a wedged turn, so overlapping sends are expected, not exotic. + const claimedRight = decision.attachRight ? right : undefined; + const previousRightHash = this.lastSentRightHash; + if (claimedRight) { + this.lastSentRightHash = claimedRight.hash; + } - if (decision.attachRight && right) { - this.lastSentRightHash = right.hash; + try { + await this.messagesRef().add(message); + } catch (e) { + // The workspace never left the client, so the record has to go back — but only if this send + // is still the one holding it. `claimedRight` is what separates this from an unchanged send, + // whose hash matches precisely because it attached nothing. + if (claimedRight && this.lastSentRightHash === claimedRight.hash) { + this.lastSentRightHash = previousRightHash; + } + throw e; } } diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts new file mode 100644 index 0000000000..d341477da3 --- /dev/null +++ b/src/components/chat-tutor/use-chat.test.ts @@ -0,0 +1,212 @@ +import { act, renderHook } from "@testing-library/react"; +import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; +import { kReplyDeadlineMs, useChat } from "./use-chat"; +import { Logger } from "../../lib/logger"; +import { LogEventName } from "../../lib/logger-types"; + +jest.mock("../../lib/logger", () => ({ Logger: { log: jest.fn() } })); +const mockLog = Logger.log as jest.Mock; + +// A transport whose emitters the test drives directly, so turns and status can be pushed in any +// order a real conversation produces them. +function stubTransport() { + let emitTurns: (turns: ChatTurn[]) => void = () => undefined; + let emitStatus: (status: ChatStatus) => void = () => undefined; + const sendUserMessage = jest.fn(async () => undefined); + const transport: ChatTransport = { + subscribe(onTurns, onStatus) { + emitTurns = onTurns; + emitStatus = onStatus; + onTurns([]); + onStatus("idle"); + return () => undefined; + }, + sendUserMessage, + }; + return { + transport, + sendUserMessage, + turns: (t: ChatTurn[]) => act(() => { emitTurns(t); }), + status: (s: ChatStatus) => act(() => { emitStatus(s); }), + }; +} + +const userTurn = (id: string): ChatTurn => ({ id, sender: "user", text: "help" }); +const assistantTurn = (id: string): ChatTurn => ({ id, sender: "assistant", text: "here you go" }); +const advance = (ms: number) => act(() => { jest.advanceTimersByTime(ms); }); + +const renderChat = (transport: ChatTransport) => + renderHook(() => useChat({ transport, header: "Doc · 1.1" })); + +describe("useChat reply deadline", () => { + beforeEach(() => jest.useFakeTimers()); + afterEach(() => jest.useRealTimers()); + + it("never times out while idle", () => { + const t = stubTransport(); + const { result } = renderChat(t.transport); + + advance(kReplyDeadlineMs * 2); + + expect(result.current.timedOut).toBe(false); + expect(result.current.pending).toBe(false); + }); + + it("keeps the typing indicator until the deadline, then stops it", () => { + const t = stubTransport(); + const { result } = renderChat(t.transport); + + t.turns([userTurn("m1")]); + t.status("generating"); + + advance(kReplyDeadlineMs - 1); + expect(result.current.pending).toBe(true); + expect(result.current.timedOut).toBe(false); + + advance(1); + expect(result.current.pending).toBe(false); + expect(result.current.timedOut).toBe(true); + }); + + // The case a `waiting`-only dependency list gets wrong: the student would inherit the first + // message's clock and be told Ada didn't answer seconds after sending the second one. + it("starts a fresh deadline for a message sent while already waiting", () => { + const t = stubTransport(); + const { result } = renderChat(t.transport); + + t.turns([userTurn("m1")]); + t.status("generating"); + advance(40_000); + + t.turns([userTurn("m1"), userTurn("m2")]); + advance(40_000); // 80s since the first message, 40s since the second + + expect(result.current.timedOut).toBe(false); + + advance(5_001); + expect(result.current.timedOut).toBe(true); + }); + + it("clears the timeout and renders the turn when a late reply arrives", () => { + const t = stubTransport(); + const { result } = renderChat(t.transport); + + t.turns([userTurn("m1")]); + t.status("generating"); + advance(kReplyDeadlineMs); + expect(result.current.timedOut).toBe(true); + + t.turns([userTurn("m1"), assistantTurn("a1")]); + t.status("idle"); + + expect(result.current.timedOut).toBe(false); + expect(result.current.turns).toHaveLength(2); + }); + + it("resets when the transport swaps, and the old conversation's timer cannot fire", () => { + const first = stubTransport(); + const second = stubTransport(); + const { result, rerender } = renderHook( + ({ transport }) => useChat({ transport, header: "Doc · 1.1" }), + { initialProps: { transport: first.transport } } + ); + + first.turns([userTurn("m1")]); + first.status("generating"); + advance(kReplyDeadlineMs); + expect(result.current.timedOut).toBe(true); + + rerender({ transport: second.transport }); + expect(result.current.timedOut).toBe(false); + + advance(kReplyDeadlineMs * 2); + expect(result.current.timedOut).toBe(false); + }); +}); + + +// The chat emitted no log events at all before this, so a failure count had nothing to be a rate +// of. MESSAGE_SENT is that denominator; the rest are the failures. +describe("useChat logging", () => { + const logContext = { conversationId: "conv-1", documentKey: "doc-1" }; + + const renderWithContext = (transport: ChatTransport) => + renderHook(() => useChat({ transport, header: "Doc · 1.1", logContext })); + + const eventsNamed = (event: LogEventName) => + mockLog.mock.calls.filter(([e]) => e === event); + + beforeEach(() => { + jest.useFakeTimers(); + mockLog.mockClear(); + }); + afterEach(() => jest.useRealTimers()); + + it("logs the timeout exactly once, however many renders follow", () => { + const t = stubTransport(); + const { rerender } = renderWithContext(t.transport); + + t.turns([userTurn("m1")]); + t.status("generating"); + advance(kReplyDeadlineMs); + rerender(); + rerender(); + + expect(eventsNamed(LogEventName.AI_CHAT_TIMEOUT)).toEqual([ + [LogEventName.AI_CHAT_TIMEOUT, logContext] + ]); + }); + + // The transport re-emits its status on every snapshot, so a log keyed on anything but the + // transition would fire repeatedly for one failure. + it("logs an unavailable backend once per transition, not once per snapshot", () => { + const t = stubTransport(); + renderWithContext(t.transport); + + t.status("error"); + t.status("error"); + + expect(eventsNamed(LogEventName.AI_CHAT_UNAVAILABLE)).toHaveLength(1); + }); + + it("logs a send that landed", async () => { + const t = stubTransport(); + const { result } = renderWithContext(t.transport); + + await act(async () => { await result.current.sendMessage("how do I start?"); }); + + expect(eventsNamed(LogEventName.AI_CHAT_MESSAGE_SENT)).toEqual([ + [LogEventName.AI_CHAT_MESSAGE_SENT, logContext] + ]); + }); + + // The denominator counts messages the backend could have answered, so a write that never + // landed is not one of them. + it("does not log a send whose write failed", async () => { + const t = stubTransport(); + t.sendUserMessage.mockRejectedValueOnce(new Error("offline")); + const { result } = renderWithContext(t.transport); + + await act(async () => { + await expect(result.current.sendMessage("how do I start?")).rejects.toThrow("offline"); + }); + + expect(eventsNamed(LogEventName.AI_CHAT_MESSAGE_SENT)).toHaveLength(0); + }); + + // These logs reach a research database and Rollbar. Student writing belongs in neither, and a + // failure rate does not need it. + it("never puts the student's message into a log payload", async () => { + const t = stubTransport(); + const { result } = renderWithContext(t.transport); + + await act(async () => { await result.current.sendMessage("my secret answer"); }); + t.turns([userTurn("m1")]); + t.status("generating"); + advance(kReplyDeadlineMs); + t.status("error"); + + expect(mockLog).toHaveBeenCalled(); + expect(JSON.stringify(mockLog.mock.calls)).not.toContain("my secret answer"); + }); +}); diff --git a/src/components/chat-tutor/use-chat.ts b/src/components/chat-tutor/use-chat.ts index cf4c7bfbc6..6da120dc54 100644 --- a/src/components/chat-tutor/use-chat.ts +++ b/src/components/chat-tutor/use-chat.ts @@ -1,25 +1,49 @@ import { useCallback, useEffect, useState } from "react"; import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; +import { Logger } from "../../lib/logger"; +import { LogEventName } from "../../lib/logger-types"; + +// How long the client waits for a reply before it stops claiming Ada is working. Nothing on the +// client can tell a dead turn from a slow one -- the drain writes its assistant document and its +// cursor in one batch, so a drain that died writes neither -- which is why this is a deadline and +// not a smarter reading of status. A reply carrying document context routinely takes 10-25s. +export const kReplyDeadlineMs = 45_000; + +// Distinct from the status:"error" message below: the backend reporting an error and the backend +// reporting nothing are different failures, and support can't tell them apart if they read alike. +export const kTimeoutMessage = "Ada didn't answer. Please try again."; export interface UseChatResult { turns: ChatTurn[]; status: ChatStatus; error: string | null; pending: boolean; + timedOut: boolean; sendMessage: (text: string) => Promise; header: string; } +export interface ChatLogContext { + // Joins a log row to the Firestore conversation it came from, which is the lookup a report of + // one stuck chat needs. problemPath is already on every log message, so it isn't repeated here. + conversationId: string; + documentKey: string; +} + export interface UseChatOptions { transport: ChatTransport; // Makes the per-document/per-problem scoping legible in the drawer header. header: string; + // Optional so the debug transport and tests need not supply it. Identifiers only: no message + // text ever goes into a log, which reaches a research database and Rollbar. + logContext?: ChatLogContext; } -export function useChat({ transport, header }: UseChatOptions): UseChatResult { +export function useChat({ transport, header, logContext }: UseChatOptions): UseChatResult { const [turns, setTurns] = useState([]); const [status, setStatus] = useState("idle"); const [error, setError] = useState(null); + const [timedOut, setTimedOut] = useState(false); // Re-subscribe whenever the transport instance changes — this is the hard // conversation swap when the student switches documents or problems. @@ -36,12 +60,30 @@ export function useChat({ transport, header }: UseChatOptions): UseChatResult { useEffect(() => { if (status === "error") { setError("Ada is currently unavailable. Please try again."); + Logger.log(LogEventName.AI_CHAT_UNAVAILABLE, { ...logContext }); } - }, [status]); + }, [status, logContext]); // The live transport folds "a just-sent user message awaits a reply" into the status it // emits — computed from the raw doc stream, so a silent reply clears it. - const pending = status === "generating"; + const waiting = status === "generating"; + const newestTurnId = turns.length ? turns[turns.length - 1].id : undefined; + + // Keyed on the newest turn as well as `waiting`: a second message sent mid-wait must start its + // own clock rather than inherit the first one's and be cut off seconds after the student sent + // it. The id is minted client-side by the transport's add(), so the optimistic turn and its + // confirmation share one id and this changes exactly once per message. + useEffect(() => { + setTimedOut(false); + if (!waiting) return; + const timer = setTimeout(() => { + setTimedOut(true); + Logger.log(LogEventName.AI_CHAT_TIMEOUT, { ...logContext }); + }, kReplyDeadlineMs); + return () => clearTimeout(timer); + }, [waiting, newestTurnId, logContext]); + + const pending = waiting && !timedOut; const sendMessage = useCallback(async (text: string) => { const trimmed = text.trim(); @@ -49,11 +91,14 @@ export function useChat({ transport, header }: UseChatOptions): UseChatResult { setError(null); try { await transport.sendUserMessage(trimmed); + // Only once the write landed, so the denominator counts messages the backend could + // actually have answered. + Logger.log(LogEventName.AI_CHAT_MESSAGE_SENT, { ...logContext }); } catch (e) { setError((e as Error)?.message || "Failed to send your message. Please try again."); throw e; } - }, [transport]); + }, [transport, logContext]); - return { turns, status, error, pending, sendMessage, header }; + return { turns, status, error, pending, timedOut, sendMessage, header }; } diff --git a/src/components/chat/waiting-message.test.tsx b/src/components/chat/waiting-message.test.tsx index 53ea29c863..b92c4e167e 100644 --- a/src/components/chat/waiting-message.test.tsx +++ b/src/components/chat/waiting-message.test.tsx @@ -1,6 +1,7 @@ import { render, screen } from "@testing-library/react"; import React from "react"; import WaitingMessage, { StatusMessage } from "./waiting-message"; +import { IDEAS_SLOW_MESSAGE } from "../../models/document/ai-evaluation-messages"; jest.mock("../../hooks/use-stores", () => ({ useStores: () => ({ @@ -24,6 +25,11 @@ describe("WaitingMessage", () => { expect(screen.getByTestId("comment")).toHaveTextContent("Ada is thinking about it..."); }); + it("says the wait has become unusual once the request is slow", () => { + render(); + expect(screen.getByTestId("comment")).toHaveTextContent(IDEAS_SLOW_MESSAGE); + }); + it("announces itself as a polite live region", () => { render(); expect(screen.getByTestId("comment")).toHaveAttribute("role", "status"); diff --git a/src/components/chat/waiting-message.tsx b/src/components/chat/waiting-message.tsx index ba85d8b686..a8a0feb32d 100644 --- a/src/components/chat/waiting-message.tsx +++ b/src/components/chat/waiting-message.tsx @@ -2,6 +2,7 @@ import React, { useEffect, useRef } from "react"; import { observer } from "mobx-react"; import { DocumentContentModelType } from "../../models/document/document-content"; import { kAnalyzerUserParams } from "../../../shared/shared"; +import { IDEAS_SLOW_MESSAGE } from "../../models/document/ai-evaluation-messages"; import ChatAvatar from "./chat-avatar"; const waitingMessageText = "Ada is thinking about it..."; @@ -46,7 +47,8 @@ const _WaitingMessage: React.FC = ({ content }) => { return (
- {content?.isAwaitingRemoteComment && } + {content?.isAwaitingRemoteComment && + }
); }; diff --git a/src/components/document/document.tsx b/src/components/document/document.tsx index 0288e710a0..0c6681d235 100644 --- a/src/components/document/document.tsx +++ b/src/components/document/document.tsx @@ -11,7 +11,9 @@ import { DEBUG_HISTORY_VIEW } from "../../lib/debug"; import { Logger } from "../../lib/logger"; import { LogEventName } from "../../lib/logger-types"; import { DocumentModelType } from "../../models/document/document"; -import { CommentWithId, kIdeasRequestDeadlineMs } from "../../models/document/document-comments-manager"; +import { + CommentWithId, IdeasFailureReason, kIdeasRequestDeadlineMs +} from "../../models/document/document-comments-manager"; import { LearningLogDocument, LearningLogPublication, PersonalDocument } from "../../models/document/document-types"; import { getDocumentDisplayTitle, getDocumentTitleWithTimestamp } from "../../models/document/document-utils"; import { IDEAS_EMPTY_MESSAGE, IDEAS_REQUEST_FAILED_MESSAGE } from "../../models/document/ai-evaluation-messages"; @@ -582,6 +584,11 @@ export class DocumentComponent extends BaseComponent { return; } + // Every path that gives up on this click reports through here, so the four are countable + // against REQUEST_IDEA above. Identifiers and a reason only — no document content. + const logFailure = (reason: IdeasFailureReason) => + logDocumentEvent(LogEventName.IDEAS_REQUEST_FAILED, { document }, undefined, { reason, requestId }); + commentsManager.setIdeasClickInProgress(true); // setLastEditedNow/getLastEditedTimestamp have no timeout of their own, so a stalled @@ -619,7 +626,8 @@ export class DocumentComponent extends BaseComponent { return !!(lastAIComment && lastAIComment.createdAt.getTime() > effectiveLastEdited); }, - dispose: () => statusRef.off("value", onStatus) + dispose: () => statusRef.off("value", onStatus), + onFailure: logFailure }); statusRef.on("value", onStatus); @@ -638,6 +646,7 @@ export class DocumentComponent extends BaseComponent { console.error("Ideas request failed:", error); if (aiEnabled && !timedOut && commentsManager.latestIdeasRequestId === requestId) { commentsManager.showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE); + logFailure("client-error"); } }); let resolveDeadline: (value: "timeout") => void; @@ -650,7 +659,10 @@ export class DocumentComponent extends BaseComponent { try { const result = await Promise.race([guardedAttempt.then(() => "done" as const), deadline]); if (result === "timeout") { - if (aiEnabled) commentsManager.showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE); + if (aiEnabled) { + commentsManager.showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE); + logFailure("client-deadline"); + } } else { clearTimeout(deadlineTimer); } diff --git a/src/lib/logger-types.ts b/src/lib/logger-types.ts index 54e0a914b9..153c0b0431 100644 --- a/src/lib/logger-types.ts +++ b/src/lib/logger-types.ts @@ -80,6 +80,11 @@ export enum LogEventName { CHAT_PANEL_HIDE, CHAT_PANEL_SHOW, + // Ada chat tutor. MESSAGE_SENT is the denominator the two failure events are a rate of. + AI_CHAT_MESSAGE_SENT, + AI_CHAT_TIMEOUT, + AI_CHAT_UNAVAILABLE, + // the following are for potential debugging purposes and are all marked "internal" INTERNAL_AUTHENTICATED, INTERNAL_ERROR_ENCOUNTERED, @@ -122,6 +127,7 @@ export enum LogEventName { TOOLBAR_READ_ALOUD_COMMENT_TRANSITION, REQUEST_IDEA, + IDEAS_REQUEST_FAILED, STANDALONE_SWITCH_PREVIEW_PROBLEM, diff --git a/src/models/document/ai-evaluation-messages.ts b/src/models/document/ai-evaluation-messages.ts index b8b2fde967..d01d145178 100644 --- a/src/models/document/ai-evaluation-messages.ts +++ b/src/models/document/ai-evaluation-messages.ts @@ -5,4 +5,8 @@ export const IDEAS_EMPTY_MESSAGE = "Add some work to your document before requesting Ideas"; export const IDEAS_REQUEST_FAILED_MESSAGE = "Something went wrong requesting Ideas. Please try again"; +// Shown while a request is still pending but has stopped looking normal, so a long wait reads as +// unusual rather than as nothing happening. Not a failure: the request may still succeed. +export const IDEAS_SLOW_MESSAGE = "Ada is taking longer than usual..."; export const AI_TILE_EMPTY_MESSAGE = "Add some work to your document to get additional tips on proceeding"; +export const AI_TILE_REQUEST_FAILED_MESSAGE = "Something went wrong getting tips. Please try again"; diff --git a/src/models/document/base-document-content.ts b/src/models/document/base-document-content.ts index 3296f14fdc..8e9c624c01 100644 --- a/src/models/document/base-document-content.ts +++ b/src/models/document/base-document-content.ts @@ -580,6 +580,11 @@ export const BaseDocumentContentModel = RowList.named("BaseDocumentContent") return false; }, + // True once a pending remote comment has waited long enough to look stuck rather than slow. + get isRemoteCommentSlow() { + const doc = getParentWithTypeName(self, "Document"); + return !!doc?.commentsManager?.hasSlowRemoteComment; + }, // An inline status message shown in place of a real AI comment (empty-document nudge, or a // failure message). Client-only: never written to Firestore, so it doesn't survive a reload. get statusMessage() { diff --git a/src/models/document/document-comments-manager.test.ts b/src/models/document/document-comments-manager.test.ts index ad6a4171d1..bf88b2a2b8 100644 --- a/src/models/document/document-comments-manager.test.ts +++ b/src/models/document/document-comments-manager.test.ts @@ -1,7 +1,7 @@ import { isObservable, runInAction } from "mobx"; import { kAnalyzerUserParams } from "../../../shared/shared"; import { DocumentModel, DocumentModelType } from "./document"; -import { CommentWithId, DocumentCommentsManager } from "./document-comments-manager"; +import { CommentWithId, DocumentCommentsManager, kSlowRemoteCommentMs } from "./document-comments-manager"; import { ProblemDocument } from "./document-types"; import { IDEAS_EMPTY_MESSAGE, IDEAS_REQUEST_FAILED_MESSAGE } from "./ai-evaluation-messages"; @@ -710,4 +710,165 @@ describe("DocumentCommentsManager", () => { expect(manager.statusMessage).toBeNull(); }); }); + + // The interim line exists because the hard expiry is pinned to the evaluation function's own + // 120s budget and cannot be lowered — so the only way to signal a stuck request earlier is to + // say the wait has become unusual while still waiting it out. + describe("slow requests", () => { + afterEach(() => { + jest.useRealTimers(); + }); + + const queueAi = (checkCompleted = () => false) => + manager.queueRemoteComment({ triggeredAt: Date.now(), source: "ai", checkCompleted }); + + it("is not slow before the threshold, and is slow after it", async () => { + jest.useFakeTimers(); + queueAi(); + + await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs - 1); + expect(manager.hasSlowRemoteComment).toBe(false); + + await jest.advanceTimersByTimeAsync(1); + expect(manager.hasSlowRemoteComment).toBe(true); + }); + + it("never becomes slow when its comment arrives first", async () => { + jest.useFakeTimers(); + let arrived = false; + queueAi(() => arrived); + + await jest.advanceTimersByTimeAsync(10_000); + arrived = true; + manager.setComments([]); + expect(manager.pendingComments).toHaveLength(0); + + await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs); + expect(manager.hasSlowRemoteComment).toBe(false); + }); + + it("stops being slow once it resolves", async () => { + jest.useFakeTimers(); + let arrived = false; + queueAi(() => arrived); + + await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs); + expect(manager.hasSlowRemoteComment).toBe(true); + + arrived = true; + manager.setComments([]); + expect(manager.hasSlowRemoteComment).toBe(false); + }); + + // The new timer must not disturb the give-up it precedes. + it("still expires and reports failure at 120s", async () => { + jest.useFakeTimers(); + manager.setLatestIdeasRequestId("req-a"); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, requestId: "req-a" + }); + + await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs); + expect(manager.hasSlowRemoteComment).toBe(true); + + await jest.advanceTimersByTimeAsync(120_000 - kSlowRemoteCommentMs); + expect(manager.pendingComments).toHaveLength(0); + expect(manager.hasSlowRemoteComment).toBe(false); + expect(manager.statusMessage).toMatchObject({ message: IDEAS_REQUEST_FAILED_MESSAGE }); + }); + + it("leaves nothing behind when disposed while slow", async () => { + jest.useFakeTimers(); + queueAi(); + await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs); + expect(manager.hasSlowRemoteComment).toBe(true); + + manager.dispose(); + + expect(manager.hasSlowRemoteComment).toBe(false); + expect(manager.pendingComments).toHaveLength(0); + }); + }); + + // The manager holds no document or store reference and should keep none, so it reports that a + // failure happened and the caller decides what to log. + describe("failure reporting", () => { + afterEach(() => { + jest.useRealTimers(); + }); + + it("reports an expiry for the latest click", async () => { + jest.useFakeTimers(); + const onFailure = jest.fn(); + manager.setLatestIdeasRequestId("req-a"); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, + requestId: "req-a", onFailure + }); + + await jest.advanceTimersByTimeAsync(120_000); + + expect(onFailure).toHaveBeenCalledTimes(1); + expect(onFailure).toHaveBeenCalledWith("expired"); + }); + + // An older request giving up is not a failure the student is experiencing — they have already + // clicked again — so it must not be reported either. + it("reports nothing when an older request expires after a newer click", async () => { + jest.useFakeTimers(); + const onFailure = jest.fn(); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, + requestId: "req-a", onFailure + }); + manager.setLatestIdeasRequestId("req-b"); + + await jest.advanceTimersByTimeAsync(120_000); + + expect(onFailure).not.toHaveBeenCalled(); + }); + + it("reports a server-side failure", () => { + const onFailure = jest.fn(); + manager.setLatestIdeasRequestId("req-a"); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, + requestId: "req-a", onFailure + }); + + manager.applyEvaluationStatus({ + outcome: "failed", requestId: "req-a", docUpdated: 1, completedAt: 1 + }); + + expect(onFailure).toHaveBeenCalledWith("server-failed"); + }); + + it("reports nothing for an empty document, which is a nudge and not a failure", () => { + const onFailure = jest.fn(); + manager.setLatestIdeasRequestId("req-a"); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, + requestId: "req-a", onFailure + }); + + manager.applyEvaluationStatus({ + outcome: "skipped-empty", requestId: "req-a", docUpdated: 1, completedAt: 1 + }); + + expect(onFailure).not.toHaveBeenCalled(); + }); + + it("reports nothing when the comment arrives normally", () => { + const onFailure = jest.fn(); + manager.queueRemoteComment({ + triggeredAt: Date.now(), source: "ai", checkCompleted: () => true, + requestId: "req-a", onFailure + }); + + manager.setComments([]); + + expect(manager.pendingComments).toHaveLength(0); + expect(onFailure).not.toHaveBeenCalled(); + }); + }); }); diff --git a/src/models/document/document-comments-manager.ts b/src/models/document/document-comments-manager.ts index edb1cee548..02230dae2e 100644 --- a/src/models/document/document-comments-manager.ts +++ b/src/models/document/document-comments-manager.ts @@ -18,6 +18,16 @@ export const LOCAL_COMMENT = "local"; // up. Comfortably above Shutterbug's ~45s budget plus the model call. const kRemoteCommentExpiryMs = 120_000; +// When a pending request stops looking slow and starts looking stuck. Well short of the expiry +// above, which is pinned to the evaluation function's own 120s budget and so cannot be lowered +// without reporting failure on evaluations that are merely slow. +export const kSlowRemoteCommentMs = 45_000; + +/** Which path gave up on an Ideas request, carried on the failure log so a dead server can be + * told from a dead connection. */ +export type IdeasFailureReason = + "expired" | "server-failed" | "client-deadline" | "client-error"; + export type CommentWithId = WithId; export type PendingCommentType = typeof REMOTE_COMMENT | typeof LOCAL_COMMENT; @@ -37,6 +47,9 @@ export interface IPendingRemoteComment extends IPendingComment { /** Called when this entry leaves the queue, so the caller can detach anything it set up (e.g. a * Realtime Database listener). */ dispose?: () => void; + /** Reports a failure the caller should log. The manager holds no document or store reference and + * should keep none, so it says a failure happened and the caller decides what that means. */ + onFailure?: (reason: IdeasFailureReason) => void; } interface IQueueRemoteCommentParams { @@ -45,6 +58,7 @@ interface IQueueRemoteCommentParams { checkCompleted: (comments: CommentWithId[]) => boolean; requestId?: string; dispose?: () => void; + onFailure?: (reason: IdeasFailureReason) => void; } /** The completion status the analysis pipeline writes for an evaluation request — see @@ -107,10 +121,19 @@ export class DocumentCommentsManager { * empty-document click, until the handler returns). */ ideasClickInProgress = false; + /** Pending remote entries that have passed kSlowRemoteCommentMs. A set of ids rather than a + * flag: a flag would only be correct while canRequestIdeas allows one remote entry at a time, + * and would desync silently the day that gate changes. */ + private slowRemoteCommentIds = new Set(); + constructor() { makeAutoObservable(this, {}, { autoBind: true }); } + get hasSlowRemoteComment() { + return this.slowRemoteCommentIds.size > 0; + } + /** Whether a new Ideas click may make a request: false while one is in progress or an AI * evaluation is pending. The nudge doesn't factor in — an empty click makes no request. */ get canRequestIdeas() { @@ -196,6 +219,10 @@ export class DocumentCommentsManager { runInAction(() => { this.pendingComments = this.pendingComments.filter(p => !ids.has(p.id)); + if (removed.some(p => this.slowRemoteCommentIds.has(p.id))) { + this.slowRemoteCommentIds = new Set( + [...this.slowRemoteCommentIds].filter(slowId => !ids.has(slowId))); + } }); removed.forEach(p => { @@ -203,7 +230,9 @@ export class DocumentCommentsManager { }); } - queueRemoteComment({ triggeredAt, source, checkCompleted, requestId, dispose }: IQueueRemoteCommentParams) { + queueRemoteComment( + { triggeredAt, source, checkCompleted, requestId, dispose, onFailure }: IQueueRemoteCommentParams + ) { const id = `${source}-comment-${nanoid()}`; const timer = setTimeout(() => { @@ -212,12 +241,20 @@ export class DocumentCommentsManager { // rather than letting the bubble vanish unexplained. if (requestId && requestId === this.latestIdeasRequestId) { this.showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE); + onFailure?.("expired"); } this.checkPendingComments(); }, kRemoteCommentExpiryMs); + // Replaced rather than mutated: makeAutoObservable does not make a plain Set's contents + // observable, so an in-place add would not re-render the waiting message. + const slowTimer = setTimeout(() => { + runInAction(() => { this.slowRemoteCommentIds = new Set(this.slowRemoteCommentIds).add(id); }); + }, kSlowRemoteCommentMs); + const wrappedDispose = () => { clearTimeout(timer); + clearTimeout(slowTimer); dispose?.(); }; @@ -229,7 +266,8 @@ export class DocumentCommentsManager { checkCompleted, requestId, expiresAt: Date.now() + kRemoteCommentExpiryMs, - dispose: wrappedDispose + dispose: wrappedDispose, + onFailure }; this.pendingComments.push(pending); @@ -268,13 +306,10 @@ export class DocumentCommentsManager { if (!status?.requestId) return; if (status.outcome === "commented") return; - const matchingIds = new Set( - this.pendingComments - .filter((p): p is IPendingRemoteComment => - p.postingType === REMOTE_COMMENT && p.requestId === status.requestId) - .map(p => p.id) - ); - this.removePendingComments(matchingIds); + const matching = this.pendingComments + .filter((p): p is IPendingRemoteComment => + p.postingType === REMOTE_COMMENT && p.requestId === status.requestId); + this.removePendingComments(new Set(matching.map(p => p.id))); // Only the latest click's status may change what the student sees — an older request // resolving late must not show a message over a click the student already made. @@ -285,6 +320,7 @@ export class DocumentCommentsManager { break; case "failed": this.showStatusMessage(IDEAS_REQUEST_FAILED_MESSAGE); + matching.forEach(p => p.onFailure?.("server-failed")); break; default: { // EvaluationOutcome (shared/shared.ts) gained a value this switch doesn't handle, so @@ -321,5 +357,6 @@ export class DocumentCommentsManager { }); this.comments = []; this.pendingComments = []; + this.slowRemoteCommentIds = new Set(); } } diff --git a/src/plugins/ai/ai-tile.test.tsx b/src/plugins/ai/ai-tile.test.tsx index 8dc26507c2..a7392192ed 100644 --- a/src/plugins/ai/ai-tile.test.tsx +++ b/src/plugins/ai/ai-tile.test.tsx @@ -39,7 +39,9 @@ import { logTileChangeEvent } from "../../models/tiles/log/log-tile-change-event import { LogEventName } from "../../lib/logger-types"; import { defaultAIContent } from "./ai-content"; import { AIComponent } from "./ai-tile"; -import { AI_TILE_EMPTY_MESSAGE } from "../../models/document/ai-evaluation-messages"; +import { + AI_TILE_EMPTY_MESSAGE, AI_TILE_REQUEST_FAILED_MESSAGE +} from "../../models/document/ai-evaluation-messages"; import { DocumentContentModel } from "../../models/document/document-content"; import { ReadOnlyContext } from "../../components/document/read-only-context"; @@ -165,6 +167,7 @@ describe("AIComponent", () => { // classHash is required to reach the request path; the mocks above otherwise return none, so // getAiContent stays null. describe("the request effect, with classHash present", () => { + let rejectOlderRun: (error: Error) => void = () => {}; // Real DocumentContentModel instances: documentHasStudentWork's getSnapshot() call needs a // live MST node, so these tests fail if that call is ever removed. @@ -483,20 +486,19 @@ describe("AIComponent", () => { // previousText here is the model's non-empty authored default, so this distinguishes // "restored" from "left blank" — the next test covers a real prior response. - it("on a populated document, when getAiContent rejects: text is unchanged, Loading is gone, " + - "and nothing escapes as an unhandled rejection", async () => { + it("on a populated document, when getAiContent rejects: the failure message is shown, Loading " + + "is gone, and nothing escapes as an unhandled rejection", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); mockGetAiContent.mockRejectedValueOnce(new Error("network error")); const aiContent = defaultAIContent(); aiContent.setPrompt("What do you think?"); - const previousText = aiContent.text; const aiModel = TileModel.create({ content: aiContent }); const { queryByText } = await act(async () => render( )); - expect(aiContent.text).toBe(previousText); + expect(aiContent.text).toBe(AI_TILE_REQUEST_FAILED_MESSAGE); expect(queryByText("Loading...")).not.toBeInTheDocument(); }); @@ -552,8 +554,51 @@ describe("AIComponent", () => { } }); - it("on a populated document, when a later refresh's getAiContent rejects: a real prior " + - "response survives, not just the authored placeholder", async () => { + // console.error reaches nobody — Rollbar captures uncaught errors, not caught ones — so the + // log event is the only thing that makes a tile failure countable. + it("on a populated document, logs a failed request, and logs nothing for a superseded one", + async () => { + mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); + const aiContent = defaultAIContent(); + aiContent.setPrompt("What do you think?"); + const aiModel = TileModel.create({ content: aiContent }); + + await act(async () => render()); + + (logTileChangeEvent as jest.Mock).mockClear(); + mockGetAiContent.mockRejectedValueOnce(new Error("network error")); + await act(async () => { + aiContent.requestRefresh(); + await Promise.resolve(); + await Promise.resolve(); + }); + + const failures = (logTileChangeEvent as jest.Mock).mock.calls.filter( + ([, params]) => params.operation === "requestFailed"); + expect(failures).toEqual([ + [LogEventName.AI_TOOL_CHANGE, { tileId: aiModel.id, operation: "requestFailed", change: {} }] + ]); + + // A superseded run is not a failure: its rejection must log nothing. + const promiseOlder = new Promise((_resolve, reject) => { rejectOlderRun = reject; }); + mockGetAiContent.mockImplementationOnce(() => promiseOlder); + mockGetAiContent.mockResolvedValueOnce({ data: { text: "newer response" } }); + await act(async () => { aiContent.requestRefresh(); await Promise.resolve(); }); + await act(async () => { aiContent.requestRefresh(); await Promise.resolve(); await Promise.resolve(); }); + + (logTileChangeEvent as jest.Mock).mockClear(); + await act(async () => { + rejectOlderRun(new Error("stale network error")); + await Promise.resolve(); + await Promise.resolve(); + }); + + expect((logTileChangeEvent as jest.Mock).mock.calls.filter( + ([, params]) => params.operation === "requestFailed")).toHaveLength(0); + }); + + it("on a populated document, when a later refresh's getAiContent rejects: the failure message " + + "replaces the prior response rather than leaving it to look untouched", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); const aiContent = defaultAIContent(); aiContent.setPrompt("What do you think?"); @@ -570,13 +615,13 @@ describe("AIComponent", () => { await Promise.resolve(); }); - expect(aiContent.text).toBe("Mocked customized content"); + expect(aiContent.text).toBe(AI_TILE_REQUEST_FAILED_MESSAGE); }); // getAiContent resolves (not rejects) on a server-side failure, a distinct path from the // rejection tests above. it("on a populated document, when a later refresh's response carries a server-side error: " + - "a real prior response survives, and the error is logged", async () => { + "the failure message is shown, and the error is logged", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); const aiContent = defaultAIContent(); aiContent.setPrompt("What do you think?"); @@ -594,7 +639,7 @@ describe("AIComponent", () => { await Promise.resolve(); }); - expect(aiContent.text).toBe("Mocked customized content"); + expect(aiContent.text).toBe(AI_TILE_REQUEST_FAILED_MESSAGE); expect(consoleErrorSpy).toHaveBeenCalledWith("Failed to query AI", expect.any(Error)); consoleErrorSpy.mockRestore(); }); @@ -762,9 +807,11 @@ describe("AIComponent", () => { expect(aiContent.text).toBe("Newer response"); }); - it("a run started while an earlier one is still in flight restores the real text, not that " + - "run's own blank, before capturing its own restore point — so a later failure restores " + - "the real text too", async () => { + // A failure now reports rather than restores, so the restore point is only ever read by the + // top-of-effect undo. This pins that B captured the real text and not A's blank, by letting + // the class context disappear — the remaining path that restores from the captured point. + it("a run started while an earlier one is still in flight captures the real text, not that " + + "run's own blank, as its restore point", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); const aiContent = defaultAIContent(); aiContent.setPrompt("What do you think?"); @@ -776,8 +823,7 @@ describe("AIComponent", () => { expect(aiContent.text).toBe("Mocked customized content"); const promiseA = new Promise<{ data: { text: string } }>((_resolve) => { /* A never settles */ }); - let rejectB: (error: Error) => void; - const promiseB = new Promise((_resolve, reject) => { rejectB = reject; }); + const promiseB = new Promise<{ data: { text: string } }>((_resolve) => { /* B never settles */ }); mockGetAiContent.mockImplementationOnce(() => promiseA); mockGetAiContent.mockImplementationOnce(() => promiseB); @@ -788,18 +834,19 @@ describe("AIComponent", () => { }); expect(aiContent.text).toBe(""); - // B starts before A settles. It must restore the real text — not A's blank — before its own - // request even begins. + // B starts before A settles. It must restore the real text — not A's blank — before + // capturing its own restore point and blanking again. await act(async () => { aiContent.requestRefresh(); await Promise.resolve(); }); expect(queryByText("Loading...")).toBeInTheDocument(); - // B fails: it restores what it actually captured, which must be the real text. + // The class context disappearing makes the next run take the restore branch, which writes + // back whatever B captured. A blank here would mean B had captured A's blank. + mockUserContext = mockUserContextWithoutClassHash; await act(async () => { - rejectB!(new Error("network error")); - await Promise.resolve(); + aiContent.requestRefresh(); await Promise.resolve(); }); diff --git a/src/plugins/ai/ai-tile.tsx b/src/plugins/ai/ai-tile.tsx index e7953299a9..6b04804d21 100644 --- a/src/plugins/ai/ai-tile.tsx +++ b/src/plugins/ai/ai-tile.tsx @@ -14,7 +14,7 @@ import { useStores } from "../../hooks/use-stores"; import { useUserContext } from "../../hooks/use-user-context"; import { DocumentContentModel } from "../../models/document/document-content"; import { getDocumentIdentifier } from "../../models/document/document-utils"; -import { AI_TILE_EMPTY_MESSAGE } from "../../models/document/ai-evaluation-messages"; +import { AI_TILE_EMPTY_MESSAGE, AI_TILE_REQUEST_FAILED_MESSAGE } from "../../models/document/ai-evaluation-messages"; import { liveProblemsFromUnit } from "../../models/curriculum/unit-utils"; import { AIContentModelType, logAiEvent } from "./ai-content"; import { changeSlashesToUnderscores } from "./ai-utils"; @@ -139,12 +139,17 @@ export const AIComponent: React.FC = observer((props) => { setLastUpdated(new Date(timestamp._seconds*1000)); } } catch (error) { - // Restore rather than leave the blank text set above; no-op if nothing was cleared, a - // newer refresh has taken over, or the tile was deleted mid-request — writing to a - // destroyed node would throw and hide the error this is trying to report. - if (isCurrent() && previousTextRef.current !== undefined && isAlive(content)) { - content.setText(previousTextRef.current); + // Say what happened rather than restore the old text, which looks to the student like a + // refresh that did nothing. This message is document content, so it persists and syncs — + // the same tradeoff AI_TILE_EMPTY_MESSAGE makes above; a later refresh overwrites it. + // A superseded run is not a failure, and the newer run's own restore handles it; isAlive + // because writing to a node destroyed mid-request would hide the error being reported. + if (isCurrent() && isAlive(content)) { + content.setText(AI_TILE_REQUEST_FAILED_MESSAGE); previousTextRef.current = undefined; + // The console.error below reaches nobody: Rollbar captures uncaught errors, not caught + // ones. This log is what makes a tile failure countable. + logAiEvent(content, "requestFailed", {}); } console.error("Failed to query AI", error); } finally { From 2b63f2d44aa1883be9c2ed1e314fd2aa5abb3110 Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 14:29:51 -0400 Subject: [PATCH 4/8] CLUE-731: chat reply deadline 45s -> 30s 45s was argued from an estimate of reply latency rather than a measurement, and it is a long time to a student. 30s splits the difference with the 20s the ticket originally asked for. Erring short is the cheaper mistake: a late reply still renders and clears the message, so a tight deadline costs a confusing moment rather than an answer. AI_CHAT_TIMEOUT over AI_CHAT_MESSAGE_SENT gives the rate to retune against instead of guessing again. The Ideas interim line stays at 45s: an Ideas request is normally slower (Shutterbug alone is allowed 45s), so calling it unusual at 30s would be false. The restart test now expresses its advances relative to the constant so the next change to it doesn't break the test. Co-Authored-By: Claude Opus 5 (1M context) --- .../2026-10-27-clue-731-ai-chat-timeout.md | 24 ++++++++------ ...6-10-27-clue-731-ai-chat-timeout-design.md | 31 ++++++++++++------- src/components/chat-tutor/use-chat.test.ts | 6 ++-- src/components/chat-tutor/use-chat.ts | 9 ++++-- 4 files changed, 45 insertions(+), 25 deletions(-) diff --git a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md index abfb3b7bf5..4ac817c5c5 100644 --- a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md +++ b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md @@ -2,7 +2,7 @@ > **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. -**Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever, and no AI failure is invisible to the team. The chat gets a 45s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, the AI tile reports a failed request instead of silently restoring its old text, and every one of those failures emits a log event. +**Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever, and no AI failure is invisible to the team. The chat gets a 30s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, the AI tile reports a failed request instead of silently restoring its old text, and every one of those failures emits a log event. **Architecture:** The chat deadline lives in `useChat`, the single place `pending` is derived, so it covers both transports without touching `FirestoreTransport.emitStatus`'s status precedence. The Ideas interim line is a second timer inside `queueRemoteComment`, clearing through the existing `wrappedDispose` so `removePendingComments` stays the only path an entry leaves the queue by. Logging reaches the static `Logger.log`, which queues until the logger initializes, so the chat needs no store access; the comments manager stays free of document/store coupling by taking an `onFailure` callback rather than logging itself. Separately, `FirestoreTransport` stops recording the last-sent workspace hash in completion order. @@ -16,7 +16,7 @@ | File | Responsibility | |---|---| -| `src/components/chat-tutor/use-chat.ts` *(modify)* | The 45s reply deadline, `timedOut` in the result, the timeout message constant | +| `src/components/chat-tutor/use-chat.ts` *(modify)* | The reply deadline, `timedOut` in the result, the timeout message constant | | `src/components/chat-tutor/use-chat.test.ts` *(create)* | Deadline fires, restarts per message, clears on a late reply and on transport swap | | `src/components/chat-tutor/chat.tsx` *(modify)* | Render the timeout row; keep the live region from re-announcing the previous reply | | `src/components/chat-tutor/chat-timeout.test.tsx` *(create)* | `Chat` renders the timeout row and no typing dots | @@ -85,9 +85,11 @@ Cases to assert: 2. **Fires at the deadline** — emit a user turn and `status: "generating"`, advance `kReplyDeadlineMs`; `pending` is false and `timedOut` is true. Also assert `pending` was still true one millisecond earlier, so the test pins the boundary rather than just "eventually." -3. **Restarts on a new message** — go pending, advance 40s, emit a second user turn, advance 40s; - `timedOut` is still false (total elapsed 80s, but only 40s since the newest message). This is - the case a `waiting`-only dependency list gets wrong. +3. **Restarts on a new message** — go pending, advance to just short of the deadline, emit a + second user turn, advance that far again; `timedOut` is still false (well past one deadline in + total, but not since the newest message). Express the advances as offsets from + `kReplyDeadlineMs` rather than literals, so the constant can move without breaking the test. + This is the case a `waiting`-only dependency list gets wrong. 4. **A late reply clears it** — let it time out, then emit an assistant turn and `status: "idle"`; `timedOut` returns to false and the turn is in `turns`. 5. **Transport swap resets** — rerender the hook with a second transport while timed out; @@ -104,8 +106,12 @@ In `use-chat.ts`, add the constants near the existing message string: // How long the client waits for a reply before it stops claiming Ada is working. Nothing on the // client can tell a dead turn from a slow one — the drain writes its assistant document and its // cursor in one batch, so a drain that died writes neither — which is why this is a deadline and -// not a smarter reading of status. A reply carrying document context routinely takes 10-25s. -export const kReplyDeadlineMs = 45_000; +// not a smarter reading of status. +// +// 30s is a compromise between a student's patience and a slow but healthy reply. Erring short is +// the cheaper mistake: a late reply still renders and clears the message. AI_CHAT_TIMEOUT over +// AI_CHAT_MESSAGE_SENT gives the rate this should be retuned against. +export const kReplyDeadlineMs = 30_000; // Deliberately distinct from the status:"error" message below: the backend reporting an error and // the backend reporting nothing are different failures, and support cannot tell them apart if @@ -648,7 +654,7 @@ compile — a long-lived dev server that has seen branch switches serves a stale current (see CLAUDE.md). Open the chat and send a message with the network offline (DevTools → Network → Offline) or with -the chat trigger disabled, then watch: the dots stop at 45s and the message appears, the composer +the chat trigger disabled, then watch: the dots stop at 30s and the message appears, the composer still accepts a message, and sending again restarts the dots. - [ ] **Step 4: Run `/code-self-review` over the full diff** @@ -666,7 +672,7 @@ Commit locally. Do not push until the user has checked it on localhost or said t | Risk | Handling | |---|---| -| 45s cuts off a legitimately slow reply | The reply still renders when it arrives; the message row clears with it. Nothing is discarded. If real traffic shows 45s is too tight, the constant is one line — but do not make it authorable without evidence. | +| 30s cuts off a legitimately slow reply | The reply still renders when it arrives; the message row clears with it. Nothing is discarded. `AI_CHAT_TIMEOUT` over `AI_CHAT_MESSAGE_SENT` is the rate to retune against — the constant is one line, but do not make it authorable without that evidence. | | The live region announces a stale reply on timeout | Explicitly covered: Task 2 Step 3 guards it, Task 2 Step 2 case 4 tests it. | | The slow-entry set desyncs from `pendingComments` | Both the 45s and 120s timers clear through `wrappedDispose`, and `removePendingComments` stays the single exit path. Task 5 Step 1 case 5 tests `dispose()` while slow. | | The AI tile failure message persists in document content | Stated and accepted in the spec; follows `AI_TILE_EMPTY_MESSAGE`'s existing precedent. Revisit only if a student reports a stuck error in a saved document. | diff --git a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md index e30d8760f3..92826ffe58 100644 --- a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md +++ b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md @@ -49,13 +49,15 @@ governed what this student sees now. **In** -- A 45-second client-side reply deadline for the Ada chat sidebar, with a visible message. +- A 30-second client-side reply deadline for the Ada chat sidebar, with a visible message. - Send-order (not completion-order) bookkeeping of the last-sent workspace hash in `FirestoreTransport`. - A regression test pinning the existing guarantee that a document edit cannot reach an in-flight chat turn. - A 45-second "taking longer than usual" interim line for the Ideas / document-evaluation waiting - message, with the existing 120s hard expiry unchanged. + message, with the existing 120s hard expiry unchanged. Deliberately not the chat's 30s: an Ideas + request is normally slower (Shutterbug alone is allowed 45s), so calling it unusual at 30s would + be false. - A visible failure message in the AI tile when its request fails. - A log event for every AI failure: chat timeout, chat unavailable, Ideas failure, AI tile failure — plus a chat "message sent" event, so a failure count has a denominator. @@ -70,7 +72,7 @@ governed what this student sees now. - **A Retry button in the chat.** The composer is already enabled during a pending reply, so retrying costs a retype, not a dead end. A real retry button has to decide what happens when the first turn lands late, which is a bigger question than this story. -- **Making the chat timeout authorable per unit.** One constant until there is evidence 45s is +- **Making the chat timeout authorable per unit.** One constant until the timeout rate shows it is wrong for some unit. - **The teacher-facing AI class summary** (`src/components/navigation/ai-summary.tsx`). It has its own `checking`/`generating` status machine and no reported wedge. Separate story if it needs one. @@ -93,15 +95,20 @@ should be made to wait" is a UI judgment, and `emitStatus`'s three-way precedenc that threading a fourth state through it would cost more than it buys. **Restart condition.** The timer restarts when the hook starts waiting **and whenever the newest -turn changes** — not on `waiting` alone. A student who sends a second message at 40s would -otherwise inherit the first message's clock and be told "Ada didn't answer" five seconds later, +turn changes** — not on `waiting` alone. A student who sends a second message late in the wait +would otherwise inherit the first message's clock and be told "Ada didn't answer" seconds later, about a message sent moments ago. Keying on the newest turn's id works because the id comes from `messagesRef().add()`, which mints it client-side; the optimistic snapshot and the confirmed one carry the same id, so the id changes exactly once per message. -**Value.** 45 seconds. A real reply carrying document context routinely takes 10–25s, so the -ticket's literal 20s would cut off healthy turns. 45s is unambiguously abnormal without being a -wait. +**Value.** 30 seconds, between the ticket's 20s and the 45s first proposed here. 45s was argued +from an estimate of reply latency, not a measurement, and 45s is a long time to a student. + +Erring short is the cheaper mistake: a late reply still renders and clears the message, so a +too-tight deadline costs a confusing moment rather than an answer. And this is the one number in +the story that the logging makes empirically revisable — `AI_CHAT_TIMEOUT` over +`AI_CHAT_MESSAGE_SENT` is the timeout rate, so a week of classroom use settles whether 30s cuts +off healthy replies. **On expiry.** `pending` goes false — the dots stop and the "Ada is typing" live region clears. A message row appears reading *"Ada didn't answer. Please try again."* The composer needs no @@ -227,7 +234,7 @@ introducing a fourth name for researchers to learn. | Constant | Value | Home | |---|---|---| -| `kReplyDeadlineMs` | `45_000` | `src/components/chat-tutor/use-chat.ts` | +| `kReplyDeadlineMs` | `30_000` | `src/components/chat-tutor/use-chat.ts` | | `kTimeoutMessage` | "Ada didn't answer. Please try again." | `src/components/chat-tutor/use-chat.ts` | | `kSlowRemoteCommentMs` | `45_000` | `src/models/document/document-comments-manager.ts` | | `IDEAS_SLOW_MESSAGE` | "Ada is taking longer than usual..." | `src/models/document/ai-evaluation-messages.ts` | @@ -243,7 +250,7 @@ already living in the hook. | Event | Fires when | Payload | |---|---|---| | `AI_CHAT_MESSAGE_SENT` | a user message reaches Firestore | conversation id, document key, problem path | -| `AI_CHAT_TIMEOUT` | the 45s reply deadline fires | conversation id, document key, problem path | +| `AI_CHAT_TIMEOUT` | the reply deadline fires | conversation id, document key, problem path | | `AI_CHAT_UNAVAILABLE` | the transport reports `status: "error"` | conversation id, document key, problem path | | `IDEAS_REQUEST_FAILED` | the 15s foreground deadline, the 120s expiry, or a `"failed"` server outcome | document key, problem path, request id, which of the three | | `AI_TOOL_CHANGE` *(existing)* | the AI tile's request fails | tile id, `operation: "requestFailed"` | @@ -255,7 +262,7 @@ message text, prompt text, document content or the raw server error string. | Test | Covers | |---|---| -| `use-chat.test.ts` *(new)* | Deadline fires at 45s; `pending` goes false; `timedOut` set. Timer restarts on a new turn. Late reply clears the timeout and renders. Transport swap resets. No timeout while idle. | +| `use-chat.test.ts` *(new)* | Deadline fires at `kReplyDeadlineMs`; `pending` goes false; `timedOut` set. Timer restarts on a new turn. Late reply clears the timeout and renders. Transport swap resets. No timeout while idle. | | `firestore-transport.test.ts` | Overlapping sends record the hash in send order; a failed write restores the prior hash; a failed write superseded by a newer send does not. | | `firestore-transport.test.ts` | Regression: a document mutated between send and write resolution does not change what that message carried. | | `document-comments-manager.test.ts` | Slow set populated at 45s, cleared on resolve, on expiry, and on `dispose`. | @@ -267,7 +274,7 @@ message text, prompt text, document content or the raw server error string. | all of the above | No logged payload contains message text, prompt text or document content. | No Cypress work: all four behaviors are timer-driven and are exercised honestly with Jest fake -timers. A Cypress spec would have to wait 45 real seconds to prove anything. +timers. A Cypress spec would have to wait the real deadline out to prove anything. ## Delivery diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts index d341477da3..786dd69627 100644 --- a/src/components/chat-tutor/use-chat.test.ts +++ b/src/components/chat-tutor/use-chat.test.ts @@ -74,12 +74,14 @@ describe("useChat reply deadline", () => { const t = stubTransport(); const { result } = renderChat(t.transport); + const nearlyDue = kReplyDeadlineMs - 5_000; + t.turns([userTurn("m1")]); t.status("generating"); - advance(40_000); + advance(nearlyDue); t.turns([userTurn("m1"), userTurn("m2")]); - advance(40_000); // 80s since the first message, 40s since the second + advance(nearlyDue); // well past one deadline in total, but not since the second message expect(result.current.timedOut).toBe(false); diff --git a/src/components/chat-tutor/use-chat.ts b/src/components/chat-tutor/use-chat.ts index 6da120dc54..8342929d4d 100644 --- a/src/components/chat-tutor/use-chat.ts +++ b/src/components/chat-tutor/use-chat.ts @@ -6,8 +6,13 @@ import { LogEventName } from "../../lib/logger-types"; // How long the client waits for a reply before it stops claiming Ada is working. Nothing on the // client can tell a dead turn from a slow one -- the drain writes its assistant document and its // cursor in one batch, so a drain that died writes neither -- which is why this is a deadline and -// not a smarter reading of status. A reply carrying document context routinely takes 10-25s. -export const kReplyDeadlineMs = 45_000; +// not a smarter reading of status. +// +// 30s is a compromise between a student's patience and a slow but healthy reply. Erring short is +// the cheaper mistake: a late reply still renders and clears the message, so a tight deadline +// costs a confusing moment rather than an answer. AI_CHAT_TIMEOUT over AI_CHAT_MESSAGE_SENT gives +// the timeout rate this should be retuned against, rather than guessing again. +export const kReplyDeadlineMs = 30_000; // Distinct from the status:"error" message below: the backend reporting an error and the backend // reporting nothing are different failures, and support can't tell them apart if they read alike. From bd358c2d3466f68bb0e7176da4febb5a007964a8 Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 14:37:47 -0400 Subject: [PATCH 5/8] CLUE-731: self-review pass over the test files - ai-tile: rejectOlderRun was hoisted to describe scope for one test, leaving it visible to every sibling; moved inside, matching the file's own rejectOlder convention two tests down. - use-chat: the Logger mock was only cleared for the logging block, so a stale call from a deadline test could have quietly satisfied an assertion added later. Cleared for every test, and the two near-identical render helpers folded into one. - document-comments-manager: five copies of jest.useFakeTimers() in a block where every test needs it, hoisted into beforeEach. Co-Authored-By: Claude Opus 5 (1M context) --- src/components/chat-tutor/use-chat.test.ts | 25 +++++++++---------- .../document-comments-manager.test.ts | 8 +++--- src/plugins/ai/ai-tile.test.tsx | 4 +-- 3 files changed, 17 insertions(+), 20 deletions(-) diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts index 786dd69627..c93faa8bd3 100644 --- a/src/components/chat-tutor/use-chat.test.ts +++ b/src/components/chat-tutor/use-chat.test.ts @@ -1,6 +1,6 @@ import { act, renderHook } from "@testing-library/react"; import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; -import { kReplyDeadlineMs, useChat } from "./use-chat"; +import { ChatLogContext, kReplyDeadlineMs, useChat } from "./use-chat"; import { Logger } from "../../lib/logger"; import { LogEventName } from "../../lib/logger-types"; @@ -35,12 +35,18 @@ const userTurn = (id: string): ChatTurn => ({ id, sender: "user", text: "help" } const assistantTurn = (id: string): ChatTurn => ({ id, sender: "assistant", text: "here you go" }); const advance = (ms: number) => act(() => { jest.advanceTimersByTime(ms); }); -const renderChat = (transport: ChatTransport) => - renderHook(() => useChat({ transport, header: "Doc · 1.1" })); +const renderChat = (transport: ChatTransport, logContext?: ChatLogContext) => + renderHook(() => useChat({ transport, header: "Doc · 1.1", logContext })); + +// Cleared for every test, not just the logging block below: the deadline tests log too, and a +// stale call from one of them would quietly satisfy an assertion added here later. +beforeEach(() => { + jest.useFakeTimers(); + mockLog.mockClear(); +}); +afterEach(() => jest.useRealTimers()); describe("useChat reply deadline", () => { - beforeEach(() => jest.useFakeTimers()); - afterEach(() => jest.useRealTimers()); it("never times out while idle", () => { const t = stubTransport(); @@ -132,18 +138,11 @@ describe("useChat reply deadline", () => { describe("useChat logging", () => { const logContext = { conversationId: "conv-1", documentKey: "doc-1" }; - const renderWithContext = (transport: ChatTransport) => - renderHook(() => useChat({ transport, header: "Doc · 1.1", logContext })); + const renderWithContext = (transport: ChatTransport) => renderChat(transport, logContext); const eventsNamed = (event: LogEventName) => mockLog.mock.calls.filter(([e]) => e === event); - beforeEach(() => { - jest.useFakeTimers(); - mockLog.mockClear(); - }); - afterEach(() => jest.useRealTimers()); - it("logs the timeout exactly once, however many renders follow", () => { const t = stubTransport(); const { rerender } = renderWithContext(t.transport); diff --git a/src/models/document/document-comments-manager.test.ts b/src/models/document/document-comments-manager.test.ts index bf88b2a2b8..c35b02b862 100644 --- a/src/models/document/document-comments-manager.test.ts +++ b/src/models/document/document-comments-manager.test.ts @@ -715,6 +715,9 @@ describe("DocumentCommentsManager", () => { // 120s budget and cannot be lowered — so the only way to signal a stuck request earlier is to // say the wait has become unusual while still waiting it out. describe("slow requests", () => { + beforeEach(() => { + jest.useFakeTimers(); + }); afterEach(() => { jest.useRealTimers(); }); @@ -723,7 +726,6 @@ describe("DocumentCommentsManager", () => { manager.queueRemoteComment({ triggeredAt: Date.now(), source: "ai", checkCompleted }); it("is not slow before the threshold, and is slow after it", async () => { - jest.useFakeTimers(); queueAi(); await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs - 1); @@ -734,7 +736,6 @@ describe("DocumentCommentsManager", () => { }); it("never becomes slow when its comment arrives first", async () => { - jest.useFakeTimers(); let arrived = false; queueAi(() => arrived); @@ -748,7 +749,6 @@ describe("DocumentCommentsManager", () => { }); it("stops being slow once it resolves", async () => { - jest.useFakeTimers(); let arrived = false; queueAi(() => arrived); @@ -762,7 +762,6 @@ describe("DocumentCommentsManager", () => { // The new timer must not disturb the give-up it precedes. it("still expires and reports failure at 120s", async () => { - jest.useFakeTimers(); manager.setLatestIdeasRequestId("req-a"); manager.queueRemoteComment({ triggeredAt: Date.now(), source: "ai", checkCompleted: () => false, requestId: "req-a" @@ -778,7 +777,6 @@ describe("DocumentCommentsManager", () => { }); it("leaves nothing behind when disposed while slow", async () => { - jest.useFakeTimers(); queueAi(); await jest.advanceTimersByTimeAsync(kSlowRemoteCommentMs); expect(manager.hasSlowRemoteComment).toBe(true); diff --git a/src/plugins/ai/ai-tile.test.tsx b/src/plugins/ai/ai-tile.test.tsx index a7392192ed..7717703584 100644 --- a/src/plugins/ai/ai-tile.test.tsx +++ b/src/plugins/ai/ai-tile.test.tsx @@ -167,7 +167,6 @@ describe("AIComponent", () => { // classHash is required to reach the request path; the mocks above otherwise return none, so // getAiContent stays null. describe("the request effect, with classHash present", () => { - let rejectOlderRun: (error: Error) => void = () => {}; // Real DocumentContentModel instances: documentHasStudentWork's getSnapshot() call needs a // live MST node, so these tests fail if that call is ever removed. @@ -580,6 +579,7 @@ describe("AIComponent", () => { ]); // A superseded run is not a failure: its rejection must log nothing. + let rejectOlderRun: (error: Error) => void; const promiseOlder = new Promise((_resolve, reject) => { rejectOlderRun = reject; }); mockGetAiContent.mockImplementationOnce(() => promiseOlder); mockGetAiContent.mockResolvedValueOnce({ data: { text: "newer response" } }); @@ -588,7 +588,7 @@ describe("AIComponent", () => { (logTileChangeEvent as jest.Mock).mockClear(); await act(async () => { - rejectOlderRun(new Error("stale network error")); + rejectOlderRun!(new Error("stale network error")); await Promise.resolve(); await Promise.resolve(); }); From 3f9c0fba99634e22219bf4176dbabe02fcff927d Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 15:25:29 -0400 Subject: [PATCH 6/8] CLUE-731: fix three defects found in code review 1. A wedged conversation re-armed the deadline on every reopen, because isAwaitingReply is computed over rehydrated history and the sidebar unmounts when closed. Each reopen logged another AI_CHAT_TIMEOUT against a denominator that counted the send once, inflating the very rate the 30s constant is meant to be retuned against. The message still shows every time -- the conversation really is unanswered -- but the log is now paired to a send made in this session. 2. The AI tile's failure message is document content, saved and synced. The effect fires an automatic refresh on mount, so a transient failure there replaced a good prior answer with an error the student never asked for and the teacher would see. A student-requested refresh still reports; an automatic one restores, as it did before. This also restores the previousTextRef guard on that path, so an error thrown before the text is blanked no longer overwrites intact content. 3. If two overlapping sends both failed and the earlier rejected first, the later send's rollback restored the earlier (also failed) send's hash, claiming a workspace the server never received. A later send at that same hash would then attach nothing. The claim is now cleared rather than restored, costing at most one redundant re-attach. Co-Authored-By: Claude Opus 5 (1M context) --- .../chat-tutor/firestore-transport.test.ts | 26 ++++++++++++++ .../chat-tutor/firestore-transport.ts | 12 ++++--- src/components/chat-tutor/use-chat.test.ts | 34 +++++++++++++++++-- src/components/chat-tutor/use-chat.ts | 12 +++++-- src/plugins/ai/ai-tile.test.tsx | 32 +++++++++++++++-- src/plugins/ai/ai-tile.tsx | 29 ++++++++++++---- 6 files changed, 127 insertions(+), 18 deletions(-) diff --git a/src/components/chat-tutor/firestore-transport.test.ts b/src/components/chat-tutor/firestore-transport.test.ts index 7a75c54e8a..2a075f2532 100644 --- a/src/components/chat-tutor/firestore-transport.test.ts +++ b/src/components/chat-tutor/firestore-transport.test.ts @@ -393,6 +393,32 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () expect(added[2]).not.toHaveProperty("rightContext"); }); + // Both sends failing means the student was offline; neither message landed. Restoring the + // earlier send's hash would claim a workspace the server never received, so the next send that + // DID land would carry no workspace and the tutor would answer blind to the student's work. + it("claims nothing when two overlapping sends both fail", async () => { + const { added, settle, transport, edit } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); // claims W1 + edit("W2", "H2"); + const second = transport.sendUserMessage("two"); // claims W2, remembers W1 + + settle[0].reject(new Error("offline")); + await expect(first).rejects.toThrow("offline"); + settle[1].reject(new Error("offline")); + await expect(second).rejects.toThrow("offline"); + + // The student undoes the edit, so the document is back at the workspace the FIRST (also + // failed) send claimed. Restoring that claim on the second send's rollback would make this + // send attach nothing, and the server has never seen any workspace at all. + edit("W1", "H1"); + const third = transport.sendUserMessage("three"); + settle[2].resolve(); + await third; + + expect(added[2].rightContext).toBe("W1"); + }); + // Nothing retroactively tells an in-flight turn about an edit: the payload is computed before // the write. Pinned here because the guarantee is load-bearing and invisible from the call site. it("does not change what a message carried when the document is edited mid-send", async () => { diff --git a/src/components/chat-tutor/firestore-transport.ts b/src/components/chat-tutor/firestore-transport.ts index c6788186c1..20e56f132c 100644 --- a/src/components/chat-tutor/firestore-transport.ts +++ b/src/components/chat-tutor/firestore-transport.ts @@ -236,7 +236,6 @@ export class FirestoreTransport implements ChatTransport { // the ForeverLearning path. The composer stays open during a pending reply so a student can // escape a wedged turn, so overlapping sends are expected, not exotic. const claimedRight = decision.attachRight ? right : undefined; - const previousRightHash = this.lastSentRightHash; if (claimedRight) { this.lastSentRightHash = claimedRight.hash; } @@ -244,11 +243,16 @@ export class FirestoreTransport implements ChatTransport { try { await this.messagesRef().add(message); } catch (e) { - // The workspace never left the client, so the record has to go back — but only if this send - // is still the one holding it. `claimedRight` is what separates this from an unchanged send, + // The workspace never left the client, so the claim has to go — but only if this send is + // still the one holding it. `claimedRight` is what separates this from an unchanged send, // whose hash matches precisely because it attached nothing. + // + // Cleared rather than restored to the previous hash: with two sends in flight that previous + // one may itself have failed, and restoring it would claim a delivery that never happened, + // leaving the next send to omit the workspace entirely. Clearing costs at most one redundant + // re-attach, which is the cheaper way to be wrong. if (claimedRight && this.lastSentRightHash === claimedRight.hash) { - this.lastSentRightHash = previousRightHash; + this.lastSentRightHash = undefined; } throw e; } diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts index c93faa8bd3..2201f3da2f 100644 --- a/src/components/chat-tutor/use-chat.test.ts +++ b/src/components/chat-tutor/use-chat.test.ts @@ -143,10 +143,11 @@ describe("useChat logging", () => { const eventsNamed = (event: LogEventName) => mockLog.mock.calls.filter(([e]) => e === event); - it("logs the timeout exactly once, however many renders follow", () => { + it("logs the timeout exactly once, however many renders follow", async () => { const t = stubTransport(); - const { rerender } = renderWithContext(t.transport); + const { result, rerender } = renderWithContext(t.transport); + await act(async () => { await result.current.sendMessage("how do I start?"); }); t.turns([userTurn("m1")]); t.status("generating"); advance(kReplyDeadlineMs); @@ -195,6 +196,35 @@ describe("useChat logging", () => { expect(eventsNamed(LogEventName.AI_CHAT_MESSAGE_SENT)).toHaveLength(0); }); + // A wedged conversation re-arms the deadline every time the sidebar is reopened, because + // isAwaitingReply is computed over rehydrated history. The message must still appear — the + // conversation really is unanswered — but counting it again would inflate the timeout rate + // against a denominator that counted the send once. + it("shows the timeout for a conversation already waiting on open, but does not log it", () => { + const t = stubTransport(); + const { result } = renderChat(t.transport, logContext); + + // No send in this session: this is rehydrated history for a turn sent earlier. + t.turns([userTurn("m1")]); + t.status("generating"); + advance(kReplyDeadlineMs); + + expect(result.current.timedOut).toBe(true); + expect(eventsNamed(LogEventName.AI_CHAT_TIMEOUT)).toHaveLength(0); + }); + + it("logs the timeout for a message sent in this session", async () => { + const t = stubTransport(); + const { result } = renderChat(t.transport, logContext); + + await act(async () => { await result.current.sendMessage("how do I start?"); }); + t.turns([userTurn("m1")]); + t.status("generating"); + advance(kReplyDeadlineMs); + + expect(eventsNamed(LogEventName.AI_CHAT_TIMEOUT)).toHaveLength(1); + }); + // These logs reach a research database and Rollbar. Student writing belongs in neither, and a // failure rate does not need it. it("never puts the student's message into a log payload", async () => { diff --git a/src/components/chat-tutor/use-chat.ts b/src/components/chat-tutor/use-chat.ts index 8342929d4d..49d6380b6a 100644 --- a/src/components/chat-tutor/use-chat.ts +++ b/src/components/chat-tutor/use-chat.ts @@ -1,4 +1,4 @@ -import { useCallback, useEffect, useState } from "react"; +import { useCallback, useEffect, useRef, useState } from "react"; import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; import { Logger } from "../../lib/logger"; import { LogEventName } from "../../lib/logger-types"; @@ -49,6 +49,12 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC const [status, setStatus] = useState("idle"); const [error, setError] = useState(null); const [timedOut, setTimedOut] = useState(false); + // Whether the student sent anything during this mount. isAwaitingReply is computed over + // rehydrated history and the sidebar unmounts when closed, so an already-wedged conversation + // re-arms the deadline every time it is reopened. The message should still appear each time — + // the conversation really is unanswered — but counting those would inflate AI_CHAT_TIMEOUT with + // repeat views of one failure, against a denominator that counts the send once. + const sentThisSessionRef = useRef(false); // Re-subscribe whenever the transport instance changes — this is the hard // conversation swap when the student switches documents or problems. @@ -58,6 +64,7 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC setError(null); setStatus("idle"); setTurns([]); + sentThisSessionRef.current = false; return transport.subscribe(setTurns, setStatus); }, [transport]); @@ -83,7 +90,7 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC if (!waiting) return; const timer = setTimeout(() => { setTimedOut(true); - Logger.log(LogEventName.AI_CHAT_TIMEOUT, { ...logContext }); + if (sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_TIMEOUT, { ...logContext }); }, kReplyDeadlineMs); return () => clearTimeout(timer); }, [waiting, newestTurnId, logContext]); @@ -98,6 +105,7 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC await transport.sendUserMessage(trimmed); // Only once the write landed, so the denominator counts messages the backend could // actually have answered. + sentThisSessionRef.current = true; Logger.log(LogEventName.AI_CHAT_MESSAGE_SENT, { ...logContext }); } catch (e) { setError((e as Error)?.message || "Failed to send your message. Please try again."); diff --git a/src/plugins/ai/ai-tile.test.tsx b/src/plugins/ai/ai-tile.test.tsx index 7717703584..41daaac134 100644 --- a/src/plugins/ai/ai-tile.test.tsx +++ b/src/plugins/ai/ai-tile.test.tsx @@ -485,22 +485,48 @@ describe("AIComponent", () => { // previousText here is the model's non-empty authored default, so this distinguishes // "restored" from "left blank" — the next test covers a real prior response. - it("on a populated document, when getAiContent rejects: the failure message is shown, Loading " + - "is gone, and nothing escapes as an unhandled rejection", async () => { + // The student did not ask for the mount-time refresh, so a transient failure there must not + // replace a good prior answer with an error -- which is document content, saved, synced and + // visible to the teacher. + it("on a populated document, when the automatic mount refresh rejects: the previous text is " + + "restored, Loading is gone, and nothing escapes as an unhandled rejection", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); mockGetAiContent.mockRejectedValueOnce(new Error("network error")); const aiContent = defaultAIContent(); aiContent.setPrompt("What do you think?"); + const previousText = aiContent.text; const aiModel = TileModel.create({ content: aiContent }); const { queryByText } = await act(async () => render( )); - expect(aiContent.text).toBe(AI_TILE_REQUEST_FAILED_MESSAGE); + expect(aiContent.text).toBe(previousText); expect(queryByText("Loading...")).not.toBeInTheDocument(); }); + // The student clicked Update, so restoring the old text would look exactly like a refresh + // that did nothing. This is the case the durable message exists for. + it("on a populated document, when a student-requested refresh rejects: the failure message " + + "is shown", async () => { + mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); + const aiContent = defaultAIContent(); + aiContent.setPrompt("What do you think?"); + const aiModel = TileModel.create({ content: aiContent }); + + await act(async () => render()); + expect(aiContent.text).toBe("Mocked customized content"); + + mockGetAiContent.mockRejectedValueOnce(new Error("network error")); + await act(async () => { + aiContent.requestRefresh(); + await Promise.resolve(); + await Promise.resolve(); + }); + + expect(aiContent.text).toBe(AI_TILE_REQUEST_FAILED_MESSAGE); + }); + // The tile can be deleted while a request is in flight. Pins that the catch block's isAlive // guard keeps the original error from being hidden by a write to the now-destroyed node, and // from escaping as an unhandled rejection. diff --git a/src/plugins/ai/ai-tile.tsx b/src/plugins/ai/ai-tile.tsx index 6b04804d21..b37ba0bab1 100644 --- a/src/plugins/ai/ai-tile.tsx +++ b/src/plugins/ai/ai-tile.tsx @@ -58,6 +58,10 @@ export const AIComponent: React.FC = observer((props) => { const generation = ++requestGenerationRef.current; const isCurrent = () => requestGenerationRef.current === generation; + // refreshCount is stripped by exportJson, so a freshly loaded tile starts at 0 and this is + // true only once the student has actually clicked Update. It decides whether a failure is + // theirs to see -- see the catch below. + const userRequested = content.refreshCount > 0; // Undo a superseded run's own blanking before anything else runs, so this run starts from real // text — otherwise this run's own capture below would save the blank, not the good text. if (previousTextRef.current !== undefined) { @@ -139,16 +143,27 @@ export const AIComponent: React.FC = observer((props) => { setLastUpdated(new Date(timestamp._seconds*1000)); } } catch (error) { - // Say what happened rather than restore the old text, which looks to the student like a - // refresh that did nothing. This message is document content, so it persists and syncs — - // the same tradeoff AI_TILE_EMPTY_MESSAGE makes above; a later refresh overwrites it. + // A student who clicked Update is owed a visible answer: restoring the old text would + // look exactly like a refresh that did nothing. The message is document content, so it + // persists and syncs — the same tradeoff AI_TILE_EMPTY_MESSAGE makes above. + // + // The automatic refresh this effect fires on mount is NOT something the student asked + // for, and writing a failure there would replace a good prior answer with an error over + // a transient hiccup — saved, synced, and in front of the teacher. That case restores, + // which is what the tile did before this message existed. + // // A superseded run is not a failure, and the newer run's own restore handles it; isAlive // because writing to a node destroyed mid-request would hide the error being reported. if (isCurrent() && isAlive(content)) { - content.setText(AI_TILE_REQUEST_FAILED_MESSAGE); - previousTextRef.current = undefined; - // The console.error below reaches nobody: Rollbar captures uncaught errors, not caught - // ones. This log is what makes a tile failure countable. + if (userRequested) { + content.setText(AI_TILE_REQUEST_FAILED_MESSAGE); + previousTextRef.current = undefined; + } else if (previousTextRef.current !== undefined) { + content.setText(previousTextRef.current); + previousTextRef.current = undefined; + } + // Logged either way: the console.error below reaches nobody, since Rollbar captures + // uncaught errors and not caught ones, and an automatic failure is still a failure. logAiEvent(content, "requestFailed", {}); } console.error("Failed to query AI", error); From 32b067c31a2b171734bd7d4f2f8291924f6fc188 Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Wed, 28 Oct 2026 16:08:42 -0400 Subject: [PATCH 7/8] CLUE-731: address Copilot and CodeRabbit review Privacy, where the PR's stated payload contract was simply wrong: - IDEAS_REQUEST_FAILED went through logDocumentEvent, which expands the document into documentTitle and documentProperties -- both student-authored. Now Logger.log with an explicit field list; documentKey still joins a failure to its REQUEST_IDEA. - The AI tile failure went through logAiEvent -> logTileBaseEvent, which for a tile inside a Question tile also emits QUESTION_ANSWERS_CHANGE carrying the question prompt and the sibling answers. It now has its own event, AI_TILE_REQUEST_FAILED, which cannot cascade -- and a failed request was never an answer change in the first place. Correctness: - Firestore resolves add() only on backend acknowledgement, so an offline write stays pending forever. `sending` never cleared, leaving the composer disabled and the dots running past the deadline meant to end them -- the exact scenario this feature exists for. The composer is now released on the same deadline; the write is left running and still reconciles. - Claiming lastSentRightHash before delivery let a concurrent send skip a workspace whose only carrier then failed, and the tutor would answer that turn blind to the student's work. Recorded on acknowledgement now, with a sequence number so a late older send can't overwrite a newer record. The bug this replaces only ever cost redundant bytes; this one cost context. - refreshCount > 0 is click history, not "this run was requested", so any later rerun -- a remount, a context change -- could let an automatic failure overwrite a good saved answer. Compared against the previous run's count. - AI_CHAT_UNAVAILABLE re-logged on every reopen of a failed conversation, the same inflation already fixed for the timeout. Gated on a send in session. Not changed: REQUEST_IDEA still logs after its foreground work, so a client-deadline or client-error failure can precede its own attempt event. Moving it would change when the exemplar controller fires, which is student-visible -- flagged rather than guessed at. Co-Authored-By: Claude Opus 5 (1M context) --- .../chat-tutor/chat-timeout.test.tsx | 29 ++++++++- src/components/chat-tutor/chat.tsx | 9 ++- .../chat-tutor/firestore-transport.test.ts | 17 ++++++ .../chat-tutor/firestore-transport.ts | 40 +++++------- src/components/chat-tutor/use-chat.test.ts | 16 ++++- src/components/chat-tutor/use-chat.ts | 4 +- src/components/document/document.tsx | 11 +++- src/lib/logger-types.ts | 1 + src/plugins/ai/ai-tile.test.tsx | 61 ++++++++++++++++--- src/plugins/ai/ai-tile.tsx | 24 ++++++-- 10 files changed, 165 insertions(+), 47 deletions(-) diff --git a/src/components/chat-tutor/chat-timeout.test.tsx b/src/components/chat-tutor/chat-timeout.test.tsx index c12aea7887..7b039dc134 100644 --- a/src/components/chat-tutor/chat-timeout.test.tsx +++ b/src/components/chat-tutor/chat-timeout.test.tsx @@ -1,8 +1,8 @@ import React from "react"; -import { render, screen } from "@testing-library/react"; +import { act, fireEvent, render, screen } from "@testing-library/react"; import { Chat } from "./chat"; import { ChatTurn } from "./transport"; -import { kTimeoutMessage, UseChatResult } from "./use-chat"; +import { kReplyDeadlineMs, kTimeoutMessage, UseChatResult } from "./use-chat"; const chatResult = (over: Partial = {}): UseChatResult => ({ turns: [], status: "idle", error: null, pending: false, timedOut: false, @@ -46,3 +46,28 @@ describe("Chat reply timeout", () => { expect(screen.queryByTestId("chat-error")).not.toBeInTheDocument(); }); }); + +// Firestore resolves add() only once the backend acknowledges it, so an offline write stays +// pending indefinitely. Before this, `sending` never cleared: the composer stayed disabled and the +// typing dots kept running past the deadline whose whole job is to end them — the exact scenario +// the feature is meant to cover. +describe("Chat with a send that never resolves", () => { + beforeEach(() => jest.useFakeTimers()); + afterEach(() => jest.useRealTimers()); + + it("releases the composer and stops the dots on the deadline", () => { + const chat = chatResult({ sendMessage: jest.fn(() => new Promise(() => undefined)) }); + render(); + + fireEvent.change(screen.getByTestId("chat-input"), { target: { value: "how do I start?" } }); + fireEvent.submit(screen.getByTestId("chat-composer")); + + expect(screen.getByTestId("chat-typing")).toBeInTheDocument(); + expect(screen.getByTestId("chat-input")).toBeDisabled(); + + act(() => { jest.advanceTimersByTime(kReplyDeadlineMs); }); + + expect(screen.queryByTestId("chat-typing")).not.toBeInTheDocument(); + expect(screen.getByTestId("chat-input")).not.toBeDisabled(); + }); +}); diff --git a/src/components/chat-tutor/chat.tsx b/src/components/chat-tutor/chat.tsx index a6a6fdcfdd..1aa4c31459 100644 --- a/src/components/chat-tutor/chat.tsx +++ b/src/components/chat-tutor/chat.tsx @@ -1,7 +1,7 @@ import React, { FormEvent, useEffect, useMemo, useRef, useState } from "react"; import classNames from "classnames"; import { v4 as uuidv4 } from "uuid"; -import { kTimeoutMessage, UseChatResult } from "./use-chat"; +import { kReplyDeadlineMs, kTimeoutMessage, UseChatResult } from "./use-chat"; import { ChatTurn } from "./transport"; import "./chat.scss"; @@ -224,11 +224,18 @@ export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTi if (!text || sending) return; setSending(true); setInput(""); + // Firestore resolves add() only once the backend acknowledges it, so an offline write stays + // pending indefinitely (it is queued locally). Awaiting it for the UI would leave the composer + // disabled and the typing dots running forever — past the reply deadline whose whole job is to + // end exactly that. Release the composer on the same deadline. The write is left running and + // still reconciles if it lands later; this bounds the UI, not the delivery. + const release = setTimeout(() => setSending(false), kReplyDeadlineMs); try { await sendMessage(text); } catch { setInput(text); // restore so the student can retry (error surfaced by the hook) } finally { + clearTimeout(release); setSending(false); } }; diff --git a/src/components/chat-tutor/firestore-transport.test.ts b/src/components/chat-tutor/firestore-transport.test.ts index 2a075f2532..e5f702d526 100644 --- a/src/components/chat-tutor/firestore-transport.test.ts +++ b/src/components/chat-tutor/firestore-transport.test.ts @@ -419,6 +419,23 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () expect(added[2].rightContext).toBe("W1"); }); + // The send that carries the workspace can fail while a later one that skipped it succeeds. If + // the hash were claimed before delivery, that later turn would reach the backend with no + // workspace at all and the tutor would answer it blind to the student's work. + it("still carries the workspace when the send that first attached it fails", async () => { + const { added, settle, transport } = transportWithMutableWorkspace(); + + const first = transport.sendUserMessage("one"); // attaches W1 + const second = transport.sendUserMessage("two"); // document unchanged + + settle[0].reject(new Error("offline")); + await expect(first).rejects.toThrow("offline"); + settle[1].resolve(); + await second; + + expect(added[1].rightContext).toBe("W1"); + }); + // Nothing retroactively tells an in-flight turn about an edit: the payload is computed before // the write. Pinned here because the guarantee is load-bearing and invisible from the call site. it("does not change what a message carried when the document is edited mid-send", async () => { diff --git a/src/components/chat-tutor/firestore-transport.ts b/src/components/chat-tutor/firestore-transport.ts index 20e56f132c..49da8827d0 100644 --- a/src/components/chat-tutor/firestore-transport.ts +++ b/src/components/chat-tutor/firestore-transport.ts @@ -64,7 +64,14 @@ export class FirestoreTransport implements ChatTransport { // mirrors the parent doc's problemInstalled flag; a not-yet-created parent reads // as false, so the first send attaches LEFT private problemInstalled = false; + // `lastSentRightHash` means "the server has this one". It is therefore recorded only once a + // write is acknowledged: a claim staked before delivery would let a concurrent send skip a + // workspace whose only carrier then failed, and the tutor would answer that turn blind to the + // student's work. The sequence numbers keep a late-resolving older send from overwriting a newer + // one's record, which is what would otherwise re-attach a workspace the server already has. private lastSentRightHash: string | undefined; + private rightSendSeq = 0; + private lastSentRightSeq = 0; private onStatus?: (status: ChatStatus) => void; constructor(private readonly opts: FirestoreTransportOptions) {} @@ -230,31 +237,16 @@ export class FirestoreTransport implements ChatTransport { message[right.field] = right.value; } - // Recorded before the write, not after. Two overlapping sends would otherwise record in - // completion order, leaving the client believing an older workspace was the last one sent and - // re-attaching one the server already has — up to kMaxAttachedWorkspace of document JSON on - // the ForeverLearning path. The composer stays open during a pending reply so a student can - // escape a wedged turn, so overlapping sends are expected, not exotic. - const claimedRight = decision.attachRight ? right : undefined; - if (claimedRight) { - this.lastSentRightHash = claimedRight.hash; - } + // The composer stays open during a pending reply so a student can escape a wedged turn, so + // overlapping sends are expected, not exotic. See lastSentRightHash for why this is recorded + // on acknowledgement rather than optimistically, and why the order matters. + const sendSeq = ++this.rightSendSeq; - try { - await this.messagesRef().add(message); - } catch (e) { - // The workspace never left the client, so the claim has to go — but only if this send is - // still the one holding it. `claimedRight` is what separates this from an unchanged send, - // whose hash matches precisely because it attached nothing. - // - // Cleared rather than restored to the previous hash: with two sends in flight that previous - // one may itself have failed, and restoring it would claim a delivery that never happened, - // leaving the next send to omit the workspace entirely. Clearing costs at most one redundant - // re-attach, which is the cheaper way to be wrong. - if (claimedRight && this.lastSentRightHash === claimedRight.hash) { - this.lastSentRightHash = undefined; - } - throw e; + await this.messagesRef().add(message); + + if (decision.attachRight && right && sendSeq > this.lastSentRightSeq) { + this.lastSentRightSeq = sendSeq; + this.lastSentRightHash = right.hash; } } diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts index 2201f3da2f..c3ada10e0f 100644 --- a/src/components/chat-tutor/use-chat.test.ts +++ b/src/components/chat-tutor/use-chat.test.ts @@ -161,16 +161,28 @@ describe("useChat logging", () => { // The transport re-emits its status on every snapshot, so a log keyed on anything but the // transition would fire repeatedly for one failure. - it("logs an unavailable backend once per transition, not once per snapshot", () => { + it("logs an unavailable backend once per transition, not once per snapshot", async () => { const t = stubTransport(); - renderWithContext(t.transport); + const { result } = renderWithContext(t.transport); + await act(async () => { await result.current.sendMessage("how do I start?"); }); t.status("error"); t.status("error"); expect(eventsNamed(LogEventName.AI_CHAT_UNAVAILABLE)).toHaveLength(1); }); + // The parent doc's "error" persists in Firestore, so reopening a failed conversation transitions + // idle -> error again. Counting those would inflate the failure rate with repeat views. + it("does not log an unavailable backend for a conversation that was already failed on open", () => { + const t = stubTransport(); + renderChat(t.transport, logContext); + + t.status("error"); + + expect(eventsNamed(LogEventName.AI_CHAT_UNAVAILABLE)).toHaveLength(0); + }); + it("logs a send that landed", async () => { const t = stubTransport(); const { result } = renderWithContext(t.transport); diff --git a/src/components/chat-tutor/use-chat.ts b/src/components/chat-tutor/use-chat.ts index 49d6380b6a..c56a44088a 100644 --- a/src/components/chat-tutor/use-chat.ts +++ b/src/components/chat-tutor/use-chat.ts @@ -72,7 +72,9 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC useEffect(() => { if (status === "error") { setError("Ada is currently unavailable. Please try again."); - Logger.log(LogEventName.AI_CHAT_UNAVAILABLE, { ...logContext }); + // Gated like the timeout below: the parent doc's "error" persists in Firestore, so every + // reopen of a failed conversation would otherwise log again with no matching send. + if (sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_UNAVAILABLE, { ...logContext }); } }, [status, logContext]); diff --git a/src/components/document/document.tsx b/src/components/document/document.tsx index 0c6681d235..bda4282c8b 100644 --- a/src/components/document/document.tsx +++ b/src/components/document/document.tsx @@ -584,10 +584,15 @@ export class DocumentComponent extends BaseComponent { return; } - // Every path that gives up on this click reports through here, so the four are countable - // against REQUEST_IDEA above. Identifiers and a reason only — no document content. + // Every path that gives up on this click reports through here. Logger.log with an explicit + // field list rather than logDocumentEvent: that helper expands the document into + // documentTitle and documentProperties, both student-authored, and these rows reach a research + // database and Rollbar. documentKey still joins a failure to its REQUEST_IDEA. const logFailure = (reason: IdeasFailureReason) => - logDocumentEvent(LogEventName.IDEAS_REQUEST_FAILED, { document }, undefined, { reason, requestId }); + Logger.log(LogEventName.IDEAS_REQUEST_FAILED, { + documentKey: document.key, documentType: document.type, documentUid: document.uid, + requestId, reason + }); commentsManager.setIdeasClickInProgress(true); diff --git a/src/lib/logger-types.ts b/src/lib/logger-types.ts index 153c0b0431..df101656c4 100644 --- a/src/lib/logger-types.ts +++ b/src/lib/logger-types.ts @@ -128,6 +128,7 @@ export enum LogEventName { REQUEST_IDEA, IDEAS_REQUEST_FAILED, + AI_TILE_REQUEST_FAILED, STANDALONE_SWITCH_PREVIEW_PROBLEM, diff --git a/src/plugins/ai/ai-tile.test.tsx b/src/plugins/ai/ai-tile.test.tsx index 41daaac134..83688f2eeb 100644 --- a/src/plugins/ai/ai-tile.test.tsx +++ b/src/plugins/ai/ai-tile.test.tsx @@ -37,6 +37,7 @@ import { ITileApi } from "../../components/tiles/tile-api"; import { TileModel } from "../../models/tiles/tile-model"; import { logTileChangeEvent } from "../../models/tiles/log/log-tile-change-event"; import { LogEventName } from "../../lib/logger-types"; +import { Logger } from "../../lib/logger"; import { defaultAIContent } from "./ai-content"; import { AIComponent } from "./ai-tile"; import { @@ -97,6 +98,10 @@ jest.mock("../../models/document/document-utils", () => ({ // don't crash when the AI content logs changes. jest.mock("../../models/tiles/log/log-tile-change-event", () => ({ logTileChangeEvent: jest.fn() })); +// The failure event goes through Logger directly, deliberately bypassing the tile-change helper +// (which would also emit QUESTION_ANSWERS_CHANGE for a tile inside a Question tile). +jest.mock("../../lib/logger", () => ({ Logger: { log: jest.fn() } })); + describe("AIComponent", () => { const content = defaultAIContent(); const model = TileModel.create({content}); @@ -505,6 +510,42 @@ describe("AIComponent", () => { expect(queryByText("Loading...")).not.toBeInTheDocument(); }); + // refreshCount stays positive after an Update, so classifying on "> 0" would make a later + // automatic request — here a remount of the same model, as happens when a document view is + // closed and reopened — look student-requested, and let its failure overwrite a good saved + // answer with an error nobody asked for. + it("after a successful Update, a failure on a remount of the same model still restores", + async () => { + mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); + const aiContent = defaultAIContent(); + aiContent.setPrompt("What do you think?"); + const aiModel = TileModel.create({ content: aiContent }); + + const { unmount } = await act(async () => + render()); + + // A real Update that succeeds, leaving refreshCount positive. + mockGetAiContent.mockResolvedValueOnce({ data: { text: "a good answer" } }); + await act(async () => { + aiContent.requestRefresh(); + await Promise.resolve(); + await Promise.resolve(); + }); + expect(aiContent.text).toBe("a good answer"); + + unmount(); + + const callsBefore = mockGetAiContent.mock.calls.length; + mockGetAiContent.mockRejectedValueOnce(new Error("network error")); + await act(async () => render( + + )); + + // Without this the test could pass by the remount never making a request at all. + expect(mockGetAiContent.mock.calls.length).toBe(callsBefore + 1); + expect(aiContent.text).toBe("a good answer"); + }); + // The student clicked Update, so restoring the old text would look exactly like a refresh // that did nothing. This is the case the durable message exists for. it("on a populated document, when a student-requested refresh rejects: the failure message " + @@ -590,7 +631,7 @@ describe("AIComponent", () => { await act(async () => render()); - (logTileChangeEvent as jest.Mock).mockClear(); + (Logger.log as jest.Mock).mockClear(); mockGetAiContent.mockRejectedValueOnce(new Error("network error")); await act(async () => { aiContent.requestRefresh(); @@ -598,11 +639,13 @@ describe("AIComponent", () => { await Promise.resolve(); }); - const failures = (logTileChangeEvent as jest.Mock).mock.calls.filter( - ([, params]) => params.operation === "requestFailed"); - expect(failures).toEqual([ - [LogEventName.AI_TOOL_CHANGE, { tileId: aiModel.id, operation: "requestFailed", change: {} }] - ]); + const failures = (Logger.log as jest.Mock).mock.calls.filter( + ([event]) => event === LogEventName.AI_TILE_REQUEST_FAILED); + expect(failures).toHaveLength(1); + expect(failures[0][1]).toMatchObject({ tileId: aiModel.id, userRequested: true }); + // Its own event, so it can never cascade into QUESTION_ANSWERS_CHANGE. + expect(logTileChangeEvent).not.toHaveBeenCalledWith( + LogEventName.AI_TOOL_CHANGE, expect.objectContaining({ operation: "requestFailed" })); // A superseded run is not a failure: its rejection must log nothing. let rejectOlderRun: (error: Error) => void; @@ -612,15 +655,15 @@ describe("AIComponent", () => { await act(async () => { aiContent.requestRefresh(); await Promise.resolve(); }); await act(async () => { aiContent.requestRefresh(); await Promise.resolve(); await Promise.resolve(); }); - (logTileChangeEvent as jest.Mock).mockClear(); + (Logger.log as jest.Mock).mockClear(); await act(async () => { rejectOlderRun!(new Error("stale network error")); await Promise.resolve(); await Promise.resolve(); }); - expect((logTileChangeEvent as jest.Mock).mock.calls.filter( - ([, params]) => params.operation === "requestFailed")).toHaveLength(0); + expect((Logger.log as jest.Mock).mock.calls.filter( + ([event]) => event === LogEventName.AI_TILE_REQUEST_FAILED)).toHaveLength(0); }); it("on a populated document, when a later refresh's getAiContent rejects: the failure message " + diff --git a/src/plugins/ai/ai-tile.tsx b/src/plugins/ai/ai-tile.tsx index b37ba0bab1..73b293c5fc 100644 --- a/src/plugins/ai/ai-tile.tsx +++ b/src/plugins/ai/ai-tile.tsx @@ -10,6 +10,8 @@ import { BasicEditableTileTitle } from "../../components/tiles/basic-editable-ti import { TileToolbar } from "../../components/toolbar/tile-toolbar"; import { ITileProps } from "../../components/tiles/tile-component"; import { useFirebaseFunction } from "../../hooks/use-firebase-function"; +import { Logger } from "../../lib/logger"; +import { LogEventName } from "../../lib/logger-types"; import { useStores } from "../../hooks/use-stores"; import { useUserContext } from "../../hooks/use-user-context"; import { DocumentContentModel } from "../../models/document/document-content"; @@ -39,6 +41,10 @@ export const AIComponent: React.FC = observer((props) => { // Text to restore when a request is invalidated with no successor to finish the job (e.g. the // class context disappears mid-request). Shared across runs, and cleared once no longer needed. const previousTextRef = useRef(undefined); + // The refreshCount this effect last ran against. The effect also reruns when userContext, the + // document or unit config changes, so "has ever been refreshed" would misread those as the + // student asking — see userRequested below. + const lastRefreshCountRef = useRef(content.refreshCount); useEffect(() => { onRegisterTileApi({ @@ -58,10 +64,11 @@ export const AIComponent: React.FC = observer((props) => { const generation = ++requestGenerationRef.current; const isCurrent = () => requestGenerationRef.current === generation; - // refreshCount is stripped by exportJson, so a freshly loaded tile starts at 0 and this is - // true only once the student has actually clicked Update. It decides whether a failure is - // theirs to see -- see the catch below. - const userRequested = content.refreshCount > 0; + // True only when refreshCount moved since the last run of this effect, i.e. the student + // clicked Update to cause THIS run. A rerun from any other dependency is automatic, however + // many times they clicked before. Decides whether a failure is theirs to see — see the catch. + const userRequested = content.refreshCount > lastRefreshCountRef.current; + lastRefreshCountRef.current = content.refreshCount; // Undo a superseded run's own blanking before anything else runs, so this run starts from real // text — otherwise this run's own capture below would save the blank, not the good text. if (previousTextRef.current !== undefined) { @@ -164,7 +171,14 @@ export const AIComponent: React.FC = observer((props) => { } // Logged either way: the console.error below reaches nobody, since Rollbar captures // uncaught errors and not caught ones, and an automatic failure is still a failure. - logAiEvent(content, "requestFailed", {}); + // + // Its own event rather than logAiEvent: that routes through logTileBaseEvent, which + // for a tile inside a Question tile also emits QUESTION_ANSWERS_CHANGE carrying the + // question prompt and the sibling answers. A failed request is not an answer change, + // and these rows reach a research database and Rollbar. + Logger.log(LogEventName.AI_TILE_REQUEST_FAILED, { + tileId: model.id, documentId: identifier, userRequested + }); } console.error("Failed to query AI", error); } finally { From 42557f0cebee5d5796faa5e1c47e5a84cfd4dc35 Mon Sep 17 00:00:00 2001 From: Leslie Bondaryk Date: Thu, 29 Oct 2026 11:06:53 -0400 Subject: [PATCH 8/8] CLUE-731: address review feedback Verified each item before acting; one was wrong and is left as is. Correctness: - An offline send could still strand the student. The deadline released `pending` but not the composer's own `sending`, and Chat draws dots for `pending || sending` while disabling the input. Once released, a second send is possible, so a send-generation ref stops a superseded send from re-disabling the composer or restoring its message over the new draft. - REQUEST_IDEA carried no requestId, so a failure could not be matched to its attempt. It carries one now, and the comment no longer claims documentKey is the join. - chatDebug is ungated in every appMode, so debug dry runs logged AI_CHAT_MESSAGE_SENT with an empty payload, inflating the denominator with rows naming no conversation. Chat events now log only with a log context. Verified wrong on my part: makeAutoObservable does convert a plain Set to an ObservableSet, and an in-place add re-runs observers (checked against MobX 6.13.7). The comment claiming otherwise is gone and the copying with it. Tests: - document.test.tsx now pins IDEAS_REQUEST_FAILED field by field, and that nothing is logged where a unit has no aiEvaluation. Routing it back through logDocumentEvent now fails the suite; before, student-authored titles could have returned to the research database unnoticed. - Two assertions could not fail: the ai-tile check named an operation nothing emits, and chat-timeout's dots assertion rendered with pending and sending both false. The first is now precise, the second deleted. - The transport tests kept their coverage but not their names, which still described the rollback design that record-on-ack removed. Pushed back on: the claim that two transport tests pass by construction. Three mutations -- claim-before-write, clear-on-any-failure, and completion order -- each fail at least one of the five, so none is vacuous. Also left alone: moving these docs out of docs/superpowers/. That is the current convention (24 specs, last touched this week) against docs/specs (5 files, last touched in April). Spec brought up to date; the plan is marked built and superseded rather than rewritten, since its value is as the record of what was planned. Co-Authored-By: Claude Opus 5 (1M context) --- .../2026-10-27-clue-731-ai-chat-timeout.md | 7 ++ ...6-10-27-clue-731-ai-chat-timeout-design.md | 91 +++++++++++-------- .../chat-tutor/chat-timeout.test.tsx | 33 +++++-- src/components/chat-tutor/chat.tsx | 22 +++-- .../chat-tutor/firestore-transport.test.ts | 27 +++--- .../chat-tutor/firestore-transport.ts | 12 +-- src/components/chat-tutor/use-chat.test.ts | 4 +- src/components/chat-tutor/use-chat.ts | 30 +++--- src/components/document/document.test.tsx | 34 ++++++- src/components/document/document.tsx | 5 +- .../document/document-comments-manager.ts | 11 +-- src/plugins/ai/ai-tile.test.tsx | 19 ++-- src/plugins/ai/ai-tile.tsx | 25 ++--- 13 files changed, 185 insertions(+), 135 deletions(-) diff --git a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md index 4ac817c5c5..024d7c02d0 100644 --- a/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md +++ b/docs/superpowers/plans/2026-10-27-clue-731-ai-chat-timeout.md @@ -1,5 +1,12 @@ # CLUE-731: AI Chats Should Time Out — Implementation Plan +> **Status: built and superseded.** This is the plan as written before implementation, kept for +> the record. Review found three defects in what it specified, so the shipped code differs from it +> in three places: the reply deadline also releases the composer's `sending` state (Task 2); the +> workspace hash is recorded on acknowledgement rather than claimed before the write (Task 3); and +> the AI tile reports only a student-requested failure, under its own `AI_TILE_REQUEST_FAILED` +> event rather than `AI_TOOL_CHANGE` (Tasks 6-7). The design doc is the current description. + > **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. **Goal:** No AI surface in CLUE leaves a student watching a progress indicator forever, and no AI failure is invisible to the team. The chat gets a 30s client-side reply deadline, Ideas gets a 45s "taking longer than usual" line ahead of its existing 120s give-up, the AI tile reports a failed request instead of silently restoring its old text, and every one of those failures emits a log event. diff --git a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md index 92826ffe58..e13aa6091b 100644 --- a/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md +++ b/docs/superpowers/specs/2026-10-27-clue-731-ai-chat-timeout-design.md @@ -111,8 +111,15 @@ the story that the logging makes empirically revisable — `AI_CHAT_TIMEOUT` ove off healthy replies. **On expiry.** `pending` goes false — the dots stop and the "Ada is typing" live region clears. -A message row appears reading *"Ada didn't answer. Please try again."* The composer needs no -change; it is already enabled during a pending reply. +A message row appears reading *"Ada didn't answer. Please try again."* + +The deadline also has to release the composer's own `sending` state. Firestore resolves `add()` +only on backend acknowledgement, so an offline write stays pending indefinitely and `Chat` renders +dots for `pending || sending` while disabling the input — which would leave the student past the +deadline with running dots and a dead composer, the exact state this exists to end. The write is +left running and still reconciles if it lands. Because the student can then send again while an +earlier send is unresolved, a send-generation ref stops a superseded send from re-disabling the +composer or restoring its message over what they have since typed. **Wording.** Deliberately distinct from the existing `status:"error"` line ("Ada is currently unavailable. Please try again."). Those are different failures — one is the backend reporting an @@ -136,25 +143,20 @@ causes makes both the component and its tests guess. `chat.tsx` renders one mess frozen at send time, and the drain reads only what is on the message documents. This is pinned with a regression test rather than changed. -**The real defect beside it.** `lastSentRightHash` is assigned *after* the `await`: - -```ts -await this.messagesRef().add(message); -if (decision.attachRight && right) { - this.lastSentRightHash = right.hash; -} -``` - -Two overlapping sends therefore record in completion order, not send order. Send A (hash `H1`) -and send B (`H2`) can resolve B-then-A, leaving the client believing `H1` was last sent when the -server has `H2`. The next message re-attaches a workspace the server already has — on the -ForeverLearning path that is up to 900 KB of document JSON per message. Overlapping sends are not -hypothetical: the composer is open during a pending reply precisely so a student can escape a -wedged turn. - -**Fix.** Assign in send order, before the await. On a failed write, restore the previous value -unless a newer send has already superseded it — otherwise a failed send would mark a workspace as -delivered that never left the client, and the student's retry would omit it. +**The real defect beside it.** `lastSentRightHash` was assigned *after* the `await`, so two +overlapping sends recorded in completion order. Send A (hash `H1`) and send B (`H2`) can resolve +B-then-A, leaving the client believing `H1` was last sent when the server has `H2`; the next +message then re-attaches a workspace the server already has — on the ForeverLearning path up to +900 KB of document JSON. Overlapping sends are not hypothetical: the composer is open during a +pending reply precisely so a student can escape a wedged turn. + +**Fix.** `lastSentRightHash` means *the server has acknowledged this one*, so it is recorded after +the write succeeds, and a monotonic send sequence stops a late-resolving older send from +overwriting a newer one's record. Claiming the hash *before* the write — the first attempt here — +is worse than the bug it replaced: a concurrent send would see the claim, skip an unchanged +workspace, and if the only carrier then failed, that turn would reach the backend with no +workspace at all and the tutor would answer it blind. A failed write now records nothing, so the +next send carries the workspace again. Over-attaching costs bytes; omitting costs context. ### 3. Ideas interim line @@ -225,10 +227,11 @@ authored prompt, or any document content.** These logs go to a research database student-written text does not belong in either, and a failure rate does not need it. The raw server error string is also left out — it can be long and can echo request content. -**Event names.** The chat gets three new ones, since it has none to reuse. Ideas gets one. The AI -tile reuses its existing `AI_TOOL_CHANGE` with `operation: "requestFailed"`, matching the -convention already in `ai-content.ts` (`requestRefresh` is logged the same way) rather than -introducing a fourth name for researchers to learn. +**Event names.** The chat gets three new ones, since it has none to reuse; Ideas and the AI tile +get one each. The tile's failure deliberately does *not* reuse `AI_TOOL_CHANGE` through +`logAiEvent`: that helper means "this tile's content changed" and cascades into +`QUESTION_ANSWERS_CHANGE` for a tile inside a Question tile. A failed request is not an answer +change, and that cascade would carry the question prompt and the sibling answers into telemetry. ## Constants @@ -252,26 +255,40 @@ already living in the hook. | `AI_CHAT_MESSAGE_SENT` | a user message reaches Firestore | conversation id, document key, problem path | | `AI_CHAT_TIMEOUT` | the reply deadline fires | conversation id, document key, problem path | | `AI_CHAT_UNAVAILABLE` | the transport reports `status: "error"` | conversation id, document key, problem path | -| `IDEAS_REQUEST_FAILED` | the 15s foreground deadline, the 120s expiry, or a `"failed"` server outcome | document key, problem path, request id, which of the three | -| `AI_TOOL_CHANGE` *(existing)* | the AI tile's request fails | tile id, `operation: "requestFailed"` | +| `IDEAS_REQUEST_FAILED` | the 15s foreground deadline, a client error, the 120s expiry, or a `"failed"` server outcome | document key, type and uid, request id, and which of the four | +| `AI_TILE_REQUEST_FAILED` | the AI tile's request fails | tile id, document id, whether the student requested it | + +`AI_CHAT_MESSAGE_SENT` is the denominator for the two chat failure events; a send with no log +context (the debug transport, which is ungated in every appMode) is not counted. -`AI_CHAT_MESSAGE_SENT` is the denominator for the two chat failure events. No event carries -message text, prompt text, document content or the raw server error string. +The Ideas failure rate is `IDEAS_REQUEST_FAILED` over `REQUEST_IDEA`, joined on `requestId`, which +both now carry. It is a floor rather than an exact rate: `REQUEST_IDEA` is logged only after the +click's foreground Firebase work succeeds, so a `client-deadline` or `client-error` failure can +have no attempt row to match. + +No event carries message text, prompt text, document content, document title or the raw server +error string. `logDocumentEvent` and `logAiEvent` are both deliberately bypassed for these: the +first expands a document into `documentTitle` and `documentProperties`, and the second cascades +into `QUESTION_ANSWERS_CHANGE` for a tile inside a Question tile, carrying the question prompt and +the sibling answers. ## Testing | Test | Covers | |---|---| -| `use-chat.test.ts` *(new)* | Deadline fires at `kReplyDeadlineMs`; `pending` goes false; `timedOut` set. Timer restarts on a new turn. Late reply clears the timeout and renders. Transport swap resets. No timeout while idle. | -| `firestore-transport.test.ts` | Overlapping sends record the hash in send order; a failed write restores the prior hash; a failed write superseded by a newer send does not. | +| `use-chat.test.ts` | Deadline fires at `kReplyDeadlineMs`; `pending` goes false; `timedOut` set. Timer restarts on a new turn. Late reply clears the timeout and renders. Transport swap resets. No timeout while idle. | +| `use-chat.test.ts` | Timeout and unavailable each log once per episode, not once per render. A landed send logs; a failed send and a send with no log context do not. No payload carries the student's message. | +| `use-chat.test.ts` | A conversation already waiting, or already failed, on open shows its message but logs nothing — only a send made in this session counts. | +| `chat-timeout.test.tsx` | The timeout row renders, an error outranks it, and the live region does not re-announce the previous reply. A never-resolving send releases the composer on the deadline, and a superseded send neither re-disables it nor overwrites the new draft. | +| `firestore-transport.test.ts` | The hash records in send order, not completion order; a failed write records nothing, so the workspace is carried again; an older send failing leaves a newer acknowledged hash alone; an unchanged send failing changes nothing. | | `firestore-transport.test.ts` | Regression: a document mutated between send and write resolution does not change what that message carried. | -| `document-comments-manager.test.ts` | Slow set populated at 45s, cleared on resolve, on expiry, and on `dispose`. | +| `document-comments-manager.test.ts` | Slow set populated at 45s, cleared on resolve, on expiry, and on `dispose`. Each in-manager Ideas failure path reports once; an expiry superseded by a newer click reports nothing. | +| `document.test.tsx` | `IDEAS_REQUEST_FAILED` carries exactly the allowed fields and the right reason on both client paths, and nothing is logged where the unit has no `aiEvaluation`. | | `waiting-message.test.tsx` | Interim message replaces the thinking message when the entry is slow. | -| `ai-tile.test.tsx` | Failure writes the message; a superseded run restores instead. | -| `use-chat.test.ts` | Timeout and unavailable each log once per episode, not once per render. A successful send logs; a failed send does not. | -| `document-comments-manager.test.ts` | Each of the three Ideas failure paths logs, and an expiry superseded by a newer click does not. | -| `ai-tile.test.tsx` | A failed request logs `requestFailed`; a superseded run logs nothing. | -| all of the above | No logged payload contains message text, prompt text or document content. | +| `ai-tile.test.tsx` | A requested failure writes the message and logs; an automatic one restores; a superseded run does neither. The failure never reaches the tile-change helper. | + +Each of these was checked by mutation — reverting the behavior it describes makes it fail — rather +than by passing once. No Cypress work: all four behaviors are timer-driven and are exercised honestly with Jest fake timers. A Cypress spec would have to wait the real deadline out to prove anything. diff --git a/src/components/chat-tutor/chat-timeout.test.tsx b/src/components/chat-tutor/chat-timeout.test.tsx index 7b039dc134..617950a093 100644 --- a/src/components/chat-tutor/chat-timeout.test.tsx +++ b/src/components/chat-tutor/chat-timeout.test.tsx @@ -17,11 +17,6 @@ describe("Chat reply timeout", () => { expect(screen.getByTestId("chat-error")).toHaveTextContent(kTimeoutMessage); }); - it("stops the typing indicator", () => { - render(); - expect(screen.queryByTestId("chat-typing")).not.toBeInTheDocument(); - }); - // A real send failure must not be masked by the deadline that follows it. it("prefers a send error over the timeout message", () => { render(); @@ -48,9 +43,8 @@ describe("Chat reply timeout", () => { }); // Firestore resolves add() only once the backend acknowledges it, so an offline write stays -// pending indefinitely. Before this, `sending` never cleared: the composer stayed disabled and the -// typing dots kept running past the deadline whose whole job is to end them — the exact scenario -// the feature is meant to cover. +// pending indefinitely. The deadline therefore has to bound the composer's own sending state, not +// just the wait for a reply, or the dots run on past it with the input disabled. describe("Chat with a send that never resolves", () => { beforeEach(() => jest.useFakeTimers()); afterEach(() => jest.useRealTimers()); @@ -70,4 +64,27 @@ describe("Chat with a send that never resolves", () => { expect(screen.queryByTestId("chat-typing")).not.toBeInTheDocument(); expect(screen.getByTestId("chat-input")).not.toBeDisabled(); }); + + // Once the composer is released the student can send again, and the first send may still settle. + it("does not let a superseded send re-disable the composer or overwrite the new draft", () => { + let failFirst: (e: Error) => void = () => undefined; + const sendMessage = jest.fn() + .mockImplementationOnce(() => new Promise((_r, rej) => { failFirst = rej; })) + .mockImplementationOnce(() => new Promise(() => undefined)); + render(); + const input = () => screen.getByTestId("chat-input") as HTMLInputElement; + + fireEvent.change(input(), { target: { value: "first message" } }); + fireEvent.submit(screen.getByTestId("chat-composer")); + act(() => { jest.advanceTimersByTime(kReplyDeadlineMs); }); + + fireEvent.change(input(), { target: { value: "second message" } }); + fireEvent.submit(screen.getByTestId("chat-composer")); + expect(input()).toBeDisabled(); + + act(() => { failFirst(new Error("offline")); }); + + expect(input()).toBeDisabled(); // the second send is still in flight + expect(input().value).toBe(""); // and the student's composer is not stuffed with the first + }); }); diff --git a/src/components/chat-tutor/chat.tsx b/src/components/chat-tutor/chat.tsx index 1aa4c31459..b06b2c81cd 100644 --- a/src/components/chat-tutor/chat.tsx +++ b/src/components/chat-tutor/chat.tsx @@ -122,6 +122,10 @@ export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTi const { turns, error, pending, timedOut, sendMessage, header } = chat; const [input, setInput] = useState(""); const [sending, setSending] = useState(false); + // Identifies the newest submit. Once the release timer below frees the composer, an earlier send + // can still settle: without this its finally would re-enable the composer mid-send, and its + // catch would overwrite whatever the student has since typed with the old message. + const sendGenRef = useRef(0); const [copied, setCopied] = useState(false); const listRef = useRef(null); const inputRef = useRef(null); @@ -224,19 +228,21 @@ export const Chat: React.FC = ({ chat, onClose, closeLabel, transcriptTi if (!text || sending) return; setSending(true); setInput(""); - // Firestore resolves add() only once the backend acknowledges it, so an offline write stays - // pending indefinitely (it is queued locally). Awaiting it for the UI would leave the composer - // disabled and the typing dots running forever — past the reply deadline whose whole job is to - // end exactly that. Release the composer on the same deadline. The write is left running and - // still reconciles if it lands later; this bounds the UI, not the delivery. - const release = setTimeout(() => setSending(false), kReplyDeadlineMs); + // An offline add() stays pending indefinitely, so awaiting it for the UI would hold the + // composer disabled past the deadline meant to end exactly that. This bounds the UI only: the + // write keeps running and still reconciles if it lands. + const gen = ++sendGenRef.current; + const isNewest = () => gen === sendGenRef.current; + const release = setTimeout(() => { if (isNewest()) setSending(false); }, kReplyDeadlineMs); try { await sendMessage(text); } catch { - setInput(text); // restore so the student can retry (error surfaced by the hook) + // Restore so the student can retry (the error itself is surfaced by the hook). Never over + // text they have typed since: a superseded send's message is not what they are writing now. + if (isNewest()) setInput(prev => prev || text); } finally { clearTimeout(release); - setSending(false); + if (isNewest()) setSending(false); } }; diff --git a/src/components/chat-tutor/firestore-transport.test.ts b/src/components/chat-tutor/firestore-transport.test.ts index e5f702d526..5639368d30 100644 --- a/src/components/chat-tutor/firestore-transport.test.ts +++ b/src/components/chat-tutor/firestore-transport.test.ts @@ -287,9 +287,8 @@ describe("FirestoreTransport measures the workspace in bytes", () => { }); -// The composer stays open while a reply is pending — that is the student's only escape from a -// wedged turn — so two sends can be in flight at once. `lastSentRightHash` therefore has to track -// what was SENT, not what happened to resolve last. +// The composer stays open while a reply is pending, so two sends can be in flight at once. +// `lastSentRightHash` means "acknowledged by the server", recorded in send order. describe("FirestoreTransport workspace bookkeeping under overlapping sends", () => { // Unlike fakeFirestore above, each add() hands back a promise the test settles by hand, which is // the only way to express one send resolving while another is still open. @@ -338,7 +337,7 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () expect(added[2]).not.toHaveProperty("rightContext"); }); - it("re-attaches a workspace whose write failed", async () => { + it("attaches again when the write that carried the workspace failed", async () => { const { added, settle, transport } = transportWithMutableWorkspace(); const first = transport.sendUserMessage("one"); @@ -352,8 +351,8 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () expect(added[1].rightContext).toBe("W1"); }); - // A's rollback must not undo B's successful delivery of the same workspace. - it("does not roll back over a newer send that succeeded", async () => { + // An older send failing must not unsettle what a newer, successful one delivered. + it("keeps a newer send's acknowledged workspace when an older send fails", async () => { const { added, settle, transport, edit } = transportWithMutableWorkspace(); const first = transport.sendUserMessage("one"); @@ -372,9 +371,8 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () expect(added[2]).not.toHaveProperty("rightContext"); }); - // The hashes match precisely BECAUSE this send attached nothing, so a hash match alone is not - // evidence that this send is the one holding the record. - it("does not clear the record when an unchanged send fails", async () => { + // This send attached nothing, so its failure says nothing about what the server already has. + it("leaves the acknowledged hash in place when an unchanged send fails", async () => { const { added, settle, transport } = transportWithMutableWorkspace(); const first = transport.sendUserMessage("one"); @@ -396,21 +394,20 @@ describe("FirestoreTransport workspace bookkeeping under overlapping sends", () // Both sends failing means the student was offline; neither message landed. Restoring the // earlier send's hash would claim a workspace the server never received, so the next send that // DID land would carry no workspace and the tutor would answer blind to the student's work. - it("claims nothing when two overlapping sends both fail", async () => { + it("records nothing when two overlapping sends both fail", async () => { const { added, settle, transport, edit } = transportWithMutableWorkspace(); - const first = transport.sendUserMessage("one"); // claims W1 + const first = transport.sendUserMessage("one"); // carries W1 edit("W2", "H2"); - const second = transport.sendUserMessage("two"); // claims W2, remembers W1 + const second = transport.sendUserMessage("two"); // carries W2 settle[0].reject(new Error("offline")); await expect(first).rejects.toThrow("offline"); settle[1].reject(new Error("offline")); await expect(second).rejects.toThrow("offline"); - // The student undoes the edit, so the document is back at the workspace the FIRST (also - // failed) send claimed. Restoring that claim on the second send's rollback would make this - // send attach nothing, and the server has never seen any workspace at all. + // The student undoes the edit, so the document is back at the workspace the first (also + // failed) send carried. Nothing was acknowledged, so this send must carry it again. edit("W1", "H1"); const third = transport.sendUserMessage("three"); settle[2].resolve(); diff --git a/src/components/chat-tutor/firestore-transport.ts b/src/components/chat-tutor/firestore-transport.ts index 49da8827d0..a5303f5d8d 100644 --- a/src/components/chat-tutor/firestore-transport.ts +++ b/src/components/chat-tutor/firestore-transport.ts @@ -64,11 +64,10 @@ export class FirestoreTransport implements ChatTransport { // mirrors the parent doc's problemInstalled flag; a not-yet-created parent reads // as false, so the first send attaches LEFT private problemInstalled = false; - // `lastSentRightHash` means "the server has this one". It is therefore recorded only once a - // write is acknowledged: a claim staked before delivery would let a concurrent send skip a - // workspace whose only carrier then failed, and the tutor would answer that turn blind to the - // student's work. The sequence numbers keep a late-resolving older send from overwriting a newer - // one's record, which is what would otherwise re-attach a workspace the server already has. + // "The server has this one", so it is recorded only on acknowledgement: claiming before delivery + // would let a concurrent send skip a workspace whose only carrier then failed, leaving the tutor + // blind to the student's work. The sequence keeps a late older send from overwriting a newer + // record, which would re-attach a workspace the server already has. private lastSentRightHash: string | undefined; private rightSendSeq = 0; private lastSentRightSeq = 0; @@ -237,9 +236,6 @@ export class FirestoreTransport implements ChatTransport { message[right.field] = right.value; } - // The composer stays open during a pending reply so a student can escape a wedged turn, so - // overlapping sends are expected, not exotic. See lastSentRightHash for why this is recorded - // on acknowledgement rather than optimistically, and why the order matters. const sendSeq = ++this.rightSendSeq; await this.messagesRef().add(message); diff --git a/src/components/chat-tutor/use-chat.test.ts b/src/components/chat-tutor/use-chat.test.ts index c3ada10e0f..8373671ffd 100644 --- a/src/components/chat-tutor/use-chat.test.ts +++ b/src/components/chat-tutor/use-chat.test.ts @@ -133,8 +133,8 @@ describe("useChat reply deadline", () => { }); -// The chat emitted no log events at all before this, so a failure count had nothing to be a rate -// of. MESSAGE_SENT is that denominator; the rest are the failures. +// MESSAGE_SENT is the denominator the failure events are a rate of, so what does and does not +// count as a send decides whether that rate means anything. describe("useChat logging", () => { const logContext = { conversationId: "conv-1", documentKey: "doc-1" }; diff --git a/src/components/chat-tutor/use-chat.ts b/src/components/chat-tutor/use-chat.ts index c56a44088a..604e9fe6f0 100644 --- a/src/components/chat-tutor/use-chat.ts +++ b/src/components/chat-tutor/use-chat.ts @@ -3,15 +3,10 @@ import { ChatStatus, ChatTransport, ChatTurn } from "./transport"; import { Logger } from "../../lib/logger"; import { LogEventName } from "../../lib/logger-types"; -// How long the client waits for a reply before it stops claiming Ada is working. Nothing on the -// client can tell a dead turn from a slow one -- the drain writes its assistant document and its -// cursor in one batch, so a drain that died writes neither -- which is why this is a deadline and -// not a smarter reading of status. -// -// 30s is a compromise between a student's patience and a slow but healthy reply. Erring short is -// the cheaper mistake: a late reply still renders and clears the message, so a tight deadline -// costs a confusing moment rather than an answer. AI_CHAT_TIMEOUT over AI_CHAT_MESSAGE_SENT gives -// the timeout rate this should be retuned against, rather than guessing again. +// A deadline rather than a smarter reading of status: no client state distinguishes a dead turn +// from a slow one, since the drain commits its reply and its cursor together. Erring short is the +// cheaper mistake, because a late reply still renders and clears the message. Retune against +// AI_CHAT_TIMEOUT over AI_CHAT_MESSAGE_SENT. export const kReplyDeadlineMs = 30_000; // Distinct from the status:"error" message below: the backend reporting an error and the backend @@ -28,7 +23,7 @@ export interface UseChatResult { header: string; } -export interface ChatLogContext { +export interface ChatLogContext extends Record { // Joins a log row to the Firestore conversation it came from, which is the lookup a report of // one stuck chat needs. problemPath is already on every log message, so it isn't repeated here. conversationId: string; @@ -49,11 +44,8 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC const [status, setStatus] = useState("idle"); const [error, setError] = useState(null); const [timedOut, setTimedOut] = useState(false); - // Whether the student sent anything during this mount. isAwaitingReply is computed over - // rehydrated history and the sidebar unmounts when closed, so an already-wedged conversation - // re-arms the deadline every time it is reopened. The message should still appear each time — - // the conversation really is unanswered — but counting those would inflate AI_CHAT_TIMEOUT with - // repeat views of one failure, against a denominator that counts the send once. + // Reopening a wedged conversation re-arms the deadline from rehydrated history. The message + // should appear every time, but only a send made here counts, or repeat views inflate the rate. const sentThisSessionRef = useRef(false); // Re-subscribe whenever the transport instance changes — this is the hard @@ -74,7 +66,7 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC setError("Ada is currently unavailable. Please try again."); // Gated like the timeout below: the parent doc's "error" persists in Firestore, so every // reopen of a failed conversation would otherwise log again with no matching send. - if (sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_UNAVAILABLE, { ...logContext }); + if (logContext && sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_UNAVAILABLE, logContext); } }, [status, logContext]); @@ -92,7 +84,7 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC if (!waiting) return; const timer = setTimeout(() => { setTimedOut(true); - if (sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_TIMEOUT, { ...logContext }); + if (logContext && sentThisSessionRef.current) Logger.log(LogEventName.AI_CHAT_TIMEOUT, logContext); }, kReplyDeadlineMs); return () => clearTimeout(timer); }, [waiting, newestTurnId, logContext]); @@ -108,7 +100,9 @@ export function useChat({ transport, header, logContext }: UseChatOptions): UseC // Only once the write landed, so the denominator counts messages the backend could // actually have answered. sentThisSessionRef.current = true; - Logger.log(LogEventName.AI_CHAT_MESSAGE_SENT, { ...logContext }); + // No context means the debug transport, which is ungated in every appMode: its dry runs + // would inflate the denominator with rows carrying no conversation. + if (logContext) Logger.log(LogEventName.AI_CHAT_MESSAGE_SENT, logContext); } catch (e) { setError((e as Error)?.message || "Failed to send your message. Please try again."); throw e; diff --git a/src/components/document/document.test.tsx b/src/components/document/document.test.tsx index c4b89a053f..7d32e3c8fc 100644 --- a/src/components/document/document.test.tsx +++ b/src/components/document/document.test.tsx @@ -10,6 +10,7 @@ import { specAppConfig } from "../../models/stores/spec-app-config"; import { createSingleTileContent } from "../../utilities/test-utils"; import { kAnalyzerUserParams } from "../../../shared/shared"; import { IDEAS_EMPTY_MESSAGE, IDEAS_REQUEST_FAILED_MESSAGE } from "../../models/document/ai-evaluation-messages"; +import { Logger } from "../../lib/logger"; import { kIdeasRequestDeadlineMs } from "../../models/document/document-comments-manager"; import { logDocumentEvent } from "../../models/document/log-document-event"; import { LogEventName } from "../../lib/logger-types"; @@ -36,6 +37,28 @@ jest.mock("../../models/document/log-document-event", () => ({ logDocumentViewEvent: jest.fn() })); +jest.mock("../../lib/logger", () => ({ Logger: { log: jest.fn() } })); + +// These rows reach a research database and Rollbar, so the payload is pinned field by field: +// routing this back through logDocumentEvent would readmit the student-authored document title, +// and nothing else in the suite would notice. +function ideasFailures() { + return (Logger.log as jest.Mock).mock.calls + .filter(([event]) => event === LogEventName.IDEAS_REQUEST_FAILED); +} + +function expectIdeasFailureLogged(reason: string, doc: DocumentModelType) { + const calls = ideasFailures(); + expect(calls).toHaveLength(1); + expect(calls[0][1]).toEqual({ + documentKey: doc.key, + documentType: doc.type, + documentUid: doc.uid, + requestId: expect.any(String), + reason + }); +} + function flushMicrotasks() { return act(async () => { await Promise.resolve(); @@ -146,7 +169,8 @@ describe("Ideas button", () => { expect(stores.db.firebase.setLastEditedNow) .toHaveBeenCalledWith(stores.user, document.key, document.uid, undefined, requestId); - expect(logDocumentEvent).toHaveBeenCalledWith(LogEventName.REQUEST_IDEA, { document }); + expect(logDocumentEvent).toHaveBeenCalledWith( + LogEventName.REQUEST_IDEA, { document }, undefined, { requestId }); expect(document.commentsManager?.pendingComments).toHaveLength(1); expect(document.commentsManager?.pendingComments[0]).toMatchObject({ requestId, postingType: "remote" }); expect(stores.db.firebase.getEvaluationStatusPath) @@ -240,7 +264,8 @@ describe("Ideas button", () => { expect(stores.db.firebase.setLastEditedNow) .toHaveBeenCalledWith(stores.user, document.key, document.uid, undefined, undefined); - expect(logDocumentEvent).toHaveBeenCalledWith(LogEventName.REQUEST_IDEA, { document }); + expect(logDocumentEvent).toHaveBeenCalledWith( + LogEventName.REQUEST_IDEA, { document }, undefined, { requestId: null }); expect(document.commentsManager?.pendingComments).toHaveLength(0); expect(stores.db.firebase.ref).not.toHaveBeenCalled(); @@ -273,7 +298,8 @@ describe("Ideas button", () => { expect(stores.db.firebase.setLastEditedNow) .toHaveBeenCalledWith(stores.user, document.key, document.uid, undefined, undefined); - expect(logDocumentEvent).toHaveBeenCalledWith(LogEventName.REQUEST_IDEA, { document }); + expect(logDocumentEvent).toHaveBeenCalledWith( + LogEventName.REQUEST_IDEA, { document }, undefined, { requestId: null }); expect(document.commentsManager?.statusMessage).toBeNull(); expect(document.commentsManager?.pendingComments).toHaveLength(0); expect(stores.db.firebase.ref).not.toHaveBeenCalled(); @@ -345,6 +371,7 @@ describe("Ideas button", () => { expect(document.commentsManager?.canRequestIdeas).toBe(true); expect(document.commentsManager?.statusMessage).toMatchObject({ message: IDEAS_REQUEST_FAILED_MESSAGE }); expect(consoleErrorSpy).toHaveBeenCalledWith("Ideas request failed:", expect.any(Error)); + expectIdeasFailureLogged("client-error", document); consoleErrorSpy.mockRestore(); }); @@ -397,6 +424,7 @@ describe("Ideas button", () => { expect(document.commentsManager?.canRequestIdeas).toBe(true); expect(document.commentsManager?.statusMessage).toBeNull(); expect(consoleErrorSpy).toHaveBeenCalledWith("Ideas request failed:", expect.any(Error)); + expect(ideasFailures()).toHaveLength(0); consoleErrorSpy.mockRestore(); }); diff --git a/src/components/document/document.tsx b/src/components/document/document.tsx index bda4282c8b..f9f1deb936 100644 --- a/src/components/document/document.tsx +++ b/src/components/document/document.tsx @@ -587,7 +587,8 @@ export class DocumentComponent extends BaseComponent { // Every path that gives up on this click reports through here. Logger.log with an explicit // field list rather than logDocumentEvent: that helper expands the document into // documentTitle and documentProperties, both student-authored, and these rows reach a research - // database and Rollbar. documentKey still joins a failure to its REQUEST_IDEA. + // database and Rollbar. requestId is the join to this click's REQUEST_IDEA, which carries the + // same id -- though a failure before that call logs none, so not every failure has a match. const logFailure = (reason: IdeasFailureReason) => Logger.log(LogEventName.IDEAS_REQUEST_FAILED, { documentKey: document.key, documentType: document.type, documentUid: document.uid, @@ -642,7 +643,7 @@ export class DocumentComponent extends BaseComponent { } } - logDocumentEvent(LogEventName.REQUEST_IDEA, { document }); + logDocumentEvent(LogEventName.REQUEST_IDEA, { document }, undefined, { requestId }); })(); // Never rejects, so a late failure (after the deadline below has already shown its own diff --git a/src/models/document/document-comments-manager.ts b/src/models/document/document-comments-manager.ts index 02230dae2e..88c64950dc 100644 --- a/src/models/document/document-comments-manager.ts +++ b/src/models/document/document-comments-manager.ts @@ -219,10 +219,7 @@ export class DocumentCommentsManager { runInAction(() => { this.pendingComments = this.pendingComments.filter(p => !ids.has(p.id)); - if (removed.some(p => this.slowRemoteCommentIds.has(p.id))) { - this.slowRemoteCommentIds = new Set( - [...this.slowRemoteCommentIds].filter(slowId => !ids.has(slowId))); - } + ids.forEach(id => this.slowRemoteCommentIds.delete(id)); }); removed.forEach(p => { @@ -246,10 +243,8 @@ export class DocumentCommentsManager { this.checkPendingComments(); }, kRemoteCommentExpiryMs); - // Replaced rather than mutated: makeAutoObservable does not make a plain Set's contents - // observable, so an in-place add would not re-render the waiting message. const slowTimer = setTimeout(() => { - runInAction(() => { this.slowRemoteCommentIds = new Set(this.slowRemoteCommentIds).add(id); }); + runInAction(() => { this.slowRemoteCommentIds.add(id); }); }, kSlowRemoteCommentMs); const wrappedDispose = () => { @@ -357,6 +352,6 @@ export class DocumentCommentsManager { }); this.comments = []; this.pendingComments = []; - this.slowRemoteCommentIds = new Set(); + this.slowRemoteCommentIds.clear(); } } diff --git a/src/plugins/ai/ai-tile.test.tsx b/src/plugins/ai/ai-tile.test.tsx index 83688f2eeb..f6ec2198ee 100644 --- a/src/plugins/ai/ai-tile.test.tsx +++ b/src/plugins/ai/ai-tile.test.tsx @@ -620,8 +620,8 @@ describe("AIComponent", () => { } }); - // console.error reaches nobody — Rollbar captures uncaught errors, not caught ones — so the - // log event is the only thing that makes a tile failure countable. + // console.error reaches nobody, since Rollbar captures uncaught errors and not caught ones, so + // the log event is the only record a tile failure leaves. it("on a populated document, logs a failed request, and logs nothing for a superseded one", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); @@ -632,6 +632,7 @@ describe("AIComponent", () => { await act(async () => render()); (Logger.log as jest.Mock).mockClear(); + (logTileChangeEvent as jest.Mock).mockClear(); mockGetAiContent.mockRejectedValueOnce(new Error("network error")); await act(async () => { aiContent.requestRefresh(); @@ -643,9 +644,11 @@ describe("AIComponent", () => { ([event]) => event === LogEventName.AI_TILE_REQUEST_FAILED); expect(failures).toHaveLength(1); expect(failures[0][1]).toMatchObject({ tileId: aiModel.id, userRequested: true }); - // Its own event, so it can never cascade into QUESTION_ANSWERS_CHANGE. - expect(logTileChangeEvent).not.toHaveBeenCalledWith( - LogEventName.AI_TOOL_CHANGE, expect.objectContaining({ operation: "requestFailed" })); + // The refresh click is a real tile change and belongs on that helper; the failure is not, + // and must stay off it -- that helper is what cascades into QUESTION_ANSWERS_CHANGE, + // carrying the question prompt and sibling answers, for a tile inside a Question tile. + expect((logTileChangeEvent as jest.Mock).mock.calls.map(([, params]) => params.operation)) + .toEqual(["requestRefresh"]); // A superseded run is not a failure: its rejection must log nothing. let rejectOlderRun: (error: Error) => void; @@ -876,9 +879,9 @@ describe("AIComponent", () => { expect(aiContent.text).toBe("Newer response"); }); - // A failure now reports rather than restores, so the restore point is only ever read by the - // top-of-effect undo. This pins that B captured the real text and not A's blank, by letting - // the class context disappear — the remaining path that restores from the captured point. + // The restore point is read only by the top-of-effect undo, since a requested failure reports + // instead. This pins that B captured the real text and not A's blank, by letting the class + // context disappear — the remaining path that restores from the captured point. it("a run started while an earlier one is still in flight captures the real text, not that " + "run's own blank, as its restore point", async () => { mockStores.documents.getDocument.mockReturnValue(documentWith(populatedDocContent())); diff --git a/src/plugins/ai/ai-tile.tsx b/src/plugins/ai/ai-tile.tsx index 73b293c5fc..2f193984f3 100644 --- a/src/plugins/ai/ai-tile.tsx +++ b/src/plugins/ai/ai-tile.tsx @@ -150,17 +150,10 @@ export const AIComponent: React.FC = observer((props) => { setLastUpdated(new Date(timestamp._seconds*1000)); } } catch (error) { - // A student who clicked Update is owed a visible answer: restoring the old text would - // look exactly like a refresh that did nothing. The message is document content, so it - // persists and syncs — the same tradeoff AI_TILE_EMPTY_MESSAGE makes above. - // - // The automatic refresh this effect fires on mount is NOT something the student asked - // for, and writing a failure there would replace a good prior answer with an error over - // a transient hiccup — saved, synced, and in front of the teacher. That case restores, - // which is what the tile did before this message existed. - // - // A superseded run is not a failure, and the newer run's own restore handles it; isAlive - // because writing to a node destroyed mid-request would hide the error being reported. + // A requested refresh reports: restoring would look like a refresh that did nothing, and + // this message is document content, the same tradeoff AI_TILE_EMPTY_MESSAGE makes above. + // An automatic one restores instead, so a transient failure cannot replace a good saved + // answer. A superseded run is neither, and isAlive guards a tile deleted mid-request. if (isCurrent() && isAlive(content)) { if (userRequested) { content.setText(AI_TILE_REQUEST_FAILED_MESSAGE); @@ -169,13 +162,9 @@ export const AIComponent: React.FC = observer((props) => { content.setText(previousTextRef.current); previousTextRef.current = undefined; } - // Logged either way: the console.error below reaches nobody, since Rollbar captures - // uncaught errors and not caught ones, and an automatic failure is still a failure. - // - // Its own event rather than logAiEvent: that routes through logTileBaseEvent, which - // for a tile inside a Question tile also emits QUESTION_ANSWERS_CHANGE carrying the - // question prompt and the sibling answers. A failed request is not an answer change, - // and these rows reach a research database and Rollbar. + // Logged either way; console.error reaches nobody, as Rollbar captures only uncaught + // errors. Its own event, not logAiEvent: that cascades into QUESTION_ANSWERS_CHANGE + // for a tile inside a Question tile, carrying the prompt and sibling answers. Logger.log(LogEventName.AI_TILE_REQUEST_FAILED, { tileId: model.id, documentId: identifier, userRequested });