diff --git a/apps/web/src/domains/chat/utils/sanitize-display-messages.test.ts b/apps/web/src/domains/chat/utils/sanitize-display-messages.test.ts index 6e2eda19fc1..f0f4fa587e4 100644 --- a/apps/web/src/domains/chat/utils/sanitize-display-messages.test.ts +++ b/apps/web/src/domains/chat/utils/sanitize-display-messages.test.ts @@ -1,4 +1,4 @@ -import { describe, expect, test } from "bun:test"; +import { afterEach, describe, expect, spyOn, test } from "bun:test"; import { sanitizeDisplayMessages } from "@/domains/chat/utils/sanitize-display-messages"; import type { DisplayMessage } from "@/domains/chat/types/types"; @@ -646,7 +646,336 @@ describe("sanitizeDisplayMessages · repair dangling tool calls", () => { }); // --------------------------------------------------------------------------- -// Integration — all four hacks compose +// Hack #5 — fail stale tool calls on assistant restart / silent daemon death +// --------------------------------------------------------------------------- + +describe("sanitizeDisplayMessages · fail stale tool calls", () => { + const STALE_PREFIX = "Tool call exceeded the execution timeout"; + // Mirrors `DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC` from @vellumai/assistant-api. + // Hard-coded in the test so a regression that changes the wire-contract + // default by accident shows up here too. + const DEFAULT_TIMEOUT_MS = 120_000; + // Mirrors `STALE_GRACE_MS` from the sanitizer. Same reasoning as above. + const GRACE_MS = 30_000; + // Convenience: just past the threshold a default-timeout running tool + // call becomes stale. + const PAST_DEFAULT_TIMEOUT_MS = DEFAULT_TIMEOUT_MS + GRACE_MS + 1_000; + + // The sanitizer reads `Date.now()` once per call to produce a stable + // `nowMs` for Hack #5. Tests pin that clock via spyOn so the + // stale-detection window is deterministic. Each test sets up its own + // spy with `mockNow(...)`; the afterEach restores the real clock so + // unrelated tests in the file (and adjacent test files in the same + // worker) keep seeing real time. + let nowSpy: ReturnType | null = null; + function mockNow(nowMs: number): void { + nowSpy = spyOn(Date, "now").mockReturnValue(nowMs); + } + afterEach(() => { + nowSpy?.mockRestore(); + nowSpy = null; + }); + + test("marks a running tool call stale once default timeout + grace elapses", () => { + const started = 1_000; + const now = started + PAST_DEFAULT_TIMEOUT_MS; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "web_search", + status: "running", + startedAt: started, + }), + ], + }); + mockNow(now); + const [patched] = sanitizeDisplayMessages([m]); + expect(patched!.toolCalls![0]!.status).toBe("error"); + expect(patched!.toolCalls![0]!.isError).toBe(true); + expect(patched!.toolCalls![0]!.result).toContain(STALE_PREFIX); + }); + + test("does NOT mark stale before timeout + grace elapses", () => { + const started = 1_000; + // Right at the threshold, NOT past it. Predicate is strict >. + const now = started + DEFAULT_TIMEOUT_MS + GRACE_MS; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "web_search", + status: "running", + startedAt: started, + }), + ], + }); + mockNow(now); + const result = sanitizeDisplayMessages([m]); + expect(result[0]).toBe(m); + expect(result[0]!.toolCalls![0]!.status).toBe("running"); + }); + + test("uses progressTimeoutSec when the daemon advertised one", () => { + // Long-running shell tools advertise a 600s timeout via tool_progress. + // A run that's at 121s of elapsed time would tripping the DEFAULT + // ceiling but is still well under its real ceiling — must not fire. + const started = 1_000; + const now = started + 121_000; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "bash", + status: "running", + startedAt: started, + progressTimeoutSec: 600, + lastProgressAt: started + 119_000, + }), + ], + }); + mockNow(now); + const result = sanitizeDisplayMessages([m]); + expect(result[0]).toBe(m); + expect(result[0]!.toolCalls![0]!.status).toBe("running"); + }); + + test("measures from lastProgressAt when it is more recent than startedAt", () => { + // A long-running bash command emitting tool_progress events. As long + // as those keep landing, the tool is alive. Started two hours ago, + // last progress one second ago → not stale. + const started = 1_000; + const now = started + 2 * 60 * 60 * 1_000; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "bash", + status: "running", + startedAt: started, + progressTimeoutSec: 600, + lastProgressAt: now - 1_000, + }), + ], + }); + mockNow(now); + const result = sanitizeDisplayMessages([m]); + expect(result[0]).toBe(m); + expect(result[0]!.toolCalls![0]!.status).toBe("running"); + }); + + test("falls back to default timeout when progressTimeoutSec is zero / unknown", () => { + // Daemon ships `progressTimeoutSec: 0` to mean "unknown". The + // sanitizer must treat 0 the same as missing and use the canonical + // default constant. + const started = 1_000; + const now = started + PAST_DEFAULT_TIMEOUT_MS; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "web_search", + status: "running", + startedAt: started, + progressTimeoutSec: 0, + }), + ], + }); + mockNow(now); + const [patched] = sanitizeDisplayMessages([m]); + expect(patched!.toolCalls![0]!.status).toBe("error"); + expect(patched!.toolCalls![0]!.result).toContain(STALE_PREFIX); + }); + + test("does NOT mark stale when pendingConfirmation is set", () => { + // A tool waiting on user approval is correctly stalled — the + // daemon's execution clock hasn't even started. Could sit here for + // arbitrarily long without being dead. + const started = 1_000; + const now = started + 24 * 60 * 60 * 1_000; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "bash", + status: "running", + startedAt: started, + pendingConfirmation: { + requestId: "rq-1", + toolName: "bash", + input: {}, + }, + }), + ], + }); + mockNow(now); + const result = sanitizeDisplayMessages([m]); + expect(result[0]).toBe(m); + expect(result[0]!.toolCalls![0]!.status).toBe("running"); + }); + + test("does NOT mark stale when startedAt is missing (no clock to measure)", () => { + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: 100, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "bash", + status: "running", + // No startedAt — typically a pre-stamping history hydration. + }), + ], + }); + mockNow(1_000_000_000); + const result = sanitizeDisplayMessages([m]); + expect(result[0]).toBe(m); + expect(result[0]!.toolCalls![0]!.status).toBe("running"); + }); + + test("marks stale tools on the LAST assistant too (no subsequent-assistant requirement)", () => { + // Differs from hack #4 — for stale we don't require any later + // assistant message, because the timeout itself is the proof. + const started = 1_000; + const now = started + PAST_DEFAULT_TIMEOUT_MS; + const u = makeMessage({ + id: "u", + role: "user", + content: "go", + timestamp: started - 100, + }); + const lastAssistant = makeMessage({ + id: "a-last", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc", + toolName: "web_search", + status: "running", + startedAt: started, + }), + ], + }); + mockNow(now); + const result = sanitizeDisplayMessages([u, lastAssistant]); + expect(result[1]!.toolCalls![0]!.status).toBe("error"); + expect(result[1]!.toolCalls![0]!.result).toContain(STALE_PREFIX); + }); + + test("leaves siblings on the same message alone when one is stale", () => { + const started = 1_000; + const now = started + PAST_DEFAULT_TIMEOUT_MS; + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [ + makeToolCall({ + id: "tc-1", + toolName: "bash", + status: "completed", + startedAt: started, + result: "first ok", + }), + makeToolCall({ + id: "tc-2", + toolName: "web_search", + status: "running", + startedAt: started, + }), + makeToolCall({ + id: "tc-3", + toolName: "read_file", + status: "completed", + startedAt: started, + result: "third ok", + }), + ], + }); + mockNow(now); + const [patched] = sanitizeDisplayMessages([m]); + expect(patched!.toolCalls![0]!.result).toBe("first ok"); + expect(patched!.toolCalls![1]!.status).toBe("error"); + expect(patched!.toolCalls![1]!.isError).toBe(true); + expect(patched!.toolCalls![1]!.result).toContain(STALE_PREFIX); + expect(patched!.toolCalls![2]!.result).toBe("third ok"); + }); + + test("does not mutate the input messages or tool-call objects", () => { + const started = 1_000; + const now = started + PAST_DEFAULT_TIMEOUT_MS; + const tc = makeToolCall({ + id: "tc", + toolName: "web_search", + status: "running", + startedAt: started, + }); + const m = makeMessage({ + id: "a", + role: "assistant", + timestamp: started, + toolCalls: [tc], + }); + mockNow(now); + sanitizeDisplayMessages([m]); + expect(tc.status).toBe("running"); + expect(tc.result).toBeUndefined(); + expect(m.toolCalls![0]).toBe(tc); + }); + + test("preserves message identity when no tool calls are stale", () => { + // The sort step always returns a new outer array, so identity lives + // at the message level. Confirms hack #5 is COW at the message + // boundary when nothing needs patching. + const m1 = makeMessage({ + id: "a1", + role: "assistant", + timestamp: 100, + toolCalls: [ + makeToolCall({ + id: "tc-1", + toolName: "bash", + status: "completed", + startedAt: 100, + result: "ok", + }), + ], + }); + const m2 = makeMessage({ + id: "a2", + role: "assistant", + content: "done", + timestamp: 200, + }); + mockNow(10_000_000); + const result = sanitizeDisplayMessages([m1, m2]); + expect(result[0]).toBe(m1); + expect(result[1]).toBe(m2); + }); +}); + +// --------------------------------------------------------------------------- +// Integration — all five hacks compose // --------------------------------------------------------------------------- describe("sanitizeDisplayMessages · integration", () => { diff --git a/apps/web/src/domains/chat/utils/sanitize-display-messages.ts b/apps/web/src/domains/chat/utils/sanitize-display-messages.ts index 07151991d83..33342fff6d1 100644 --- a/apps/web/src/domains/chat/utils/sanitize-display-messages.ts +++ b/apps/web/src/domains/chat/utils/sanitize-display-messages.ts @@ -10,6 +10,8 @@ // only have to delete one file when the backend is fixed. // ----------------------------------------------------------------------------- +import { DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC } from "@vellumai/assistant-api"; + import { sortedByTimestamp } from "@/domains/chat/utils/message-sorting"; import type { ChatMessageToolCall } from "@/domains/chat/api/event-types"; import type { DisplayMessage } from "@/domains/chat/types/types"; @@ -22,6 +24,7 @@ export function sanitizeDisplayMessages( removeInvalidMessages, removeDuplicateTrailingAssistant, repairDanglingToolCalls, + failStaleToolCalls, ]; return pipeline.reduce((msgs, step) => step(msgs), messages); } @@ -271,3 +274,128 @@ function repairIfDangling(tc: ChatMessageToolCall): ChatMessageToolCall { result: SYNTHETIC_DANGLING_RESULT, }; } + +// ----------------------------------------------------------------------------- +// Hack #5 — fail stale tool calls on assistant restart / silent daemon death +// ----------------------------------------------------------------------------- +// Why it exists: when the assistant daemon restarts (or crashes silently) +// mid-tool-execution, it never delivers the `tool_result` SSE for the call +// it was running. Unlike Hack #4 — which patches dangling tools that have a +// SUBSEQUENT assistant message proving the tool completed server-side — +// this case has no subsequent activity at all. The bubble where the tool +// started simply spins forever, even across page reloads. +// +// This step is the client-side last line of defense. It applies whenever +// the elapsed time since the tool's last sign of life exceeds the +// configured execution timeout (plus a small grace buffer to absorb +// daemon-side delivery delay). +// +// Predicate (must ALL hold for a tool call to be patched): +// - `tool_call.status === "running"` (the UI's canonical "no result yet" +// signal — see `tool-call-chip.tsx`'s `isRunning`), +// - `tool_call.startedAt` is set (else we have no clock to measure +// against; typically only happens for tool calls hydrated from a +// pre-stamping history boundary), +// - `tool_call.pendingConfirmation` is null/undefined (a tool waiting on +// user approval is correctly stalled and must not be marked stale — +// the daemon's own execution timeout doesn't start until approval +// lands), +// - `(now - max(startedAt, lastProgressAt ?? 0)) > effectiveTimeoutMs + +// STALE_GRACE_MS`. +// +// `effectiveTimeoutMs` is `progressTimeoutSec * 1000` when the daemon +// reported a non-zero per-tool timeout via `tool_progress`, falling back +// to `DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC` (the canonical default the +// daemon uses when no override is configured). The fallback constant is +// exported from `@vellumai/assistant-api` so both backend enforcement +// and frontend detection reference the same wire-contract default — +// drift between them would let stale tools spin past the server-side +// ceiling, or worse, fail tools the server still considers in-flight. +// +// When all four hold, mutate the tool call to: +// - `status: "error"`, +// - `isError: true`, +// - `result: SYNTHETIC_STALE_RESULT` (explains the client-side timeout +// so a feedback report shows the root cause). +// +// Pipeline placement: runs AFTER `repairDanglingToolCalls`. Hack #4 has +// the stricter evidence (a later assistant message proves the server +// continued past the tool); whatever it leaves still-running gets +// evaluated against the timeout here. The two synthetic messages stay +// distinct on purpose — Hack #4 says "the server continued without us", +// Hack #5 says "we gave up waiting". +// +// SHORT TERM until: the assistant runtime survives restarts cleanly, +// either by persisting an "in-flight tool" record so the new process +// can emit a synthetic `tool_result` on boot, or by the gateway / host +// proxy buffering `tool_result` events across a daemon restart. +// ----------------------------------------------------------------------------- +const SYNTHETIC_STALE_RESULT = + "Tool call exceeded the execution timeout with no result. The assistant may have restarted while the tool was in flight — this is a client-side timeout, not a tool failure."; + +/** + * Grace period added on top of the configured execution timeout before a + * still-running tool call is treated as stale. Absorbs the daemon-side + * lag between hitting its own timeout (which produces a synthetic error + * tool_result) and that result actually crossing the SSE wire. Generous + * on purpose: false positives — marking a still-running tool as failed + * — are worse than a few seconds of extra spinner. + */ +const STALE_GRACE_MS = 30_000; + +function failStaleToolCalls(messages: DisplayMessage[]): DisplayMessage[] { + // Read the wall clock once at the top of this step so every tool + // call in this pass is evaluated against the same instant. Tests + // mock `Date.now` via `spyOn(Date, "now")` for deterministic + // stale-detection windows. + const nowMs = Date.now(); + let result: DisplayMessage[] | null = null; + for (let i = 0; i < messages.length; i++) { + const m = messages[i]!; + if (m.role !== "assistant" || !hasStaleToolCall(m, nowMs)) { + if (result) result.push(m); + continue; + } + if (!result) result = messages.slice(0, i); + result.push(withStaleToolCallsFailed(m, nowMs)); + } + return result ?? messages; +} + +function hasStaleToolCall(message: DisplayMessage, nowMs: number): boolean { + return message.toolCalls?.some((tc) => isStale(tc, nowMs)) ?? false; +} + +function withStaleToolCallsFailed( + message: DisplayMessage, + nowMs: number, +): DisplayMessage { + return { + ...message, + toolCalls: message.toolCalls!.map((tc) => + isStale(tc, nowMs) ? markStale(tc) : tc, + ), + }; +} + +function isStale(tc: ChatMessageToolCall, nowMs: number): boolean { + if (tc.status !== "running") return false; + if (tc.pendingConfirmation) return false; + if (tc.startedAt === undefined) return false; + const lastSignOfLife = Math.max(tc.startedAt, tc.lastProgressAt ?? 0); + const configuredSec = + tc.progressTimeoutSec && tc.progressTimeoutSec > 0 + ? tc.progressTimeoutSec + : DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC; + const effectiveTimeoutMs = configuredSec * 1000; + return nowMs - lastSignOfLife > effectiveTimeoutMs + STALE_GRACE_MS; +} + +function markStale(tc: ChatMessageToolCall): ChatMessageToolCall { + return { + ...tc, + status: "error", + isError: true, + result: SYNTHETIC_STALE_RESULT, + }; +} diff --git a/assistant/src/api/constants/tool-execution.ts b/assistant/src/api/constants/tool-execution.ts new file mode 100644 index 00000000000..2af6233e1cb --- /dev/null +++ b/assistant/src/api/constants/tool-execution.ts @@ -0,0 +1,21 @@ +/** + * Default cap (in seconds) on how long a single tool invocation may run + * before the assistant aborts it with a synthetic error result. This is + * the canonical default for the `timeouts.toolExecutionTimeoutSec` config + * field and the fallback used by `executeWithTimeout` when the config + * value is missing or invalid. + * + * Exposed on the API surface so frontend consumers — chiefly + * `sanitizeDisplayMessages` in the web client — can recognise tool + * calls whose live tracking outlives any plausible server-side + * execution and mark them as failed instead of spinning forever. The + * canonical case is an assistant restart mid-tool: the daemon never + * delivers the `tool_result` SSE, the client retains + * `status: "running"`, and the bubble would otherwise stall the UI + * across the restart boundary. + * + * Treat this as the wire contract for the default. Callers that need a + * different ceiling should still read the deployed config — this + * constant is only authoritative when the config doesn't override it. + */ +export const DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC = 120; diff --git a/assistant/src/api/index.ts b/assistant/src/api/index.ts index 5a927e97811..e7f0087c7d5 100644 --- a/assistant/src/api/index.ts +++ b/assistant/src/api/index.ts @@ -22,6 +22,7 @@ import { RelationshipStateUpdatedEventSchema } from "./events/relationship-state import { ToolUseStartEventSchema } from "./events/tool-use-start.js"; export { CALL_SITE_SYNTHETIC_AGENT_ERROR_MESSAGE } from "./constants/call-sites.js"; +export { DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC } from "./constants/tool-execution.js"; export { type AssistantOutboundAttachment, AssistantOutboundAttachmentSchema, diff --git a/assistant/src/config/schemas/timeouts.ts b/assistant/src/config/schemas/timeouts.ts index 520ba45796d..ad6075c1309 100644 --- a/assistant/src/config/schemas/timeouts.ts +++ b/assistant/src/config/schemas/timeouts.ts @@ -1,5 +1,7 @@ import { z } from "zod"; +import { DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC } from "../../api/constants/tool-execution.js"; + export const TimeoutConfigSchema = z .object({ shellMaxTimeoutSec: z @@ -30,7 +32,7 @@ export const TimeoutConfigSchema = z .number({ error: "timeouts.toolExecutionTimeoutSec must be a number" }) .finite("timeouts.toolExecutionTimeoutSec must be finite") .positive("timeouts.toolExecutionTimeoutSec must be a positive number") - .default(120) + .default(DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC) .describe("Default timeout for tool execution in seconds"), providerStreamTimeoutSec: z .number({ error: "timeouts.providerStreamTimeoutSec must be a number" }) diff --git a/assistant/src/tools/execution-timeout.ts b/assistant/src/tools/execution-timeout.ts index 4ae12269325..938d0695b73 100644 --- a/assistant/src/tools/execution-timeout.ts +++ b/assistant/src/tools/execution-timeout.ts @@ -1,9 +1,8 @@ +import { DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC } from "../api/constants/tool-execution.js"; import type { ToolExecutionResult } from "./types.js"; const TIMEOUT_SENTINEL = Symbol("tool-timeout"); -const DEFAULT_TOOL_TIMEOUT_SEC = 120; - /** * Convert a config-provided seconds value to a safe milliseconds value, * falling back to the default if the input is NaN, non-finite, zero, or negative. @@ -11,7 +10,7 @@ const DEFAULT_TOOL_TIMEOUT_SEC = 120; export function safeTimeoutMs(sec: unknown): number { const n = Number(sec); if (!Number.isFinite(n) || n <= 0) { - return DEFAULT_TOOL_TIMEOUT_SEC * 1000; + return DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC * 1000; } return n * 1000; } @@ -29,7 +28,7 @@ export async function executeWithTimeout( const safeMs = Number.isFinite(timeoutMs) && timeoutMs > 0 ? timeoutMs - : DEFAULT_TOOL_TIMEOUT_SEC * 1000; + : DEFAULT_TOOL_EXECUTION_TIMEOUT_SEC * 1000; let timeoutHandle: ReturnType; const timeoutPromise = new Promise((resolve) => { timeoutHandle = setTimeout(() => resolve(TIMEOUT_SENTINEL), safeMs);