diff --git a/packages/server/src/server/agent/providers/omp/agent.test.ts b/packages/server/src/server/agent/providers/omp/agent.test.ts index 19aaa5d75c1..a2d6f138ec8 100644 --- a/packages/server/src/server/agent/providers/omp/agent.test.ts +++ b/packages/server/src/server/agent/providers/omp/agent.test.ts @@ -1,8 +1,14 @@ -import { describe, expect, test } from "vitest"; -import { setImmediate as waitForImmediate } from "node:timers/promises"; +import { afterEach, describe, expect, test } from "vitest"; +import { setImmediate as waitForImmediate, setTimeout as delay } from "node:timers/promises"; import type { PaseoToolCatalog } from "../../tools/types.js"; -import type { OmpNoTurnScheduler, OmpProviderIdleScheduler } from "./agent.js"; +import type { + OmpNoTurnScheduler, + OmpProviderIdleAttempt, + OmpProviderIdleDecision, + OmpProviderIdleScheduler, +} from "./agent.js"; +import { createOmpProviderIdleScheduler } from "./agent.js"; import type { OmpUsagePollScheduler } from "./usage-poller.js"; import { OmpHarness } from "./test-utils/omp-harness.js"; @@ -14,18 +20,68 @@ function lastToolCallStatus(omp: OmpHarness, callId: string): string | undefined return last?.type === "tool_call" ? last.status : undefined; } +// Every ManualIdleScheduler registers here so a poll after the gate was +// abandoned fails the test that caused it. Throwing cannot: the gate's promise +// is consumed by a `.catch()` at the agent_end call site, so a throw would stop +// the runaway loop silently and the test would still pass. +const manualIdleSchedulers: ManualIdleScheduler[] = []; + +afterEach(() => { + const violations = manualIdleSchedulers.flatMap((scheduler) => scheduler.violations()); + manualIdleSchedulers.length = 0; + expect(violations).toEqual([]); +}); + class ManualIdleScheduler implements OmpProviderIdleScheduler { private readonly retries: Array<() => void> = []; private readonly waiters: Array<{ count: number; resolve: () => void }> = []; + private readonly seen: OmpProviderIdleAttempt[] = []; + private readonly abandonedPolls: string[] = []; private waitCount = 0; + private abandoned = false; + + constructor( + private readonly decide: (attempt: OmpProviderIdleAttempt) => OmpProviderIdleDecision = () => ({ + retry: true, + }), + ) { + manualIdleSchedulers.push(this); + } - waitForRetry(): Promise { + waitForRetry(attempt: OmpProviderIdleAttempt): Promise { + if (this.abandoned) { + // Recorded, not thrown, and counted before waitCount moves: a violating + // poll must not satisfy a waitForWaits() a test is blocked on. Denying + // again stops the loop instead of spinning with no timer. + // Capped: a runaway loop must report through afterEach rather than + // exhausting the worker before the assertion runs. + if (this.abandonedPolls.length < 8) { + this.abandonedPolls.push( + `OMP polled again after the idle scheduler abandoned the gate (attempt ${attempt.attempt})`, + ); + } + return Promise.resolve({ retry: false, reason: "wait_budget" }); + } this.waitCount += 1; + this.seen.push(attempt); for (const waiter of this.waiters.splice(0)) { if (this.waitCount >= waiter.count) waiter.resolve(); else this.waiters.push(waiter); } - return new Promise((resolve) => this.retries.push(resolve)); + const decision = this.decide(attempt); + if (!decision.retry) { + this.abandoned = true; + return Promise.resolve(decision); + } + return new Promise((resolve) => this.retries.push(() => resolve(decision))); + } + + violations(): string[] { + return this.abandonedPolls; + } + + attempts(): OmpProviderIdleAttempt[] { + return this.seen; } waitForWaits(count: number): Promise { @@ -38,6 +94,10 @@ class ManualIdleScheduler implements OmpProviderIdleScheduler { if (!resolve) throw new Error("OMP has not requested an idle-state retry"); resolve(); } + + retryAll(): void { + for (const resolve of this.retries.splice(0)) resolve(); + } } class ManualNoTurnScheduler implements OmpNoTurnScheduler { @@ -337,6 +397,361 @@ describe("OMP agent client and session", () => { await expect(completion).resolves.toMatchObject({ finalText: "first done" }); }); + test("completes once when OMP repeats agent_end for the same turn", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await omp.waitForProviderStateChecks(2); + await scheduler.waitForWaits(1); + + // OMP can end a second cycle for the same prompt; the terminal assistant + // message it already streamed would otherwise open a second gate. + omp.runtime().finishTurn(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + expect(scheduler.attempts()).toHaveLength(1); + + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + scheduler.retryAll(); + await expect(completion).resolves.toMatchObject({ finalText: "first done" }); + await waitForImmediate(); + expect(omp.completedTurnCount()).toBe(1); + }); + + test("fails the turn when OMP never reports idle", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/idle/i); + expect(omp.completedTurnCount()).toBe(0); + expect(omp.failedTurns()).toMatchObject([ + { + code: "omp_provider_idle_timeout", + diagnostic: expect.stringContaining("isStreaming=true"), + }, + ]); + }); + + test("fails the turn when OMP state checks keep failing", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.consecutiveFailures < 2 + ? { retry: true } + : { retry: false, reason: "failure_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + omp.failProviderStateChecks(new Error("state unavailable")); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/state/i); + expect(omp.completedTurnCount()).toBe(0); + expect(omp.failedTurns()).toMatchObject([ + { + code: "omp_provider_state_unavailable", + diagnostic: expect.stringContaining("state unavailable"), + }, + ]); + }); + + test("accepts a new prompt after a stalled turn fails", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + scheduler.retryAll(); + await expect(completion).rejects.toThrow(/idle/i); + + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + await expect(omp.runPrompt("second", "second done")).resolves.toMatchObject({ + finalText: "second done", + }); + }); + + test("completes an autonomous turn once when OMP repeats agent_end", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + omp.startAutonomousTurnUntilProviderIdle("autonomous done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + omp.runtime().finishTurn(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + expect(scheduler.attempts()).toHaveLength(1); + + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + scheduler.retryAll(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + expect(omp.completedTurnCount()).toBe(1); + }); + + test("reports the last OMP state when the idle wait budget expires after a failed check", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 3 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + omp.failProviderStateChecks(new Error("state unavailable")); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/idle/i); + expect(omp.failedTurns()).toMatchObject([ + { + code: "omp_provider_idle_timeout", + diagnostic: expect.stringContaining("isStreaming=true"), + }, + ]); + // The failing check is still evidence; it must not be dropped. + expect(omp.failedTurns()[0]?.diagnostic).toContain("state unavailable"); + }); + + test("fails the turn with the newest agent_end error", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + omp.runtime().finishTurn({ role: "assistant", content: [], errorMessage: "provider exploded" }); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/provider exploded/); + expect(omp.completedTurnCount()).toBe(0); + }); + + test("the default idle scheduler stops on its wait and failure budgets", async () => { + const scheduler = createOmpProviderIdleScheduler(); + + await expect( + scheduler.waitForRetry({ + attempt: 1, + consecutiveFailures: 0, + elapsedMs: 0, + totalElapsedMs: 0, + isCompacting: false, + isWaitingOnSubagents: false, + }), + ).resolves.toEqual({ retry: true }); + await expect( + scheduler.waitForRetry({ + attempt: 200, + consecutiveFailures: 0, + elapsedMs: 60_000, + totalElapsedMs: 60_000, + isCompacting: false, + isWaitingOnSubagents: false, + }), + ).resolves.toEqual({ retry: false, reason: "wait_budget" }); + await expect( + scheduler.waitForRetry({ + attempt: 3, + consecutiveFailures: 3, + elapsedMs: 100, + totalElapsedMs: 100, + isCompacting: false, + isWaitingOnSubagents: false, + }), + ).resolves.toEqual({ retry: false, reason: "failure_budget" }); + }); + + test("cancels in-flight tool calls when a turn stalls", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + omp.runtime().emit({ + type: "tool_execution_start", + toolCallId: "tool-1", + toolName: "bash", + args: { command: "sleep 30" }, + }); + expect(omp.runningToolCallIds()).toEqual(["tool-1"]); + + await scheduler.waitForWaits(1); + scheduler.retryAll(); + await expect(completion).rejects.toThrow(/idle/i); + + expect(omp.runningToolCallIds()).toEqual([]); + }); + + test("does not fail a turn that started after the gate was abandoned", async () => { + // The deny lands after ownership has moved on: get_state and waitForRetry are + // both awaits, so the turn can change under a parked gate. + let releaseDeny!: () => void; + let gateParked!: () => void; + const parked = new Promise((resolve) => { + gateParked = resolve; + }); + const scheduler: OmpProviderIdleScheduler = { + waitForRetry: () => { + gateParked(); + return new Promise((resolve) => { + releaseDeny = () => resolve({ retry: false, reason: "wait_budget" }); + }); + }, + }; + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await parked; + + // The user gives up on the stuck turn and sends another one. + await omp.interrupt(); + await completion; + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + await omp.requireStartTurn("second"); + + releaseDeny(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + + expect(omp.failedTurns()).toEqual([]); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.streamAssistantText("second done"); + runtime.finishTurn(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + expect(omp.completedTurnCount()).toBe(1); + }); + + test("keeps polling past the idle budget while OMP reports compacting", async () => { + const scheduler = createOmpProviderIdleScheduler(); + + await expect( + scheduler.waitForRetry({ + attempt: 1, + consecutiveFailures: 0, + elapsedMs: 120_000, + totalElapsedMs: 120_000, + isCompacting: true, + isWaitingOnSubagents: false, + }), + ).resolves.toEqual({ retry: true }); + await expect( + scheduler.waitForRetry({ + attempt: 1, + consecutiveFailures: 0, + elapsedMs: 120_000, + totalElapsedMs: 120_000, + isCompacting: false, + isWaitingOnSubagents: false, + }), + ).resolves.toEqual({ retry: false, reason: "wait_budget" }); + }); + + test("reports the observed compaction state and elapsed time to the scheduler", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: false, + isCompacting: true, + }); + await scheduler.waitForWaits(1); + expect(scheduler.attempts()[0]?.isCompacting).toBe(true); + + await delay(5); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.elapsedMs).toBeGreaterThanOrEqual(5); + }); + + test("keeps an earlier agent_end error when a later cycle reports none", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + omp.runtime().finishTurn({ role: "assistant", content: [], errorMessage: "provider exploded" }); + omp.runtime().finishTurn(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/provider exploded/); + }); + + test("reports an unavailable state path when no OMP state was ever observed", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + omp.failProviderStateChecks(new Error("state unavailable")); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/state/i); + expect(omp.failedTurns()).toMatchObject([{ code: "omp_provider_state_unavailable" }]); + expect(omp.failedTurns()[0]?.diagnostic).toContain("2 consecutive failures"); + }); + // #2232: parent model loop can go idle while OMP-internal `task` children // keep writing. Wire order is tool_execution_end (dispatch ack) then // subagent_lifecycle started — never the reverse. @@ -661,6 +1076,525 @@ describe("OMP agent client and session", () => { expect(omp.runningToolCallIds()).toEqual([]); }); + test("waits past the idle budget while OMP reports running subagents", async () => { + const scheduler = createOmpProviderIdleScheduler(); + + await expect( + scheduler.waitForRetry({ + attempt: 1, + consecutiveFailures: 0, + elapsedMs: 120_000, + totalElapsedMs: 120_000, + isCompacting: false, + isWaitingOnSubagents: true, + }), + ).resolves.toEqual({ retry: true }); + }); + + test("stops trusting a subagent wait once get_subagents stops answering", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + omp.reportSubagentSnapshots([{ id: "child-1", index: 0, agent: "worker", status: "running" }]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // A snapshot that cannot be fetched is not evidence that work continues, so + // the clock keeps running even though the gate still waits on the child. + omp.failSubagentSnapshots(new Error("subagents unavailable")); + clock += 120_000; + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.isWaitingOnSubagents).toBe(true); + expect(scheduler.attempts()[1]?.elapsedMs).toBeGreaterThanOrEqual(120_000); + void completion; + }); + + test("does not let an unconfirmed subagent hold the clock open", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + await omp.requireStartTurn("fan out"); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.acceptPrompt("fan out", "user-fan"); + runtime.streamAssistantText("dispatching"); + // A lifecycle child that no get_subagents reply ever lists: the gate still + // waits on it, but OMP has never confirmed it is doing anything. + runtime.emit({ + type: "subagent_lifecycle", + payload: { id: "child-1", agent: "worker", status: "started", index: 0 }, + }); + runtime.state = { ...runtime.state, isStreaming: false, isCompacting: false }; + runtime.finishTurn(); + + await scheduler.waitForWaits(1); + expect(scheduler.attempts()[0]?.isWaitingOnSubagents).toBe(true); + clock += 90_000; + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.elapsedMs).toBeGreaterThanOrEqual(90_000); + }); + + test("does not credit progress when get_state fails", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + omp.reportSubagentSnapshots([{ id: "child-1", index: 0, agent: "worker", status: "running" }]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // With get_state down there is no fresh subagent reply either, so the last + // confirmation must not keep restarting the clock. + omp.failProviderStateChecks(new Error("state unavailable")); + clock += 120_000; + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.elapsedMs).toBeGreaterThanOrEqual(120_000); + void completion; + }); + + test("names unconfirmed subagents when the gate gives up waiting on them", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + omp.reportSubagentSnapshots([{ id: "child-1", index: 0, agent: "worker", status: "running" }]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // The snapshot path goes down while the index still holds a running child. + omp.failSubagentSnapshots(new Error("subagents unavailable")); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/subagent/i); + expect(omp.failedTurns()[0]?.diagnostic).toContain("running subagents"); + }); + + test("does not claim consecutive failures when the last state check succeeded", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 3 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + omp.failProviderStateChecks(new Error("state unavailable")); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + omp.failProviderStateChecks(null); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(); + const diagnostic = omp.failedTurns()[0]?.diagnostic ?? ""; + expect(diagnostic).toContain("state unavailable"); + expect(diagnostic).not.toContain("consecutive failures"); + }); + + test("does not spend the idle budget while OMP is still emitting events", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // OMP streams a second cycle for the same prompt: slow, but demonstrably + // alive. Silence is the stall this budget is for, not elapsed time. + clock += 90_000; + omp.runtime().streamAssistantText("still working"); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.elapsedMs).toBeLessThan(60_000); + + // Now it goes quiet. + clock += 90_000; + scheduler.retryAll(); + await scheduler.waitForWaits(3); + expect(scheduler.attempts()[2]?.elapsedMs).toBeGreaterThanOrEqual(90_000); + void completion; + }); + + test("keeps spending the budget while the reported state oscillates", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // A flag flipping back and forth is not progress, so each budget keeps its + // own accrued silence instead of being reset by the change. + for (let round = 0; round < 4; round += 1) { + clock += 60_000; + omp.reportProviderState({ + isStreaming: round % 2 === 0, + isCompacting: round % 2 === 1, + }); + scheduler.retryAll(); + await scheduler.waitForWaits(round + 2); + } + const stallSilence = scheduler + .attempts() + .filter((attempt) => !attempt.isCompacting) + .map((attempt) => attempt.elapsedMs); + expect(stallSilence.at(-1)).toBeGreaterThanOrEqual(120_000); + void completion; + }); + + test("reports the live subagent state when the gate gives up", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 3 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => 0 }); + await omp.start(); + + omp.reportSubagentSnapshots([{ id: "child-1", index: 0, agent: "worker", status: "running" }]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // The child reports done, then the parent stalls with nothing running. + omp.runtime().emit({ + type: "subagent_lifecycle", + payload: { id: "child-1", agent: "worker", status: "completed", index: 0 }, + }); + omp.reportProviderState({ isStreaming: true, isCompacting: false }); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + scheduler.retryAll(); + + await expect(completion).rejects.toThrow(/idle state/); + expect(omp.failedTurns()).toMatchObject([{ code: "omp_provider_idle_timeout" }]); + expect(omp.failedTurns()[0]?.diagnostic).not.toContain("subagents"); + }); + + test("does not complete a turn the gate no longer owns", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // Park the gate inside get_state, which carries the RPC timeout, and let the + // turn change while it is in there. + omp.reportProviderState({ isStreaming: false, isCompacting: false }); + omp.runtime().holdStateChecks = true; + scheduler.retryAll(); + await omp.waitForProviderStateChecks(2); + await omp.interrupt(); + await completion; + const completedAfterCancel = omp.completedTurnCount(); + + omp.runtime().releaseStateChecks(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + expect(omp.completedTurnCount()).toBe(completedAfterCancel); + }); + + test("does not charge compaction silence to the stall budget when compaction ends", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: false, + isCompacting: true, + }); + await scheduler.waitForWaits(1); + + // Three silent minutes of auto-compaction, well inside its own budget. + clock += 180_000; + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.isCompacting).toBe(true); + + // Compaction ends and the model resumes before emitting its first token. + omp.reportProviderState({ isStreaming: true, isCompacting: false }); + scheduler.retryAll(); + await scheduler.waitForWaits(3); + expect(scheduler.attempts()[2]?.isCompacting).toBe(false); + expect(scheduler.attempts()[2]?.elapsedMs).toBeLessThan(60_000); + expect(omp.failedTurns()).toEqual([]); + void completion; + }); + + test("does not treat an unchanging subagent snapshot as progress", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + omp.reportSubagentSnapshots([ + { id: "child-1", index: 0, agent: "worker", status: "running", lastUpdate: 1 }, + ]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // The same reply, over and over, is a stuck child rather than a working one. + for (let round = 0; round < 3; round += 1) { + clock += 120_000; + scheduler.retryAll(); + await scheduler.waitForWaits(round + 2); + } + expect(scheduler.attempts()[3]?.isWaitingOnSubagents).toBe(true); + expect(scheduler.attempts()[3]?.elapsedMs).toBeGreaterThanOrEqual(240_000); + void completion; + }); + + test("counts a moving subagent snapshot as progress", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + omp.reportSubagentSnapshots([ + { id: "child-1", index: 0, agent: "worker", status: "running", lastUpdate: 1 }, + ]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + clock += 120_000; + omp.reportSubagentSnapshots([ + { id: "child-1", index: 0, agent: "worker", status: "running", lastUpdate: 2 }, + ]); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + clock += 1_000; + scheduler.retryAll(); + await scheduler.waitForWaits(3); + expect(scheduler.attempts()[2]?.elapsedMs).toBeLessThan(120_000); + void completion; + }); + + test("counts a subagent progress frame as progress", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + await omp.requireStartTurn("fan out"); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.acceptPrompt("fan out", "user-fan"); + runtime.streamAssistantText("dispatching"); + runtime.emit({ + type: "subagent_lifecycle", + payload: { id: "child-1", agent: "worker", status: "started", index: 0 }, + }); + runtime.state = { ...runtime.state, isStreaming: false, isCompacting: false }; + runtime.finishTurn(); + // Legacy OMP: no snapshot path, only narration. + omp.failSubagentSnapshots(new Error("unknown command get_subagents")); + await scheduler.waitForWaits(1); + + clock += 120_000; + runtime.emit({ + type: "subagent_progress", + payload: { + id: "child-1", + agent: "worker", + index: 0, + progress: { id: "child-1", status: "running" }, + }, + }); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.elapsedMs).toBeLessThan(120_000); + }); + + test("stops reporting a subagent wait once the child reports done", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + omp.reportSubagentSnapshots([{ id: "child-1", index: 0, agent: "worker", status: "running" }]); + const { completion } = await omp.startPromptUntilProviderIdle("fan out", "dispatched", { + isStreaming: false, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + expect(scheduler.attempts()[0]?.isWaitingOnSubagents).toBe(true); + + omp.runtime().emit({ + type: "subagent_lifecycle", + payload: { id: "child-1", agent: "worker", status: "completed", index: 0 }, + }); + // The model goes busy, so the gate cannot re-poll get_subagents. + omp.reportProviderState({ isStreaming: true, isCompacting: false }); + scheduler.retryAll(); + await scheduler.waitForWaits(2); + expect(scheduler.attempts()[1]?.isWaitingOnSubagents).toBe(false); + void completion; + }); + + test("gives up on a stalled turn even while OMP keeps chattering", async () => { + let clock = 0; + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => clock }); + await omp.start(); + + const { completion } = await omp.startPromptUntilProviderIdle("first", "first done", { + isStreaming: true, + isCompacting: false, + }); + await scheduler.waitForWaits(1); + + // Host-level chatter is not the turn advancing, and even if it were, the + // gate must not outlive its ceiling. + for (let round = 0; round < 6; round += 1) { + clock += 600_000; + omp.runtime().emit({ type: "notice", level: "info", message: "mcp server reloaded" }); + scheduler.retryAll(); + await scheduler.waitForWaits(round + 2); + } + const last = scheduler.attempts().at(-1); + expect(last?.elapsedMs).toBeGreaterThanOrEqual(600_000); + expect(last?.totalElapsedMs).toBeGreaterThanOrEqual(3_600_000); + void completion; + }); + + test("the default idle scheduler stops at the ceiling whatever the class", async () => { + const scheduler = createOmpProviderIdleScheduler(); + + await expect( + scheduler.waitForRetry({ + attempt: 1, + consecutiveFailures: 0, + elapsedMs: 0, + totalElapsedMs: 3_600_000, + isCompacting: true, + isWaitingOnSubagents: true, + }), + ).resolves.toEqual({ retry: false, reason: "wait_budget" }); + }); + + test("counts a running tool call as outstanding work", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + await omp.requireStartTurn("run something slow"); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.acceptPrompt("run something slow", "user-1"); + runtime.streamAssistantText("running"); + runtime.emit({ + type: "tool_execution_start", + toolCallId: "tool-1", + toolName: "bash", + args: { command: "sleep 600" }, + }); + runtime.state = { ...runtime.state, isStreaming: true, isCompacting: false }; + runtime.finishTurn(); + + await scheduler.waitForWaits(1); + expect(scheduler.attempts()[0]?.isWaitingOnSubagents).toBe(true); + }); + + test("does not count a tool call left over from an earlier turn", async () => { + const scheduler = new ManualIdleScheduler(); + const omp = new OmpHarness({ providerIdleScheduler: scheduler }); + await omp.start(); + + // Turn one leaks a tool call: OMP never sends its tool_execution_end. + await omp.requireStartTurn("first"); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.acceptPrompt("first", "user-1"); + runtime.emit({ + type: "tool_execution_start", + toolCallId: "orphan-1", + toolName: "bash", + args: { command: "sleep 1" }, + }); + runtime.streamAssistantText("first done"); + runtime.state = { ...runtime.state, isStreaming: false, isCompacting: false }; + runtime.finishTurn(); + for (let flush = 0; flush < 5; flush += 1) await waitForImmediate(); + + await omp.requireStartTurn("second"); + runtime.beginTurn(); + runtime.acceptPrompt("second", "user-2"); + runtime.streamAssistantText("second running"); + runtime.state = { ...runtime.state, isStreaming: true, isCompacting: false }; + runtime.finishTurn(); + + await scheduler.waitForWaits(1); + expect(scheduler.attempts()[0]?.isWaitingOnSubagents).toBe(false); + }); + + test("does not describe finished children as a subagent stall", async () => { + const scheduler = new ManualIdleScheduler((attempt) => + attempt.attempt < 2 ? { retry: true } : { retry: false, reason: "wait_budget" }, + ); + const omp = new OmpHarness({ providerIdleScheduler: scheduler, now: () => 0 }); + await omp.start(); + + // A reply listing only finished children names nothing still going. + omp.reportSubagentSnapshots([ + { id: "child-1", index: 0, agent: "worker", status: "completed" }, + ]); + await omp.requireStartTurn("fan out"); + const runtime = omp.runtime(); + runtime.beginTurn(); + runtime.acceptPrompt("fan out", "user-fan"); + runtime.streamAssistantText("dispatching"); + runtime.emit({ + type: "subagent_lifecycle", + payload: { id: "child-2", agent: "worker", status: "started", index: 1 }, + }); + runtime.state = { ...runtime.state, isStreaming: false, isCompacting: false }; + runtime.finishTurn(); + + await scheduler.waitForWaits(1); + scheduler.retryAll(); + await waitForImmediate(); + + expect(omp.failedTurns()[0]?.diagnostic).toContain("would not confirm"); + }); + test("does not complete on OMP's extension-notice agent_end", async () => { const omp = new OmpHarness(); await omp.start(); diff --git a/packages/server/src/server/agent/providers/omp/agent.ts b/packages/server/src/server/agent/providers/omp/agent.ts index c24266d1577..0985da254c7 100644 --- a/packages/server/src/server/agent/providers/omp/agent.ts +++ b/packages/server/src/server/agent/providers/omp/agent.ts @@ -81,6 +81,7 @@ import type { OmpModel, OmpRuntimeEvent, OmpSessionState, + OmpSubagentSnapshot, OmpThinkingLevel, } from "./rpc-types.js"; import { @@ -137,10 +138,53 @@ export interface OmpAgentClientOptions { providerIdleScheduler?: OmpProviderIdleScheduler; noTurnScheduler?: OmpNoTurnScheduler; usagePollScheduler?: OmpUsagePollScheduler; + /** Monotonic clock for the provider-idle budget; injected by tests. */ + now?: () => number; +} + +export interface OmpProviderIdleAttempt { + /** State checks already made for this completion gate, 1-based. */ + attempt: number; + /** Consecutive `get_state` rejections; any successful response resets it. */ + consecutiveFailures: number; + /** + * Monotonic silence: time since OMP last showed a sign of life, accrued + * separately for each budget so time under a long one is never inherited by a + * shorter one. Elapsed time alone is not a stall. + */ + elapsedMs: number; + /** + * Monotonic time since the gate opened, which no progress signal resets. Four + * review rounds each found a different signal that could be stuck on, so the + * ceiling is what makes the wait bounded without having to enumerate them. + */ + totalElapsedMs: number; + /** Whether the last observed state reported compaction in progress. */ + isCompacting: boolean; + /** Whether OMP-internal subagents or tool calls from this turn are outstanding. */ + isWaitingOnSubagents: boolean; +} + +/** + * `reason` names the exhausted budget so the turn reports why it stopped rather + * than inferring it from whichever check happened to be last. + */ +export type OmpProviderIdleDecision = + | { retry: true } + | { retry: false; reason: "wait_budget" | "failure_budget" }; + +interface OmpProviderIdleSilence { + compacting: number; + work: number; + other: number; + lastPollAt: number; + lastEventAt: number; + fingerprint: string | null; } export interface OmpProviderIdleScheduler { - waitForRetry(): Promise; + /** Wait before the next state check, or abandon the gate so the turn fails. */ + waitForRetry(attempt: OmpProviderIdleAttempt): Promise; } export interface OmpNoTurnScheduler { @@ -185,6 +229,7 @@ interface OmpAgentSessionOptions { providerIdleScheduler?: OmpProviderIdleScheduler; noTurnScheduler?: OmpNoTurnScheduler; usagePollScheduler?: OmpUsagePollScheduler; + now?: () => number; paseoTools?: PaseoToolCatalog; /** * When false (resumed sessions), replayed session events are dropped until @@ -194,10 +239,70 @@ interface OmpAgentSessionOptions { live?: boolean; } -function createOmpProviderIdleScheduler(): OmpProviderIdleScheduler { +// Autonomous OMP cycles carry no turn ID; they still need a gate key of their own. +const OMP_AUTONOMOUS_GATE_KEY = "autonomous"; + +// OMP processes a state request only once its RPC loop is promptable again, so +// the first checks after agent_end usually miss. Poll fast at first, then back +// off: a stalled provider otherwise costs 100 RPCs a second for as long as the +// stall lasts. +const OMP_PROVIDER_IDLE_MIN_RETRY_MS = 10; +const OMP_PROVIDER_IDLE_MAX_RETRY_MS = 1_000; +// Wall clock, not a retry count: each get_state carries the JSONL-RPC request +// timeout, so counting attempts would let a slow-but-answering state path stretch +// the wait to tens of minutes. +const OMP_PROVIDER_IDLE_BUDGET_MS = 60_000; +// Compaction is a model call over the whole context, so it routinely outlasts the +// idle budget. Waiting on a reported compaction is not the stall this gate guards +// against, but it still needs an end. +const OMP_PROVIDER_COMPACTING_BUDGET_MS = 600_000; +// A fan-out has no bounded length, so this bounds silence about one, not the +// fan-out itself: a reply whose running children changed restarts the clock. +const OMP_PROVIDER_SUBAGENT_BUDGET_MS = 600_000; +// A get_state rejection already costs a full RPC timeout, so a few in a row are +// enough evidence that the state path is gone. +const OMP_PROVIDER_IDLE_FAILURE_BUDGET = 3; +// The wait no progress signal can extend. Generous enough for a real fan-out, +// finite so an unforeseen signal stuck on cannot restore the unbounded poll. +const OMP_PROVIDER_IDLE_CEILING_MS = 3_600_000; + +function ompProviderIdleRetryDelayMs(attempt: number): number { + const backoff = OMP_PROVIDER_IDLE_MIN_RETRY_MS * 2 ** (attempt - 1); + return Math.min(OMP_PROVIDER_IDLE_MAX_RETRY_MS, backoff); +} + +// Precedence matches accrueProviderIdleSilence, which decides which bucket the +// silence went into. If the two disagree, silence is compared against another +// class's budget. +function ompProviderIdleBudgetMs(waitingOnSubagents: boolean, compacting: boolean): number { + if (compacting) { + return OMP_PROVIDER_COMPACTING_BUDGET_MS; + } + return waitingOnSubagents ? OMP_PROVIDER_SUBAGENT_BUDGET_MS : OMP_PROVIDER_IDLE_BUDGET_MS; +} + +export function createOmpProviderIdleScheduler(): OmpProviderIdleScheduler { return { - waitForRetry: async () => { - await new Promise((resolve) => setTimeout(resolve, 10)); + waitForRetry: async ({ + attempt, + consecutiveFailures, + elapsedMs, + totalElapsedMs, + isCompacting, + isWaitingOnSubagents, + }) => { + if (consecutiveFailures >= OMP_PROVIDER_IDLE_FAILURE_BUDGET) { + return { retry: false, reason: "failure_budget" }; + } + if (totalElapsedMs >= OMP_PROVIDER_IDLE_CEILING_MS) { + return { retry: false, reason: "wait_budget" }; + } + const budgetMs = ompProviderIdleBudgetMs(isWaitingOnSubagents, isCompacting); + if (elapsedMs >= budgetMs) { + return { retry: false, reason: "wait_budget" }; + } + await delay(ompProviderIdleRetryDelayMs(attempt)); + return { retry: true }; }, }; } @@ -526,6 +631,73 @@ function latestOmpErrorMessage(messages: OmpAgentMessage[]): string | null { return formatOmpErrorMessage(latestAssistant); } +function ompStalledTurnMessage(stateUnavailable: boolean, subagentsBlocked: boolean): string { + if (stateUnavailable) { + return "OMP finished its response but its state is unavailable, so Paseo cannot confirm the turn ended."; + } + if (subagentsBlocked) { + return "OMP finished its response but never finished its running subagents, so Paseo stopped waiting for the turn to end."; + } + return "OMP finished its response but never reported an idle state, so Paseo stopped waiting for the turn to end."; +} + +function ompStalledTurnCode(stateUnavailable: boolean, subagentsBlocked: boolean): string { + if (stateUnavailable) { + return "omp_provider_state_unavailable"; + } + return subagentsBlocked ? "omp_provider_subagent_stall" : "omp_provider_idle_timeout"; +} + +const OMP_NON_PROGRESS_EVENT_TYPES = new Set([ + "notice", + "available_commands_update", + "goal_updated", + "todo_reminder", +]); + +function isOmpTurnProgressEvent(event: OmpRuntimeEvent): boolean { + return !OMP_NON_PROGRESS_EVENT_TYPES.has(event.type); +} + +/** + * Progress is a reply that differs from the last one. + * + * Measured against OMP 17.4.0: `lastUpdate` moves per child activity, not per + * reply, so it is a real progress signal rather than a clock. It does not move + * while a child is busy but quiet - a child running `sleep 40` past its parent's + * agent_end held one value for 39.6 s across 80 polls, with no inbound frame + * either, because the parent's `task` tool call (whose tool_execution_update + * timer fires every 500 ms) has already ended by then. Keying on the running-id + * set instead would be strictly worse: it is frozen for the child's whole life. + * + * The consequence is deliberate and bounded: a child silent for longer than + * OMP_PROVIDER_SUBAGENT_BUDGET_MS fails its parent turn, because a snapshot that + * never changes is indistinguishable from a wedged one. + */ +function ompSubagentFingerprint(snapshots: OmpSubagentSnapshot[]): string { + return snapshots + .filter( + (snapshot) => + snapshot.status !== "completed" && + snapshot.status !== "failed" && + snapshot.status !== "aborted", + ) + .map((snapshot) => `${snapshot.id}:${snapshot.status}:${snapshot.lastUpdate ?? ""}`) + .sort() + .join("|"); +} + +/** Newest agent_end wins, unless it would discard an error the gate already holds. */ +function preferErroredOmpPayload( + current: OmpAgentMessage[], + incoming: OmpAgentMessage[], +): OmpAgentMessage[] { + if (latestOmpErrorMessage(incoming)) { + return incoming; + } + return latestOmpErrorMessage(current) ? current : incoming; +} + function isRecord(value: unknown): value is Record { return typeof value === "object" && value !== null && !Array.isArray(value); } @@ -843,6 +1015,9 @@ export class OmpAgentSession implements AgentSession { private readonly subscribers = new Set<(event: AgentStreamEvent) => void>(); private readonly activeToolCalls = new Map(); + /** Tool calls outlive their turn when OMP drops tool_execution_end; the gate + * must not treat that leak as work outstanding on a later turn. */ + private readonly activeToolCallTurns = new Map(); private readonly deferredTaskResults = new Map< string, { toolCall: OmpTrackedToolCall; result: OmpToolResult } @@ -855,6 +1030,8 @@ export class OmpAgentSession implements AgentSession { private activeAssistantMessageId: string | null = null; private activeTurnTerminalAssistantMessage: OmpAgentMessage | null = null; private activeTurnStarted = false; + private providerIdleGate: { key: string; messages: OmpAgentMessage[] } | null = null; + private lastSessionEventAt = 0; private activeTurnHasUserMessage = false; private activeNoTurnPromptText: string | null = null; private readonly pendingNoTurnOutputs: Array<{ turnId: string; message: string }> = []; @@ -873,6 +1050,7 @@ export class OmpAgentSession implements AgentSession { private state: OmpSessionState; private readonly currentModeId: string | null; private readonly providerIdleScheduler: OmpProviderIdleScheduler; + private readonly now: () => number; private readonly noTurnScheduler: OmpNoTurnScheduler; private readonly usagePoller: OmpUsagePoller; private closed = false; @@ -888,6 +1066,7 @@ export class OmpAgentSession implements AgentSession { this.paseoTools = options.paseoTools; this.live = options.live ?? true; this.providerIdleScheduler = options.providerIdleScheduler ?? createOmpProviderIdleScheduler(); + this.now = options.now ?? (() => performance.now()); this.noTurnScheduler = options.noTurnScheduler ?? createOmpNoTurnScheduler(); this.usagePoller = new OmpUsagePoller({ scheduler: options.usagePollScheduler, @@ -1154,6 +1333,7 @@ export class OmpAgentSession implements AgentSession { await this.runtimeSession.branch(target); await this.refreshState(); this.activeToolCalls.clear(); + this.activeToolCallTurns.clear(); } async close(): Promise { @@ -1161,6 +1341,7 @@ export class OmpAgentSession implements AgentSession { return; } this.closed = true; + this.providerIdleGate = null; this.usagePoller.close(); this.cancelNoTurnPromptCompletion(); try { @@ -1186,6 +1367,7 @@ export class OmpAgentSession implements AgentSession { this.emitToolCallEvent(toolCallId, toolCall, "canceled", null, null); } this.activeToolCalls.clear(); + this.activeToolCallTurns.clear(); for (const event of this.subagentIndex.terminalizeRunning(this.runtimeSession)) { this.emit(event); } @@ -1731,6 +1913,14 @@ export class OmpAgentSession implements AgentSession { } private handleRuntimeEvent(event: OmpRuntimeEvent): void { + // Only frames that mean the turn advanced count as progress. Host chatter — + // notices, command lists, goal timers, todo reminders — arrives on its own + // cadence and would otherwise refill the budget forever. Stamped here rather + // than in handleSessionEvent because subagent narration, auto-compaction and + // host-tool traffic never reach that far. + if (isOmpTurnProgressEvent(event)) { + this.lastSessionEventAt = this.now(); + } if (isExtensionUiRequestEvent(event)) { this.handleExtensionUiRequest(event); return; @@ -1840,6 +2030,7 @@ export class OmpAgentSession implements AgentSession { case "tool_execution_start": { const toolCall = parseToolArgs(event.toolName, event.args); this.activeToolCalls.set(event.toolCallId, toolCall); + this.activeToolCallTurns.set(event.toolCallId, turnId); this.activeAskUserDialog = readActiveAskUserDialog(event.toolName, event.args); this.emitToolCallEvent(event.toolCallId, toolCall, "running", null, null); return; @@ -1894,7 +2085,11 @@ export class OmpAgentSession implements AgentSession { } // A state request is processed after OMP's RPC loop becomes promptable, // so do not advertise Paseo idle until it reports that transition. - void this.completeTurnAfterProviderIdle(turnId, terminalMessages); + void this.completeTurnAfterProviderIdle(turnId, terminalMessages).catch( + (error: unknown) => { + this.logger.warn({ err: error }, "OMP provider idle gate failed"); + }, + ); return; } default: @@ -1919,6 +2114,7 @@ export class OmpAgentSession implements AgentSession { // the call active until the index has a linked child and none are running. if (event.toolName === "task" && !event.isError) { this.activeToolCalls.set(event.toolCallId, toolCall); + this.activeToolCallTurns.set(event.toolCallId, turnId); this.deferredTaskResults.set(event.toolCallId, { toolCall, result }); this.emitToolCallEvent(event.toolCallId, toolCall, "running", result, null); this.settleDeferredTaskCalls(); @@ -1926,6 +2122,7 @@ export class OmpAgentSession implements AgentSession { } this.activeToolCalls.delete(event.toolCallId); + this.activeToolCallTurns.delete(event.toolCallId); const error = event.isError ? event.result : null; const status = event.isError ? "failed" : "completed"; this.emitToolCallEvent(event.toolCallId, toolCall, status, result, error); @@ -1968,6 +2165,7 @@ export class OmpAgentSession implements AgentSession { } this.deferredTaskResults.delete(toolCallId); this.activeToolCalls.delete(toolCallId); + this.activeToolCallTurns.delete(toolCallId); this.emitToolCallEvent(toolCallId, pending.toolCall, "completed", pending.result, null); this.subagentCardTracker.delete(toolCallId); } @@ -2169,8 +2367,7 @@ export class OmpAgentSession implements AgentSession { }); } - private completeTurn(turnId: string | undefined, messages: OmpAgentMessage[]): void { - this.forceSettleDeferredTaskCalls(); + private resetActiveTurn(): void { this.activeTurnId = null; this.activeClientMessageId = null; this.activeAssistantMessageId = null; @@ -2178,6 +2375,11 @@ export class OmpAgentSession implements AgentSession { this.activeTurnStarted = false; this.activeTurnHasUserMessage = false; this.clearNoTurnBuffers(); + } + + private completeTurn(turnId: string | undefined, messages: OmpAgentMessage[]): void { + this.forceSettleDeferredTaskCalls(); + this.resetActiveTurn(); const errorMessage = latestOmpErrorMessage(messages); if (typeof errorMessage === "string" && errorMessage.length > 0) { this.usagePoller.stopTurn(); @@ -2198,38 +2400,259 @@ export class OmpAgentSession implements AgentSession { void this.refreshAfterTurn(finalUsage); } + /** Ownership can change across an await; completing a turn this gate no longer + * represents would clear the turn that replaced it. */ + private completeTurnIfGateOwned(turnId: string | undefined, messages: OmpAgentMessage[]): void { + if (!this.ownsProviderIdleGate(turnId)) { + return; + } + this.completeTurn(turnId, messages); + } + + /** + * The budget spends silence, not elapsed time. An inbound frame or a subagent + * reply that changed since the last one is progress and clears it. A flag + * staying on is not: that is the stall being bounded. Each class keeps its own + * total so time under a long budget is not inherited by a shorter one. + */ + private accrueProviderIdleSilence( + silence: OmpProviderIdleSilence, + fingerprint: string | null, + observed: { compacting: boolean; waitingOnWork: boolean }, + ): number { + const now = this.now(); + const progressed = + this.lastSessionEventAt !== silence.lastEventAt || fingerprint !== silence.fingerprint; + silence.lastEventAt = this.lastSessionEventAt; + silence.fingerprint = fingerprint; + const delta = now - silence.lastPollAt; + silence.lastPollAt = now; + if (progressed) { + silence.compacting = 0; + silence.work = 0; + silence.other = 0; + } else if (observed.compacting) { + silence.compacting += delta; + } else if (observed.waitingOnWork) { + silence.work += delta; + } else { + silence.other += delta; + } + if (observed.compacting) { + return silence.compacting; + } + return observed.waitingOnWork ? silence.work : silence.other; + } + + private hasActiveToolCallsFor(turnId: string | undefined): boolean { + for (const [toolCallId, toolCallTurnId] of this.activeToolCallTurns) { + if (toolCallTurnId === turnId && this.activeToolCalls.has(toolCallId)) { + return true; + } + } + return false; + } + + private ownsProviderIdleGate(turnId: string | undefined): boolean { + return !this.closed && this.activeTurnStarted && this.currentTurnIdForEvent() === turnId; + } + private async completeTurnAfterProviderIdle( turnId: string | undefined, messages: OmpAgentMessage[], ): Promise { - while (!this.closed && this.activeTurnStarted && this.currentTurnIdForEvent() === turnId) { - try { - const state = await this.runtimeSession.getState(); - this.state = state; - // Parent model idle is not enough: OMP-internal `task` children keep - // writing after agent_end / isStreaming=false (#2232). - if (!state.isStreaming && !state.isCompacting && !(await this.hasRunningOmpSubagents())) { - this.completeTurn(turnId, messages); + // OMP can end more than one cycle for a single prompt. Without this gate a + // second loop races the first and completes the same turn twice. Autonomous + // cycles carry no turn ID, so they share one key: their loop polls too. + const key = turnId ?? OMP_AUTONOMOUS_GATE_KEY; + if (this.providerIdleGate?.key === key) { + // The newest agent_end owns the terminal payload so a later provider error + // is not dropped, except when it would drop one the gate already holds. + this.providerIdleGate.messages = preferErroredOmpPayload( + this.providerIdleGate.messages, + messages, + ); + return; + } + const gate = { key, messages }; + this.providerIdleGate = gate; + try { + // Silence is counted per budget class. One shared clock would make time + // spent under the ten-minute compaction budget instantly delinquent the + // moment the sixty-second stall budget takes over. + const gateStartedAt = this.now(); + const silence: OmpProviderIdleSilence = { + compacting: 0, + work: 0, + other: 0, + lastPollAt: this.now(), + lastEventAt: this.lastSessionEventAt, + fingerprint: null, + }; + let subagentFingerprint: string | null = null; + let attempt = 0; + let consecutiveFailures = 0; + let lastState: OmpSessionState | null = null; + let lastError: unknown = null; + let subagentsConfirmed = false; + while (this.ownsProviderIdleGate(turnId)) { + attempt += 1; + try { + const state = await this.runtimeSession.getState(); + this.state = state; + lastState = state; + consecutiveFailures = 0; + // Parent model idle is not enough: OMP-internal `task` children keep + // writing after agent_end / isStreaming=false (#2232). + const modelBusy = state.isStreaming || state.isCompacting; + const subagents = modelBusy ? null : await this.pollOmpSubagents(); + subagentsConfirmed = (subagents?.fingerprint ?? "") !== ""; + if (subagents) { + subagentFingerprint = subagents.fingerprint ?? subagentFingerprint; + } + if (subagents && !subagents.running) { + this.completeTurnIfGateOwned(turnId, gate.messages); + return; + } + } catch (error) { + lastError = error; + consecutiveFailures += 1; + subagentsConfirmed = false; + this.logger.debug( + { err: error }, + "OMP state unavailable while waiting for provider idle", + ); + } + // The budget spends silence, not elapsed time. An inbound frame or a + // subagent reply that changed since the last one is progress and clears + // it. A flag staying on is not: that is the stall being bounded. The + // flags only choose how long silence may last. + const compacting = lastState?.isCompacting === true; + // A started tool call or an outstanding child is work Paseo can see, and + // it earns the longer budget even when OMP says nothing about it. + const waitingOnWork = + this.subagentIndex.hasRunning(this.runtimeSession) || this.hasActiveToolCallsFor(turnId); + const elapsedMs = this.accrueProviderIdleSilence(silence, subagentFingerprint, { + compacting, + waitingOnWork, + }); + const decision = await this.providerIdleScheduler.waitForRetry({ + attempt, + consecutiveFailures, + elapsedMs, + totalElapsedMs: this.now() - gateStartedAt, + isCompacting: compacting, + isWaitingOnSubagents: waitingOnWork, + }); + if (!decision.retry) { + if (!this.ownsProviderIdleGate(turnId)) { + return; + } + this.failStalledTurn(turnId, { + reason: decision.reason, + attempt, + consecutiveFailures, + lastState, + lastError, + subagentsConfirmed, + }); return; } - } catch (error) { - this.logger.debug({ err: error }, "OMP state unavailable while waiting for provider idle"); } - await this.providerIdleScheduler.waitForRetry(); + } finally { + if (this.providerIdleGate === gate) { + this.providerIdleGate = null; + } } } - private async hasRunningOmpSubagents(): Promise { + /** + * The fingerprint is what the budget compares: a reply that changed since the + * last one is progress. The index alone never is. + */ + private async pollOmpSubagents(): Promise<{ running: boolean; fingerprint: string | null }> { + let snapshots: OmpSubagentSnapshot[] | null = null; try { - const snapshots = await this.runtimeSession.getSubagents(); + snapshots = await this.runtimeSession.getSubagents(); + } catch (error) { + this.logger.debug({ err: error }, "OMP get_subagents unavailable during idle gate"); + } + if (snapshots) { for (const event of this.subagentIndex.reconcileSnapshots(this.runtimeSession, snapshots)) { this.emit(event); } - } catch (error) { - this.logger.debug({ err: error }, "OMP get_subagents unavailable during idle gate"); } this.settleDeferredTaskCalls(); - return this.subagentIndex.hasRunning(this.runtimeSession); + return { + // `running` is what the gate waits on (#2232) and how long the budget may + // run. The fingerprint is what counts as progress: a child merely being + // listed again is the same stuck flag the state field would be, so only a + // reply that changed since the last one restarts the budget. + running: this.subagentIndex.hasRunning(this.runtimeSession), + fingerprint: snapshots ? ompSubagentFingerprint(snapshots) : null, + }; + } + + private failStalledTurn( + turnId: string | undefined, + context: { + reason: "wait_budget" | "failure_budget"; + attempt: number; + consecutiveFailures: number; + lastState: OmpSessionState | null; + lastError: unknown; + subagentsConfirmed: boolean; + }, + ): void { + // A hanging state path burns the wait budget before the failure budget, so a + // gate that never saw a state is an unavailable state path whichever ran out. + // Read the index now rather than trusting a flag carried across polls where + // subagents were never queried. + const subagentsBlocked = this.subagentIndex.hasRunning(this.runtimeSession); + const stateUnavailable = + context.reason === "failure_budget" || (!context.lastState && context.lastError !== null); + // Both observations go into every diagnostic: which budget ran out says what + // Paseo did, the last state and the last error say what OMP was doing. + const details = [`state checks: ${context.attempt}`]; + if (context.lastState) { + details.push( + `last OMP state: isStreaming=${context.lastState.isStreaming}, isCompacting=${context.lastState.isCompacting}`, + ); + } + if (context.lastError) { + const failureCount = + context.consecutiveFailures > 0 + ? ` after ${context.consecutiveFailures} consecutive failures` + : ""; + details.push( + `last get_state error${failureCount}: ${toDiagnosticErrorMessage(context.lastError)}`, + ); + } + if (subagentsBlocked) { + details.push( + context.subagentsConfirmed + ? "OMP still listed running subagents" + : "OMP still held running subagents it would not confirm", + ); + } + const diagnostic = details.join("; "); + this.logger.warn( + { turnId, reason: context.reason, diagnostic }, + "OMP never reported an idle state after ending its response", + ); + // A stall leaves OMP's state unknown, so anything still marked running has no + // turn left to finish it. + this.terminalizeActiveWork(); + this.resetActiveTurn(); + this.usagePoller.stopTurn(); + this.emit({ + type: "turn_failed", + provider: this.provider, + turnId, + error: ompStalledTurnMessage(stateUnavailable, subagentsBlocked), + code: ompStalledTurnCode(stateUnavailable, subagentsBlocked), + diagnostic, + }); } private async refreshState(): Promise { @@ -2251,6 +2674,7 @@ export class OmpAgentClient implements AgentClient { private readonly modelRoleParams: OmpModelRoleParams; private readonly subagentCardScheduler?: OmpSubagentCardScheduler; private readonly providerIdleScheduler?: OmpProviderIdleScheduler; + private readonly now?: () => number; private readonly noTurnScheduler?: OmpNoTurnScheduler; private readonly usagePollScheduler?: OmpUsagePollScheduler; private readonly runtime: OmpRuntime; @@ -2274,6 +2698,7 @@ export class OmpAgentClient implements AgentClient { this.modelRoleParams = modelRoleParams; this.subagentCardScheduler = options.subagentCardScheduler; this.providerIdleScheduler = options.providerIdleScheduler; + this.now = options.now; this.noTurnScheduler = options.noTurnScheduler; this.usagePollScheduler = options.usagePollScheduler; this.runtime = options.runtime ?? createRuntime(options.logger, runtimeSettings); @@ -2315,6 +2740,7 @@ export class OmpAgentClient implements AgentClient { logger: this.logger, subagentCardScheduler: this.subagentCardScheduler, providerIdleScheduler: this.providerIdleScheduler, + now: this.now, noTurnScheduler: this.noTurnScheduler, usagePollScheduler: this.usagePollScheduler, paseoTools: launchContext?.paseoTools, @@ -2357,6 +2783,7 @@ export class OmpAgentClient implements AgentClient { logger: this.logger, subagentCardScheduler: this.subagentCardScheduler, providerIdleScheduler: this.providerIdleScheduler, + now: this.now, noTurnScheduler: this.noTurnScheduler, usagePollScheduler: this.usagePollScheduler, paseoTools: launchContext?.paseoTools, diff --git a/packages/server/src/server/agent/providers/omp/omp-agent.real.e2e.test.ts b/packages/server/src/server/agent/providers/omp/omp-agent.real.e2e.test.ts new file mode 100644 index 00000000000..de4b95a10fb --- /dev/null +++ b/packages/server/src/server/agent/providers/omp/omp-agent.real.e2e.test.ts @@ -0,0 +1,112 @@ +import { mkdtempSync, rmSync } from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { beforeAll, describe, expect, test } from "vitest"; + +import type { AgentSession, AgentStreamEvent } from "../../agent-sdk-types.js"; +import { createTestLogger } from "../../../../test-utils/test-logger.js"; +import { + canRunRealProvider, + createRealProviderClient, + getRealProviderConfig, +} from "../../../daemon-e2e/real-provider-test-config.js"; + +// The post-agent_end completion gate (getpaseo/paseo#3654) is exercised only by +// fakes elsewhere in this directory. These tests run it against a real OMP so a +// bounded gate is proven not to have cost ordinary completion. +const TIMEOUT_MS = 300_000; + +async function runAllowingProviderError( + session: AgentSession, + prompt: string, +): Promise<{ finalText: string } | null> { + try { + return await session.run(prompt); + } catch { + return null; + } +} + +describe("OMP provider idle gate (real)", () => { + let canRun = false; + + beforeAll(async () => { + canRun = await canRunRealProvider("omp"); + }); + + async function withSession( + prefix: string, + body: (session: AgentSession, events: AgentStreamEvent[]) => Promise, + ): Promise { + const client = createRealProviderClient("omp", createTestLogger()); + const cwd = mkdtempSync(path.join(os.tmpdir(), prefix)); + try { + const session = await client.createSession({ ...getRealProviderConfig("omp"), cwd }); + const events: AgentStreamEvent[] = []; + const unsubscribe = session.subscribe((event) => events.push(event)); + try { + await body(session, events); + } finally { + unsubscribe(); + await session.close(); + } + } finally { + rmSync(cwd, { recursive: true, force: true }); + } + } + + function terminalTurnTypes(events: readonly AgentStreamEvent[]): string[] { + const terminal = events.filter( + (event) => + event.type === "turn_completed" || + event.type === "turn_failed" || + event.type === "turn_canceled", + ); + return terminal.map((event) => event.type); + } + + test( + "an ordinary turn ends in exactly one turn_completed", + async (context) => { + if (!canRun) { + context.skip(); + } + await withSession("paseo-omp-idle-gate-", async (session, events) => { + const result = await session.run("Reply with exactly OMP_GATE_OK and nothing else."); + + expect(result.finalText).toContain("OMP_GATE_OK"); + expect(terminalTurnTypes(events)).toEqual(["turn_completed"]); + }); + }, + TIMEOUT_MS, + ); + + test( + "a turn that fans out ends in exactly one terminal turn event", + async (context) => { + if (!canRun) { + context.skip(); + } + await withSession("paseo-omp-idle-gate-subagent-", async (session, events) => { + // Whether the model drives `task` correctly is its business - the test + // model is small enough to get the call wrong. What the gate owes is one + // terminal event either way: it must neither complete a turn twice nor + // leave a finished one open. + const outcome = await runAllowingProviderError( + session, + [ + "Use task to create exactly one child named GateChild.", + "It must run exactly this bash command: printf 'GATE_CHILD_OK\\n'.", + "Wait for that child to finish, then reply with exactly OMP_GATE_PARENT_OK.", + ].join(" "), + ); + + expect(terminalTurnTypes(events)).toHaveLength(1); + if (outcome?.finalText.includes("OMP_GATE_PARENT_OK")) { + expect(terminalTurnTypes(events)).toEqual(["turn_completed"]); + } + }); + }, + TIMEOUT_MS, + ); +}); diff --git a/packages/server/src/server/agent/providers/omp/test-utils/fake-omp.ts b/packages/server/src/server/agent/providers/omp/test-utils/fake-omp.ts index 21f94e5ba84..cf2b69b76f4 100644 --- a/packages/server/src/server/agent/providers/omp/test-utils/fake-omp.ts +++ b/packages/server/src/server/agent/providers/omp/test-utils/fake-omp.ts @@ -252,6 +252,9 @@ export class FakeOmpSession implements OmpRuntimeSession { if (this.getStateRequestCount >= waiter.count) waiter.resolve(); else this.stateRequestWaiters.push(waiter); } + if (this.holdStateChecks) { + await new Promise((resolve) => this.heldStateChecks.push(resolve)); + } if (this.getStateError) { throw this.getStateError; } @@ -266,6 +269,13 @@ export class FakeOmpSession implements OmpRuntimeSession { this.stateReports.push(...states); } + holdStateChecks = false; + private readonly heldStateChecks: Array<() => void> = []; + + releaseStateChecks(): void { + for (const resolve of this.heldStateChecks.splice(0)) resolve(); + } + waitForStateRequests(count: number): Promise { if (this.getStateRequestCount >= count) return Promise.resolve(); return new Promise((resolve) => this.stateRequestWaiters.push({ count, resolve })); diff --git a/packages/server/src/server/agent/providers/omp/test-utils/omp-harness.ts b/packages/server/src/server/agent/providers/omp/test-utils/omp-harness.ts index 30d75bb8f4b..06c1c8886b1 100644 --- a/packages/server/src/server/agent/providers/omp/test-utils/omp-harness.ts +++ b/packages/server/src/server/agent/providers/omp/test-utils/omp-harness.ts @@ -20,7 +20,7 @@ import { } from "../agent.js"; import type { OmpUsagePollScheduler } from "../usage-poller.js"; import type { OmpAgentMessage, OmpRpcSlashCommand } from "../rpc-types.js"; -import { FakeOmp } from "./fake-omp.js"; +import { FakeOmp, type FakeOmpSubagentSnapshot } from "./fake-omp.js"; const CWD = "/tmp/paseo-omp-agent-test"; @@ -69,6 +69,7 @@ export class OmpHarness { constructor( options: { providerIdleScheduler?: OmpProviderIdleScheduler; + now?: () => number; noTurnScheduler?: OmpNoTurnScheduler; usagePollScheduler?: OmpUsagePollScheduler; } = {}, @@ -77,6 +78,7 @@ export class OmpHarness { logger: pino({ level: "silent" }), runtime: this.omp, providerIdleScheduler: options.providerIdleScheduler, + now: options.now, noTurnScheduler: options.noTurnScheduler, usagePollScheduler: options.usagePollScheduler, }); @@ -247,10 +249,29 @@ export class OmpHarness { return { completion: run }; } + startAutonomousTurnUntilProviderIdle( + output: string, + providerState: { isStreaming: boolean; isCompacting: boolean }, + ): void { + const runtime = this.omp.latestSession(); + runtime.beginTurn(); + runtime.streamAssistantText(output); + runtime.state = { ...runtime.state, ...providerState }; + runtime.finishTurn(); + } + waitForProviderStateChecks(count: number): Promise { return this.omp.latestSession().waitForStateRequests(count); } + reportSubagentSnapshots(snapshots: FakeOmpSubagentSnapshot[]): void { + this.omp.latestSession().subagents = snapshots; + } + + failSubagentSnapshots(error: Error | null): void { + this.omp.latestSession().getSubagentsError = error; + } + reportProviderState(state: { isStreaming: boolean; isCompacting: boolean }): void { const runtime = this.omp.latestSession(); runtime.state = { ...runtime.state, ...state }; @@ -406,6 +427,10 @@ export class OmpHarness { return items; } + failedTurns(): Array> { + return this.events.flatMap((event) => (event.type === "turn_failed" ? [event] : [])); + } + completedTurnCount(): number { return this.events.filter((event) => event.type === "turn_completed").length; }