fix(sync): settle completed turns and finished messages promptly
A lost or delayed turn-ending `session.idle` left the busy spinner up until the watchdog poll caught it (5-10s). An assistant `message.updated` carrying `time.completed` now schedules one status check for that session, and `streaming.ts` stops treating a completed trailing message as streaming. The check is deferred by 750ms and re-reads the session status when the timer fires, so the overwhelmingly common case — the turn's own `session.idle` arriving right behind the completed message — settles on its own and costs zero extra requests; only a session the store still believes busy spends a fetch. The poll shares the watchdog's in-flight directory guard, so the deferred check and the periodic poll cannot overlap on one directory. Status authority is unchanged: the monotonic pass never lowers status, and an authoritative resync runs only when the snapshot disagrees.
This commit is contained in:
@@ -222,7 +222,7 @@ Streaming lifecycle derivation has two paths. Directory attach, switch, bootstra
|
||||
|
||||
A trailing assistant message that the server stamped `time.completed` is never marked as streaming: the stamp means the whole response (text plus every tool call) finished, so even while the session stays busy for the next step of the turn, the typing indicator and the streaming part-update suspension must not linger on finished content. The message-level streaming state (`streamingMessageIds` / `messageStreamStates`) is therefore a *message* lifecycle, not a turn lifecycle — it is completed by an explicit `time.completed`, by a newer trailing message, or by the session leaving `busy`.
|
||||
|
||||
When an assistant `message.updated` event carries `time.completed` and the store still believes the session busy, sync fires one immediate directory status poll (`maybePollStatusAfterMessageCompletion`): the monotonic pass confirms/raises active status but never lowers it, and when the snapshot reports the session idle while the store believes it busy — a delayed or lost `session.idle` — an authoritative resync settles the status at once. This narrows the stuck-spinner window after turn completion from a full watchdog poll interval to a single round-trip; one in-flight fetch per directory bounds the fan-out and the 5s watchdog poll remains the backstop.
|
||||
When an assistant `message.updated` event carries `time.completed` and the store still believes the session busy, sync schedules one deferred status check (`maybePollStatusAfterMessageCompletion`, ~750ms). The status is re-read when the timer fires, so a normal turn whose `session.idle` lands inside that window issues no request at all; only a still-busy session spends a directory status poll, sharing the watchdog's one-in-flight-per-directory guard. The invariant is unchanged from the watchdog escalation: the monotonic pass confirms or raises active status and never lowers it, and an authoritative resync runs only when the snapshot disagrees with a store that still believes the session busy. This narrows the stuck-spinner window after a lost `session.idle` from a watchdog interval to one round-trip; the 5s watchdog poll remains the backstop.
|
||||
|
||||
Incomplete-session materialization is deduplicated by runtime, directory, and session for the full cooldown window, including after a fast success or failure. A settled-running-tool recovery may supersede a different request in that window so an earlier pre-settlement refresh cannot consume the only terminal recovery signal. Deferred recovery is dropped if its captured runtime is no longer active. If recovery requests a tail refresh while an older load is in flight, one refresh runs after that load instead of losing the newer authority demand. Completion retains the cooldown marker until expiry, and an older completion cannot clear a newer request marker. Recovery starts after the current ordered event batch and rechecks whether local state already contains the requested entity before starting HTTP. An explicit empty part bucket is authoritative fetched-empty state, not a missing snapshot. This prevents repeated orphan/missing-part events from creating message-tail and status request storms while preserving later recovery.
|
||||
|
||||
|
||||
@@ -1,8 +1,9 @@
|
||||
/**
|
||||
* Tests for the immediate status poll fired when an assistant message
|
||||
* completes (issue OPE-193, B1): the busy spinner must not linger for up to a
|
||||
* full watchdog poll interval after a turn completed when the session.idle
|
||||
* event was delayed or lost.
|
||||
* Tests for the deferred status poll fired when an assistant message completes
|
||||
* (issue OPE-193): the busy spinner must not linger for up to a full watchdog
|
||||
* poll interval after a turn completed when the session.idle event was delayed
|
||||
* or lost — and a normal turn, whose session.idle arrives promptly, must not
|
||||
* cost a single extra request.
|
||||
*/
|
||||
import { beforeEach, describe, expect, mock, test } from "bun:test"
|
||||
import { create, type StoreApi } from "zustand"
|
||||
@@ -12,19 +13,14 @@ import type { DirectoryStore } from "../child-store"
|
||||
|
||||
type StatusSnapshot = Record<string, SessionStatus | undefined>
|
||||
|
||||
let statusSnapshotResult: StatusSnapshot | null = { ses_1: { type: "idle" } }
|
||||
let statusSnapshotErrors = 0
|
||||
let respondWithSnapshot: () => Promise<StatusSnapshot | null> = () => Promise.resolve({ ses_1: { type: "idle" } })
|
||||
const statusSnapshotCalls: string[] = []
|
||||
|
||||
mock.module("@/lib/opencode/client", () => ({
|
||||
opencodeClient: {
|
||||
getSessionStatusForDirectory: mock((directory: string) => {
|
||||
statusSnapshotCalls.push(directory)
|
||||
if (statusSnapshotErrors > 0) {
|
||||
statusSnapshotErrors -= 1
|
||||
return Promise.resolve(null)
|
||||
}
|
||||
return Promise.resolve(statusSnapshotResult)
|
||||
return respondWithSnapshot()
|
||||
}),
|
||||
},
|
||||
}))
|
||||
@@ -33,28 +29,28 @@ mock.module("@/lib/runtime-switch", () => ({
|
||||
getRuntimeKey: () => "test-runtime",
|
||||
}))
|
||||
|
||||
import { maybePollStatusAfterMessageCompletion } from "../sync-context"
|
||||
import { maybePollStatusAfterMessageCompletion, MESSAGE_COMPLETION_STATUS_POLL_DELAY_MS } from "../sync-context"
|
||||
|
||||
const createStore = (status: SessionStatus | undefined): StoreApi<DirectoryStore> => {
|
||||
const createStore = (status: SessionStatus): StoreApi<DirectoryStore> => {
|
||||
return create<DirectoryStore>()((set) => ({
|
||||
...INITIAL_STATE,
|
||||
...(status ? { session_status: { ses_1: status } } : {}),
|
||||
session_status: { ses_1: status },
|
||||
patch: (partial) => set(partial),
|
||||
replace: (next) => set(next),
|
||||
}))
|
||||
}
|
||||
|
||||
const sleep = (ms: number): Promise<void> => new Promise((resolve) => setTimeout(resolve, ms))
|
||||
|
||||
/** Past the deferral, plus room for the background-network task chain. */
|
||||
const waitForPollSettled = async (): Promise<void> => {
|
||||
// The helper runs under the background-network concurrency gate; give the
|
||||
// task chain (and any promise-based snapshot) real time to finish.
|
||||
await new Promise((resolve) => setTimeout(resolve, 25))
|
||||
await new Promise((resolve) => setTimeout(resolve, 25))
|
||||
await sleep(MESSAGE_COMPLETION_STATUS_POLL_DELAY_MS + 50)
|
||||
await sleep(50)
|
||||
}
|
||||
|
||||
describe("maybePollStatusAfterMessageCompletion (issue OPE-193)", () => {
|
||||
beforeEach(() => {
|
||||
statusSnapshotResult = { ses_1: { type: "idle" } }
|
||||
statusSnapshotErrors = 0
|
||||
respondWithSnapshot = () => Promise.resolve({ ses_1: { type: "idle" } })
|
||||
statusSnapshotCalls.length = 0
|
||||
})
|
||||
|
||||
@@ -79,10 +75,25 @@ describe("maybePollStatusAfterMessageCompletion (issue OPE-193)", () => {
|
||||
expect(statusSnapshotCalls).toEqual([])
|
||||
})
|
||||
|
||||
test("settles a busy session to idle immediately when the snapshot omits it", async () => {
|
||||
test("issues no request when session.idle arrives inside the deferral window", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
// The turn's own session.idle event lands well before the timer fires.
|
||||
await sleep(50)
|
||||
store.getState().patch({ session_status: { ses_1: { type: "idle" } } })
|
||||
await waitForPollSettled()
|
||||
|
||||
expect(statusSnapshotCalls).toEqual([])
|
||||
})
|
||||
|
||||
test("settles a busy session to idle when the idle event never arrives", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
// Nothing settles the session inside the window; the poll must run.
|
||||
expect(statusSnapshotCalls).toEqual([])
|
||||
|
||||
await waitForPollSettled()
|
||||
|
||||
expect(statusSnapshotCalls).toEqual(["/test/project", "/test/project"])
|
||||
@@ -91,7 +102,7 @@ describe("maybePollStatusAfterMessageCompletion (issue OPE-193)", () => {
|
||||
|
||||
test("keeps the session busy when the snapshot confirms it is still active", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
statusSnapshotResult = { ses_1: { type: "busy" } }
|
||||
respondWithSnapshot = () => Promise.resolve({ ses_1: { type: "busy" } })
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
await waitForPollSettled()
|
||||
@@ -104,7 +115,7 @@ describe("maybePollStatusAfterMessageCompletion (issue OPE-193)", () => {
|
||||
|
||||
test("preserves the busy status when the status fetch fails", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
statusSnapshotErrors = 1
|
||||
respondWithSnapshot = () => Promise.resolve(null)
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
await waitForPollSettled()
|
||||
@@ -115,34 +126,15 @@ describe("maybePollStatusAfterMessageCompletion (issue OPE-193)", () => {
|
||||
expect(store.getState().session_status?.ses_1?.type).toBe("busy")
|
||||
})
|
||||
|
||||
test("deduplicates concurrent polls for the same directory", async () => {
|
||||
test("schedules one check for a burst of completions on the same session", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
statusSnapshotResult = new Promise((resolve) => {
|
||||
setTimeout(() => resolve({ ses_1: { type: "idle" } }), 10)
|
||||
}) as unknown as StatusSnapshot
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
await waitForPollSettled()
|
||||
|
||||
expect(statusSnapshotCalls).toEqual(["/test/project", "/test/project"])
|
||||
})
|
||||
|
||||
test("does not poll again while a previous poll for the directory is in flight", async () => {
|
||||
const store = createStore({ type: "busy" })
|
||||
let release: () => void = () => {}
|
||||
statusSnapshotResult = new Promise((resolve) => {
|
||||
release = () => resolve({ ses_1: { type: "idle" } })
|
||||
}) as unknown as StatusSnapshot
|
||||
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
maybePollStatusAfterMessageCompletion("/test/project", store, "ses_1")
|
||||
release()
|
||||
await waitForPollSettled()
|
||||
|
||||
// First call ran the poll; the second call was deduped by the in-flight
|
||||
// guard. The escalation (second fetch) is the authoritative resync.
|
||||
// One monotonic poll plus its authoritative escalation, not three.
|
||||
expect(statusSnapshotCalls).toEqual(["/test/project", "/test/project"])
|
||||
expect(store.getState().session_status?.ses_1?.type).toBe("idle")
|
||||
})
|
||||
|
||||
@@ -16,13 +16,15 @@ import {
|
||||
const message = (id: string, role: "user" | "assistant"): Message => ({
|
||||
id,
|
||||
role,
|
||||
time: { created: 1 },
|
||||
} as unknown as Message)
|
||||
|
||||
const completedAssistantMessage = (id: string): Message => ({
|
||||
id,
|
||||
role: "assistant",
|
||||
time: { created: 1, completed: 100 },
|
||||
} as unknown as Message)
|
||||
const completedAssistantMessage = (id: string): Message => {
|
||||
const base = message(id, "assistant")
|
||||
// SAFETY: test fixture — the streaming reducers read only `id`, `role`, and
|
||||
// `time.completed`, which this literal provides.
|
||||
return { ...base, time: { created: 1, completed: 100 } } as Message
|
||||
}
|
||||
|
||||
const stateWithMessages = (messages: Message[], status: SessionStatus = { type: "busy" } as SessionStatus): State => ({
|
||||
...INITIAL_STATE,
|
||||
|
||||
@@ -67,7 +67,7 @@ const findTrailingAssistantMessage = (messages: Message[] | undefined): Message
|
||||
* finished content until the session settles.
|
||||
*/
|
||||
const isTrailingMessageComplete = (message: Message): boolean => {
|
||||
return typeof (message as { time?: { completed?: unknown } }).time?.completed === "number"
|
||||
return message.role === "assistant" && message.time.completed !== undefined
|
||||
}
|
||||
|
||||
export function updateStreamingState(state: State, now = Date.now()) {
|
||||
|
||||
@@ -341,10 +341,17 @@ type PendingSessionMaterialization = {
|
||||
const SESSION_MATERIALIZATION_COOLDOWN_MS = 5_000
|
||||
const pendingSessionMaterializations = new Map<string, PendingSessionMaterialization>()
|
||||
|
||||
// In-flight guard for the immediate status poll fired when an assistant
|
||||
// message completes (see maybePollStatusAfterMessageCompletion). Keyed by
|
||||
// directory so a burst of completing messages shares one status fetch.
|
||||
const messageCompletionStatusPolls = new Set<string>()
|
||||
// One in-flight directory status fetch at a time, shared by the active-session
|
||||
// watchdog poll and the deferred completion poll so the two cannot overlap on
|
||||
// the same directory.
|
||||
const statusPollingDirectories = new Set<string>()
|
||||
|
||||
// Deferred completion polls awaiting their delay, keyed by directory+session so
|
||||
// a burst of completing messages schedules one check.
|
||||
const pendingMessageCompletionPolls = new Map<string, ReturnType<typeof setTimeout>>()
|
||||
|
||||
// How long to wait for the turn's own `session.idle` before spending a request.
|
||||
export const MESSAGE_COMPLETION_STATUS_POLL_DELAY_MS = 750
|
||||
|
||||
function enqueueSessionMaterialization(
|
||||
directory: string,
|
||||
@@ -737,19 +744,22 @@ async function resyncDirectorySessionStatuses(
|
||||
}
|
||||
|
||||
/**
|
||||
* Immediately re-check the session status after an assistant message
|
||||
* completes. The turn-ending `session.idle` event can be delayed or lost; left
|
||||
* alone, the busy spinner keeps showing until the next watchdog poll tick
|
||||
* (up to ~5s) and its escalation (up to ~10s). One cheap status fetch right
|
||||
* after the completion confirms the turn really ended, mirroring the watchdog
|
||||
* escalation: the monotonic pass confirms/raises busy but never lowers it, and
|
||||
* when the snapshot reports the session idle while the store still believes it
|
||||
* busy, an authoritative resync settles the status immediately.
|
||||
* Re-check the session status shortly after an assistant message completes.
|
||||
* The turn-ending `session.idle` event can be delayed or lost; left alone, the
|
||||
* busy spinner keeps showing until the next watchdog poll tick (up to ~5s) and
|
||||
* its escalation (up to ~10s).
|
||||
*
|
||||
* Bounded: one in-flight fetch per directory, only for sessions the store
|
||||
* currently believes active, best-effort (the watchdog poll remains the
|
||||
* backstop). This narrows recovery latency without restructuring the polling
|
||||
* design.
|
||||
* The check is deferred by `MESSAGE_COMPLETION_STATUS_POLL_DELAY_MS`, and the
|
||||
* status is read again when the timer fires: a normal turn whose `session.idle`
|
||||
* arrives inside that window settles on its own and issues no request at all.
|
||||
* Only a session the store still believes busy costs one status fetch, which
|
||||
* mirrors the watchdog escalation — the monotonic pass confirms/raises busy but
|
||||
* never lowers it, and when the snapshot reports the session idle while the
|
||||
* store still believes it busy, an authoritative resync settles the status.
|
||||
*
|
||||
* Bounded: one scheduled check per session, one in-flight status fetch per
|
||||
* directory (shared with the watchdog poll), best-effort — the watchdog poll
|
||||
* remains the backstop.
|
||||
*/
|
||||
export function maybePollStatusAfterMessageCompletion(
|
||||
directory: string,
|
||||
@@ -759,24 +769,35 @@ export function maybePollStatusAfterMessageCompletion(
|
||||
if (!directory || directory === "global" || !sessionID) return
|
||||
const current = store.getState().session_status?.[sessionID]
|
||||
if (!current || current.type === "idle") return
|
||||
if (messageCompletionStatusPolls.has(directory)) return
|
||||
|
||||
messageCompletionStatusPolls.add(directory)
|
||||
void (async () => {
|
||||
try {
|
||||
const statuses = await runBackgroundNetworkTask(() =>
|
||||
resyncDirectorySessionStatuses(directory, store, [sessionID], "monotonic"))
|
||||
if (!statuses) return
|
||||
if (needsSnapshotAfterStatusPoll(store.getState(), sessionID, statuses[sessionID])) {
|
||||
await runBackgroundNetworkTask(() =>
|
||||
resyncDirectorySessionStatuses(directory, store, [sessionID], "authoritative"))
|
||||
const pendingKey = `${directory}\u0000${sessionID}`
|
||||
if (pendingMessageCompletionPolls.has(pendingKey)) return
|
||||
|
||||
const timer = setTimeout(() => {
|
||||
pendingMessageCompletionPolls.delete(pendingKey)
|
||||
const latest = store.getState().session_status?.[sessionID]
|
||||
if (!latest || latest.type === "idle") return
|
||||
if (statusPollingDirectories.has(directory)) return
|
||||
|
||||
statusPollingDirectories.add(directory)
|
||||
void (async () => {
|
||||
try {
|
||||
const statuses = await runBackgroundNetworkTask(() =>
|
||||
resyncDirectorySessionStatuses(directory, store, [sessionID], "monotonic"))
|
||||
if (!statuses) return
|
||||
if (needsSnapshotAfterStatusPoll(store.getState(), sessionID, statuses[sessionID])) {
|
||||
await runBackgroundNetworkTask(() =>
|
||||
resyncDirectorySessionStatuses(directory, store, [sessionID], "authoritative"))
|
||||
}
|
||||
} catch {
|
||||
// Best-effort — the watchdog poll retries on its own cadence.
|
||||
} finally {
|
||||
statusPollingDirectories.delete(directory)
|
||||
}
|
||||
} catch {
|
||||
// Best-effort — the watchdog poll retries on its own cadence.
|
||||
} finally {
|
||||
messageCompletionStatusPolls.delete(directory)
|
||||
}
|
||||
})()
|
||||
})()
|
||||
}, MESSAGE_COMPLETION_STATUS_POLL_DELAY_MS)
|
||||
|
||||
pendingMessageCompletionPolls.set(pendingKey, timer)
|
||||
}
|
||||
|
||||
// After a monotonic poll, decide whether to escalate to a full authoritative
|
||||
@@ -2123,7 +2144,6 @@ export function SyncProvider(props: {
|
||||
const lastChildDiscoveryAtByDirectoryRef = useRef(new Map<string, number>())
|
||||
const resyncingDirectoriesRef = useRef(new Set<string>())
|
||||
const blockingRequestResyncingDirectoriesRef = useRef(new Set<string>())
|
||||
const statusPollingDirectoriesRef = useRef(new Set<string>())
|
||||
const pipelineReconnectRef = useRef<((reason?: string) => void) | null>(null)
|
||||
const pipelineHasConnectedRef = useRef(false)
|
||||
const pipelineDisconnectedBeforeFirstConnectRef = useRef(false)
|
||||
@@ -2486,7 +2506,7 @@ export function SyncProvider(props: {
|
||||
store: StoreApi<DirectoryStore>,
|
||||
candidateSessionIds: string[],
|
||||
) => {
|
||||
const polling = statusPollingDirectoriesRef.current
|
||||
const polling = statusPollingDirectories
|
||||
if (polling.has(directory)) return
|
||||
polling.add(directory)
|
||||
try {
|
||||
@@ -2544,7 +2564,7 @@ export function SyncProvider(props: {
|
||||
.finally(() => {
|
||||
running = false
|
||||
if (stopped) {
|
||||
statusPollingDirectoriesRef.current.clear()
|
||||
statusPollingDirectories.clear()
|
||||
}
|
||||
})
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user