diff --git a/packages/core/test/engine.test.ts b/packages/core/test/engine.test.ts index be75069..31b5042 100644 --- a/packages/core/test/engine.test.ts +++ b/packages/core/test/engine.test.ts @@ -10,7 +10,7 @@ import { mkdtemp, readFile, rm } from "node:fs/promises"; import { tmpdir } from "node:os"; import { join } from "node:path"; -import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { assistantText, emptyTokenCounts, @@ -179,6 +179,68 @@ describe("ContextEngine ReAct loop (mock LLM, approve callback)", () => { expect(recordedTypes.some((t) => t?.startsWith("partial_"))).toBe(false); }); + it("a slow tool delays the run only by its own latency: the loop adds no waits, timers, or dropped wakes", async () => { + // Regression pin for the ci-windows timeout of the test above (goal-mode PR #66's + // merge-ref run): on one cold Windows runner the suite-start burst of first Git-Bash + // spawns ran ~28-36s and the test crossed the then-30s platform deadline, which looked + // like a goal-mode hang in the run loop. The loop's actual contract, pinned here with + // virtual tool latency instead of a real spawn (platform-neutral, deterministic): tool + // latency flows through 1:1 — wall time ≈ latency + ε. An engine-side wait inserted + // between turns would blow the upper bound, a dropped continuation wake would hang this + // test into its own deadline, and a timer armed alongside the tool would trip the spies + // (the engine's only setTimeout is the reconnect backoff, a failure-path affair). + const TOOL_LATENCY_MS = 300; + const EPSILON_MS = 1_000; + const realSetTimeout = globalThis.setTimeout.bind(globalThis); + const timeoutSpy = vi.spyOn(globalThis, "setTimeout"); + const intervalSpy = vi.spyOn(globalThis, "setInterval"); + try { + const llm = new FakeLLM(); + const environment: EnvironmentInterface = { + async listTools() { + return []; + }, + async *executeTool({ toolCall: tc }) { + // The injected "slow spawn" (through the pre-spy setTimeout, invisible to the spies). + await new Promise((resolve) => realSetTimeout(resolve, TOOL_LATENCY_MS)); + yield toolCallOutput({ output: "wrote hello.txt", toolCallId: tc.payload.tool_call_id }); + }, + toolPermission() { + return "rw"; + }, + }; + const engine = new ContextEngine({ llm, environment }); + + const start = performance.now(); + const collected = await collectRun( + engine, + [userText("Create hello.txt saying Hello, Penguin")], + allowAll, + ); + const elapsed = performance.now() - start; + const timersArmed = timeoutSpy.mock.calls.length + intervalSpy.mock.calls.length; + + // The flow completed both turns, with the slow tool's output fed back and paired. + expect(llm.calls).toBe(2); + expect( + llm.receivedSecondInput!.some( + (m) => (m.payload as { type?: string }).type === "tool_call_output", + ), + ).toBe(true); + expect(collected.map((m) => (m.payload as { type?: string }).type)).toContain( + "tool_call_output", + ); + // Latency-additive: the tool's own wait, plus scheduling slack — nothing multiplied. + expect(elapsed).toBeGreaterThanOrEqual(TOOL_LATENCY_MS - 5); + expect(elapsed).toBeLessThan(TOOL_LATENCY_MS + EPSILON_MS); + // And no engine-armed wall-clock wait rode along. + expect(timersArmed).toBe(0); + } finally { + timeoutSpy.mockRestore(); + intervalSpy.mockRestore(); + } + }); + it("streams origin-tagged nested messages to the consumer but keeps them out of trace and the next-turn input", async () => { const NAME = "__nested_forward_tool__"; BUILTIN_TOOL_FACTORIES[NAME] = (definition) => ({ diff --git a/packages/core/vitest.config.ts b/packages/core/vitest.config.ts index 3638d30..93af275 100644 --- a/packages/core/vitest.config.ts +++ b/packages/core/vitest.config.ts @@ -3,14 +3,30 @@ * many core tests spawn a real shell (Git-Bash on the Windows CI runners) or write the * full Agent State layout, and Windows runner I/O variance (cold shell spawns, Defender * first-touch scans, slow-disk moments) has pushed individually fast tests past vitest's - * 5s default — a different test on each run. A larger failure deadline changes nothing - * for passing tests; POSIX keeps the 5s default to fail fast during local development. + * 5s default — a different test on each run. + * + * The deadline's first sizing (30s) turned out to be inside that variance tail: on one + * cold runner (PR #66's merge-ref run) the suite-start burst of first spawns across + * parallel workers put environment.test.ts's single-spawn write at 28.1s PASSING and + * engine.test.ts's first test at 35.7s FAILING, while runs of the same code minutes + * before and after finished the failing test in ~1.4s. The slowdown tracked OS work + * only — pure-JS test files stayed at normal speed in the same run — so the flow + * terminates and merely waits on the OS. Amplification confirms it: injecting spawn + * latency into the same test (a PENGUIN_SHELL shim sleeping before bash) reproduces the + * failure exactly at 30s injected vs the old 30s deadline, with the flow completing + * ~70ms after the spawn at every magnitude tried — tool latency flows through 1:1, the + * loop adds no waits of its own (pinned platform-neutrally by the "slow tool delays the + * run only by its own latency" test in test/engine.test.ts). 120s clears the observed + * tail with headroom while still bounding a genuinely hung test. + * + * A larger failure deadline changes nothing for passing tests; POSIX keeps the 5s + * default to fail fast during local development. */ import { defineConfig } from "vitest/config"; export default defineConfig({ test: { environment: "node", - testTimeout: process.platform === "win32" ? 30_000 : 5_000, + testTimeout: process.platform === "win32" ? 120_000 : 5_000, }, });