diff --git a/packages/cli/src/__tests__/extension-tool-timeout.test.ts b/packages/cli/src/__tests__/extension-tool-timeout.test.ts index 66abf733c4..d4bf29ceaf 100644 --- a/packages/cli/src/__tests__/extension-tool-timeout.test.ts +++ b/packages/cli/src/__tests__/extension-tool-timeout.test.ts @@ -1,14 +1,59 @@ -import { describe, expect, it, vi } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { + __clearExtensionStoreBootStateForTesting, raceWithTimeoutAndAbort, + resolveExtensionToolTimeoutMs, wrapExtensionToolExecute, } from "../extension.js"; /* FNXC:MergeQueue 2026-07-15-11:15: FN-7956 hung AI merge review on unbounded extension fn_task_show. These unit tests lock the fail-closed timeout/abort budgets that unblock agent turns when store work wedges. + +FNXC:MergeQueue 2026-07-15-11:20: +Code review follow-up: per-tool budgets must not clip fn_research_run(wait_for_completion) (default max_wait_ms 90s) under a flat 60s outer wrap. */ +afterEach(() => { + __clearExtensionStoreBootStateForTesting(); + vi.restoreAllMocks(); +}); + +describe("resolveExtensionToolTimeoutMs", () => { + it("keeps the default 60s budget for ordinary store tools", () => { + expect(resolveExtensionToolTimeoutMs("fn_task_show")).toBe(60_000); + expect(resolveExtensionToolTimeoutMs("fn_task_list")).toBe(60_000); + }); + + it("raises the budget for fn_research_run wait_for_completion above default max_wait_ms", () => { + // Default max_wait_ms is 90s; outer wrap must be strictly larger. + expect( + resolveExtensionToolTimeoutMs("fn_research_run", { wait_for_completion: true }), + ).toBe(90_000 + 15_000); + }); + + it("honors explicit max_wait_ms for research wait", () => { + expect( + resolveExtensionToolTimeoutMs("fn_research_run", { + wait_for_completion: true, + max_wait_ms: 120_000, + }), + ).toBe(120_000 + 15_000); + }); + + it("keeps 60s for research when not waiting for completion", () => { + expect(resolveExtensionToolTimeoutMs("fn_research_run", { wait_for_completion: false })).toBe(60_000); + expect(resolveExtensionToolTimeoutMs("fn_research_run", {})).toBe(60_000); + }); + + it("gives multi-minute budgets to skills install and import/browse tools", () => { + expect(resolveExtensionToolTimeoutMs("fn_skills_install")).toBe(300_000); + expect(resolveExtensionToolTimeoutMs("fn_task_import_github")).toBe(180_000); + expect(resolveExtensionToolTimeoutMs("fn_task_browse_github_issues")).toBe(180_000); + expect(resolveExtensionToolTimeoutMs("fn_web_fetch")).toBe(90_000); + }); +}); + describe("raceWithTimeoutAndAbort", () => { it("resolves when the promise wins", async () => { await expect( @@ -63,6 +108,7 @@ describe("wrapExtensionToolExecute", () => { }); it("converts timeouts into isError tool results instead of hanging", async () => { + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); const execute = vi.fn( () => new Promise(() => { @@ -76,9 +122,11 @@ describe("wrapExtensionToolExecute", () => { details: { error: expect.stringMatching(/timed out after 25ms/) }, }); expect((result as { content: Array<{ text: string }> }).content[0].text).toContain("fn_hang failed"); + expect(warn).toHaveBeenCalledWith(expect.stringContaining("fn_hang")); }); it("converts abort into isError tool results", async () => { + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); const controller = new AbortController(); const execute = vi.fn( () => @@ -93,5 +141,31 @@ describe("wrapExtensionToolExecute", () => { isError: true, details: { error: "aborted" }, }); + expect(warn).toHaveBeenCalledWith(expect.stringContaining("fn_abort aborted")); + }); + + it("uses per-tool research wait budget when timeoutMs is omitted", async () => { + const execute = vi.fn(async () => ({ content: [{ type: "text" as const, text: "done" }] })); + const wrapped = wrapExtensionToolExecute("fn_research_run", execute); + // Should not use the flat 60s path for wait_for_completion — budget is 105s; this call is instant. + await expect( + wrapped("id", { wait_for_completion: true, max_wait_ms: 90_000 }, undefined), + ).resolves.toEqual({ content: [{ type: "text", text: "done" }] }); + expect(execute).toHaveBeenCalledOnce(); + }); + + it("does not clip a research wait that finishes under max_wait_ms but over 60s", async () => { + // Simulate a 70ms wait with a 100ms research budget (not the flat 60ms default for ordinary tools). + const execute = vi.fn( + async () => { + await new Promise((r) => setTimeout(r, 70)); + return { content: [{ type: "text" as const, text: "research-ok" }] }; + }, + ); + // Explicit small budget that still exceeds the simulated wait (params would resolve to 90s+ in prod). + const wrapped = wrapExtensionToolExecute("fn_research_run", execute, 150); + await expect( + wrapped("id", { wait_for_completion: true, max_wait_ms: 90_000 }, undefined), + ).resolves.toEqual({ content: [{ type: "text", text: "research-ok" }] }); }); }); diff --git a/packages/cli/src/extension.ts b/packages/cli/src/extension.ts index 208990ace2..6e1f808cb0 100644 --- a/packages/cli/src/extension.ts +++ b/packages/cli/src/extension.ts @@ -241,6 +241,13 @@ Concurrent first-call fn_* tools must share one boot promise. Without this, two */ const storeBootInflight = new Map>(); /* +FNXC:MergeQueue 2026-07-15-11:20: +After a hard boot failure, brief cooldown prevents stampede re-boots against a broken backend. +Timeout alone does not set cooldown — the orphan inflight may still succeed and populate storeCache. +*/ +const storeBootFailureCooldown = new Map(); +const BOOT_FAILURE_COOLDOWN_MS = 5_000; +/* FNXC:MergeQueue 2026-07-15-11:08: Propagate the active tool AbortSignal into getStore without rewriting every execute body. registerTool installs the signal here before invoking the real execute. */ @@ -249,9 +256,15 @@ const extensionToolSignal = new AsyncLocalStorage(); const EXTENSION_STORE_BOOT_TIMEOUT_MS = 30_000; /* FNXC:MergeQueue 2026-07-15-11:15: -Default wall-clock budget for every host-extension fn_* tool. Store/CRUD tools must not park an agent turn forever; long shell work belongs in coding builtins (bash), not extension tools. +Default wall-clock budget for store/CRUD host-extension tools. Long-running tools use resolveExtensionToolTimeoutMs instead of this flat default (research wait, skills install, imports). */ const EXTENSION_TOOL_TIMEOUT_MS = 60_000; +/** Slack added above fn_research_run max_wait_ms so the outer wrap cannot clip an intentional wait. */ +const RESEARCH_WAIT_SLACK_MS = 15_000; +const RESEARCH_DEFAULT_MAX_WAIT_MS = 90_000; +const SKILLS_INSTALL_TIMEOUT_MS = 300_000; +const IMPORT_BROWSE_TIMEOUT_MS = 180_000; +const WEB_FETCH_TIMEOUT_MS = 90_000; function isAbortError(error: unknown): boolean { return ( @@ -260,6 +273,31 @@ function isAbortError(error: unknown): boolean { ); } +/** + * FNXC:MergeQueue 2026-07-15-11:20: + * Per-tool outer budgets. A flat 60s wrap false-failed fn_research_run(wait_for_completion) whose default max_wait_ms is 90s. + * Store tools stay at 60s; intentional multi-minute tools get higher ceilings. + * + * @internal Exported for unit tests. + */ +export function resolveExtensionToolTimeoutMs(toolName: string, params?: unknown): number { + const name = toolName.trim(); + if (name === "fn_research_run") { + const record = params && typeof params === "object" ? (params as Record) : {}; + if (record.wait_for_completion === true) { + const rawMax = record.max_wait_ms; + const maxWait = + typeof rawMax === "number" && Number.isFinite(rawMax) ? Math.max(0, rawMax) : RESEARCH_DEFAULT_MAX_WAIT_MS; + return maxWait + RESEARCH_WAIT_SLACK_MS; + } + return EXTENSION_TOOL_TIMEOUT_MS; + } + if (name === "fn_skills_install") return SKILLS_INSTALL_TIMEOUT_MS; + if (name.startsWith("fn_task_import_") || name.startsWith("fn_task_browse_")) return IMPORT_BROWSE_TIMEOUT_MS; + if (name === "fn_web_fetch") return WEB_FETCH_TIMEOUT_MS; + return EXTENSION_TOOL_TIMEOUT_MS; +} + /** * Race a promise against a wall-clock timeout and optional AbortSignal. * Does not cancel the underlying work (Node has no structured cancel for store boot), @@ -288,7 +326,7 @@ export async function raceWithTimeoutAndAbort( if (onAbort && signal) signal.removeEventListener("abort", onAbort); fn(); }; - // Swallow late rejections after timeout/abort so the orphaned work cannot surface as unhandledRejection. + // Late settlement after timeout/abort is no-op'd; the .then handlers keep the promise from becoming unhandledRejection. promise.then( (value) => settle(() => resolve(value)), (error) => settle(() => reject(error)), @@ -318,11 +356,12 @@ export async function raceWithTimeoutAndAbort( * FNXC:MergeQueue 2026-07-15-11:15: * Wrap every extension tool execute with timeout + AbortSignal so a wedged store call cannot park the agent forever (FN-7956 fn_task_show hang). * Errors become isError tool results so the model can continue rather than leaving the turn blocked on an open tool call. + * FNXC:MergeQueue 2026-07-15-11:20: Timeout budget is per-tool (resolveExtensionToolTimeoutMs) unless an explicit timeoutMs is passed. */ export function wrapExtensionToolExecute( toolName: string, execute: (...args: TArgs) => TResult | Promise, - timeoutMs: number = EXTENSION_TOOL_TIMEOUT_MS, + timeoutMs?: number, ): (...args: TArgs) => Promise; details: { error: string }; @@ -331,17 +370,23 @@ export function wrapExtensionToolExecute( return async (...args: TArgs) => { // ExtensionAPI execute signature: (toolCallId, params, signal?, onUpdate?, ctx?) const signal = (args[2] instanceof AbortSignal ? args[2] : undefined) as AbortSignal | undefined; + const params = args[1]; + const budgetMs = + timeoutMs !== undefined && Number.isFinite(timeoutMs) && timeoutMs > 0 + ? timeoutMs + : resolveExtensionToolTimeoutMs(toolName, params); try { return await extensionToolSignal.run(signal, () => raceWithTimeoutAndAbort( Promise.resolve(execute(...args)), - timeoutMs, + budgetMs, signal, toolName, ), ); } catch (error) { if (isAbortError(error)) { + console.warn(`[fusion-extension] ${toolName} aborted`); return { content: [{ type: "text" as const, text: `${toolName} aborted.` }], details: { error: "aborted" }, @@ -349,6 +394,11 @@ export function wrapExtensionToolExecute( }; } const message = error instanceof Error ? error.message : String(error); + if (/timed out after \d+ms/.test(message)) { + console.warn(`[fusion-extension] ${toolName}: ${message}`); + } else { + console.error(`[fusion-extension] ${toolName} failed: ${message}`); + } return { content: [{ type: "text" as const, text: `${toolName} failed: ${message}` }], details: { error: message }, @@ -363,6 +413,13 @@ async function getStore(cwd: string, signal?: AbortSignal): Promise { const existing = storeCache.get(projectRoot); if (existing) return existing.store; + const cooldown = storeBootFailureCooldown.get(projectRoot); + if (cooldown && Date.now() < cooldown.untilMs) { + throw new Error( + `fn extension TaskStore boot recently failed (cooldown ${BOOT_FAILURE_COOLDOWN_MS}ms): ${cooldown.error}`, + ); + } + const effectiveSignal = signal ?? extensionToolSignal.getStore(); let inflight = storeBootInflight.get(projectRoot); @@ -374,25 +431,61 @@ async function getStore(cwd: string, signal?: AbortSignal): Promise { FNXC:MergeQueue 2026-07-15-11:08: First extension tool call in a dashboard/engine process boots a second TaskStore. Bound that boot and coalesce concurrent callers so a wedged boot cannot park every fn_* tool forever. + + FNXC:MergeQueue 2026-07-15-11:20: + Boot failure sets a short cooldown to avoid stampede re-boots. Tool timeout does not cancel the orphan boot; on success it still populates storeCache for later calls. */ inflight = (async () => { try { const boot = await createTaskStoreForBackend({ rootDir: projectRoot }); + storeBootFailureCooldown.delete(projectRoot); storeCache.set(projectRoot, { store: boot.taskStore, shutdown: boot.shutdown }); return boot.taskStore; + } catch (error) { + const message = error instanceof Error ? error.message : String(error); + storeBootFailureCooldown.set(projectRoot, { + untilMs: Date.now() + BOOT_FAILURE_COOLDOWN_MS, + error: message, + }); + throw error; } finally { storeBootInflight.delete(projectRoot); } })(); + // Keep a handler attached so timed-out waiters cannot leave an unhandledRejection when boot fails late. + void inflight.catch(() => undefined); storeBootInflight.set(projectRoot, inflight); } - return raceWithTimeoutAndAbort( - inflight, - EXTENSION_STORE_BOOT_TIMEOUT_MS, - effectiveSignal, - "fn extension TaskStore boot", - ); + try { + return await raceWithTimeoutAndAbort( + inflight, + EXTENSION_STORE_BOOT_TIMEOUT_MS, + effectiveSignal, + "fn extension TaskStore boot", + ); + } catch (error) { + const message = error instanceof Error ? error.message : String(error); + if (/timed out after \d+ms/.test(message)) { + /* + FNXC:MergeQueue 2026-07-15-11:20: + Timeout unblocks the tool turn only — the orphan createTaskStoreForBackend continues. Log so operators do not assume the dual-store boot stopped. + */ + console.warn( + `[fusion-extension] TaskStore boot still running after ${EXTENSION_STORE_BOOT_TIMEOUT_MS}ms ` + + `(projectRoot=${projectRoot}); orphan boot continues and may populate the cache later`, + ); + } + throw error; + } +} + +/** + * @internal Test-only: clear inflight boot map and failure cooldown without closing cached stores. + */ +export function __clearExtensionStoreBootStateForTesting(): void { + storeBootInflight.clear(); + storeBootFailureCooldown.clear(); } /** diff --git a/packages/engine/src/__tests__/agent-session-helpers.test.ts b/packages/engine/src/__tests__/agent-session-helpers.test.ts index 6811834141..37591f52e9 100644 --- a/packages/engine/src/__tests__/agent-session-helpers.test.ts +++ b/packages/engine/src/__tests__/agent-session-helpers.test.ts @@ -596,6 +596,44 @@ describe("createResolvedAgentSession", () => { ); }); + it("forwards sessionPurpose into runtime.createSession for host-extension policy", async () => { + /* + FNXC:MergeQueue 2026-07-15-11:20: + FN-7956 fix requires sessionPurpose "merger" to reach createFnAgent so host extensions are skipped. + */ + const mockSession = { prompt: vi.fn() } as any; + const createSessionMock = vi.fn().mockResolvedValue({ + session: mockSession, + sessionFile: "session.json", + }); + resolveRuntimeMock.mockResolvedValue({ + runtime: { + id: "pi", + name: "Default PI Runtime", + createSession: createSessionMock, + promptWithFallback: vi.fn(), + describeModel: vi.fn(() => "mock/model"), + }, + runtimeId: "pi", + wasConfigured: false, + }); + + const { createResolvedAgentSession } = await import("../agent-session-helpers.js"); + + await createResolvedAgentSession({ + sessionPurpose: "merger", + pluginRunner: undefined, + cwd: "/tmp/project", + systemPrompt: "merge", + }); + + expect(createSessionMock).toHaveBeenCalledWith( + expect.objectContaining({ + sessionPurpose: "merger", + }), + ); + }); + it("emits session:runtime-resolved when runAuditor is provided", async () => { const mockSession = { prompt: vi.fn() } as any; const createSessionMock = vi.fn().mockResolvedValue({ session: mockSession }); diff --git a/packages/engine/src/pi.ts b/packages/engine/src/pi.ts index da44fa8096..6cde3c70ff 100644 --- a/packages/engine/src/pi.ts +++ b/packages/engine/src/pi.ts @@ -2281,9 +2281,14 @@ export async function createFnAgent(options: AgentOptions): Promise const skipHostExtensions = isReadonly || options.sessionPurpose === "merger"; const effectiveExtensionPaths = skipHostExtensions ? [] : hostExtensionPaths; if (skipHostExtensions && hostExtensionPaths.length > 0) { - piLog.log( - `${isReadonly ? "readonly" : "merger"} session — host extensions (${hostExtensionPaths.length}) skipped`, - ); + /* + FNXC:MergeQueue 2026-07-15-11:20: + Log the actual skip reason (readonly vs sessionPurpose) so future skip reasons do not mislabel as "merger". + */ + const skipReason = isReadonly + ? "readonly" + : `sessionPurpose=${options.sessionPurpose ?? "unknown"}`; + piLog.log(`${skipReason} session — host extensions (${hostExtensionPaths.length}) skipped`); } const resourceLoader = new DefaultResourceLoader({