diff --git a/src/cli/runCleanup.ts b/src/cli/runCleanup.ts index 77646900ae3..96c1957c5ee 100644 --- a/src/cli/runCleanup.ts +++ b/src/cli/runCleanup.ts @@ -1,13 +1,16 @@ /** - * Best-effort teardown runner for `xum run`. + * Best-effort teardown runner for the CLI roots (`xum run`, `xum workflow`). * * Teardown executes after the run outcome (including the run-complete JSON * event) has already been produced. A disposer that throws or rejects there * must not flip a finished run into a failing exit code: benchmark harnesses * treat a nonzero exit as an infrastructure error and discard the whole * trial. Contain each step, report the failure, and keep running the - * remaining steps. + * remaining steps. Each step also reports its duration as a `[shutdown]` + * debug line (shutdownStep), matching `ServiceContainer.dispose()`. */ +import { shutdownStep } from "@/node/services/shutdownStep"; + export interface RunCleanupStep { name: string; run: () => void | Promise; @@ -19,7 +22,9 @@ export async function runBestEffortCleanup( ): Promise { for (const step of steps) { try { - await step.run(); + await shutdownStep(step.name, async () => { + await step.run(); + }); } catch (error) { try { reportError(step.name, error); diff --git a/src/cli/server.ts b/src/cli/server.ts index 9205decaee1..98e42dfc1db 100644 --- a/src/cli/server.ts +++ b/src/cli/server.ts @@ -11,6 +11,7 @@ import { resolveXumEnvironmentValue } from "@/common/compat/legacyMux"; import { initializeXumHomeTransition } from "@/node/compat/xumTransition"; import { ServerLockfile } from "@/node/services/serverLockfile"; import { log } from "@/node/services/log"; +import { shutdownStep } from "@/node/services/shutdownStep"; import type { BrowserWindow } from "electron"; import { Command } from "commander"; import { validateProjectPath } from "@/node/utils/pathUtils"; @@ -229,6 +230,7 @@ async function main(): Promise { cleanupInProgress = true; console.log("Shutting down server..."); + const shutdownStartedAt = performance.now(); // Force exit after timeout if cleanup hangs const forceExitTimer = setTimeout(() => { @@ -242,15 +244,25 @@ async function main(): Promise { try { // Close all PTY sessions first - serviceContainer.terminalService.closeAllSessions(); + shutdownStep("terminalService.closeAllSessions", () => + serviceContainer.terminalService.closeAllSessions() + ); - // Dispose background processes + // Dispose background processes (writes its own per-step [shutdown] lines) await serviceContainer.dispose(); // Stop server (releases lockfile, stops mDNS, closes HTTP server) - await serviceContainer.serverService.stopServer(); + await shutdownStep("serverService.stopServer", () => + serviceContainer.serverService.stopServer() + ); clearTimeout(forceExitTimer); + // Last JS-side line: anything the process still spends after this is + // outside the teardown lists (e.g. a worker thread mid-module-evaluation + // that process.exit has to wait out). + log.debug("[shutdown] exiting", { + totalMs: Math.round(performance.now() - shutdownStartedAt), + }); process.exit(0); } catch (err) { appendServerCrashLogSync({ diff --git a/src/cli/workflow.ts b/src/cli/workflow.ts index 3e2c13634a6..baccd8b04c6 100644 --- a/src/cli/workflow.ts +++ b/src/cli/workflow.ts @@ -43,6 +43,7 @@ import { WorkflowTaskServiceAdapter, } from "@/node/services/workflows/WorkflowTaskServiceAdapter"; import { hasAnyConfiguredProvider, buildProvidersFromEnv } from "@/node/utils/providerRequirements"; +import { runBestEffortCleanup } from "./runCleanup"; import { getParseOptions } from "./argv"; import { exitAfterStdoutFlush } from "./processExit"; import { resolveProjectDir, resolveProjectTrusted } from "./trust"; @@ -267,65 +268,45 @@ async function disposeWorkflowResources(input: { realProviderService?: ProviderService; policyService?: PolicyService; }): Promise { - // Suppress monitor:stopped before session.dispose() triggers cleanup() so persisted - // armed-monitor registry records survive shutdown (post-restart "monitor lost" wakes). - input.services?.backgroundProcessManager.beginShutdown(); - // Interrupt + await the runtime's supervised fibers while their dependencies - // are still alive (same slot as ServiceContainer.dispose); never rejects. - if (input.services) { - await closeScopeBounded(input.services.appFiberScope); - } - try { - input.session?.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose session", { error: getErrorMessage(error) }); - } - try { - input.services?.mcpServerManager.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose MCP server manager", { - error: getErrorMessage(error), - }); - } - try { - await input.codexOauthService?.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose Codex OAuth service", { - error: getErrorMessage(error), - }); - } - try { - await input.coderOauthService?.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose Coder OAuth service", { - error: getErrorMessage(error), - }); - } - try { - input.realProviderService?.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose real-config provider service", { - error: getErrorMessage(error), - }); - } - try { - input.policyService?.dispose(); - } catch (error) { - log.warn("xum workflow: failed to dispose policy service", { - error: getErrorMessage(error), - }); - } - try { - await input.services?.backgroundProcessManager.terminateAll(); - } catch (error) { - log.warn("xum workflow: failed to terminate background processes", { - error: getErrorMessage(error), - }); - } - // Last: release the Effect runtime that owns the core graph; never rejects. - if (input.services) { - await disposeAppRuntime(input.services.runtime.managed); - } + const services = input.services; + // Same shape as `xum run`'s list: every step is contained, reported, and + // timed as a `[shutdown]` line; a failing step never skips the ones after it. + await runBestEffortCleanup( + [ + ...(services + ? [ + // Suppress monitor:stopped before session.dispose() triggers cleanup() so persisted + // armed-monitor registry records survive shutdown (post-restart "monitor lost" wakes). + { + name: "backgroundProcessManager.beginShutdown", + run: () => services.backgroundProcessManager.beginShutdown(), + }, + // Interrupt + await the runtime's supervised fibers while their dependencies + // are still alive (same slot as ServiceContainer.dispose); never rejects. + { name: "appFiberScope.close", run: () => closeScopeBounded(services.appFiberScope) }, + ] + : []), + { name: "session.dispose", run: () => input.session?.dispose() }, + { name: "mcpServerManager.dispose", run: () => services?.mcpServerManager.dispose() }, + { name: "codexOauthService.dispose", run: () => input.codexOauthService?.dispose() }, + { name: "coderOauthService.dispose", run: () => input.coderOauthService?.dispose() }, + { name: "realProviderService.dispose", run: () => input.realProviderService?.dispose() }, + { name: "policyService.dispose", run: () => input.policyService?.dispose() }, + { + name: "backgroundProcessManager.terminateAll", + run: () => services?.backgroundProcessManager.terminateAll(), + }, + // Last: release the Effect runtime that owns the core graph; never rejects. + ...(services + ? [{ name: "appRuntime.dispose", run: () => disposeAppRuntime(services.runtime.managed) }] + : []), + ], + (stepName, error) => { + log.warn(`xum workflow: cleanup step failed: ${stepName}`, { + error: getErrorMessage(error), + }); + } + ); input.tempDir[Symbol.dispose](); } diff --git a/src/node/services/di/appRuntime.ts b/src/node/services/di/appRuntime.ts index bba3552b192..97266b2cd99 100644 --- a/src/node/services/di/appRuntime.ts +++ b/src/node/services/di/appRuntime.ts @@ -1,40 +1,140 @@ /** - * App-lifetime Effect runtime (Effect migration Phase 11). + * App-lifetime Effect runtime (Effect migration Phase 11) — and the durable + * **DI contract** for the Layer graph it builds. * - * A `ManagedRuntime` built from the process's Layer graph (`./layers/app.ts` - * for `ServiceContainer` roots). It owns the app-lifetime `Scope`, and its - * built `Context` is what oRPC Effect-native handlers receive as - * `"effect/context"`. + * A `ManagedRuntime` built from the process's Layer graph: `./layers/app.ts` + * (`AppLive`) for `ServiceContainer` roots (desktop, `xum server`, ACP, + * tests/ipc), `CoreLive` alone for the headless CLI roots (`xum run`, + * `xum workflow`, via `coreServicesRoot.ts`). It owns the app-lifetime + * `Scope`, its built `Context` is what oRPC Effect-native handlers + * receive as `"effect/context"`, and it is the source of the two runtime seams + * described below. Service classes were not rewritten for this: Layers are + * thin adapters around the existing constructors, and the former composition + * roots' setter/listener wiring lives in `CoreWiringLive`/`DesktopWiringLive` + * in the original statement order. * - * DI contract (Phase 11 compatibility rules, not permanent architecture law): + * ## Invariants (Phase 11 compatibility contract, not permanent law) * - * - **Synchronous layer bodies.** Every Layer in the graph must build without + * - **I1 — Synchronous layer bodies.** Every Layer in the graph builds without * suspending (`Layer.succeed`/`Layer.sync`/`Layer.effect` over sync effects; * `acquireRelease` with a sync acquire is fine). `makeAppRuntime` builds the * graph eagerly with `runSync` and asserts that it completed, so a layer that * suspends fails right here — at construction, exactly where a throwing - * service constructor fails today, and therefore inside every entry point's - * existing startup catch path (`desktop/main.ts` dialog, `cli/server.ts`/ACP - * log-and-exit). Asynchronous acquisition belongs in `initialize()` or a - * later explicit async factory root, never silently inside a layer. Eager - * building also keeps fibers started through the runtime synchronous up to - * their first async boundary (`cachedContext` is set, so `runX` is - * `Effect.run…With(context)`), which the deterministic-winner funnels in the - * codebase rely on. - * - **Only the composition root holds the runtime.** Services must not be - * handed the `ManagedRuntime`: after `dispose()` every `runX` on it dies with - * "ManagedRuntime disposed", and a late worker callback would defect. - * - **No layer finalizers yet.** Teardown order stays explicit in - * `ServiceContainer.dispose()`; layer bodies register no finalizers, so - * `disposeAppRuntime` (the last dispose step) reorders nothing. It is wired - * now so that later phases (the streamManager engine core) have a fixed, - * bounded slot for scope-owned resources. - * - **Two runtime seams, not one handle.** Workers hold an `EffectRunner` - * (`./effectRunner.ts`: context-bound, unsupervised, `R = never`) so they can - * run on the runtime's `Clock` without ever holding the runtime; work that - * shutdown must await forks into `AppFiberScope` (`./appFiberScope.ts`), - * the one supervised resource, closed explicitly early in `dispose()` via - * `closeScopeBounded` and re-closed idempotently by `disposeAppRuntime`. + * service constructor failed before, i.e. inside every entry point's + * existing startup catch path (`desktop/main.ts` "Startup Failed" dialog, + * `cli/server.ts`/ACP log-and-exit). Asynchronous acquisition belongs in + * `ServiceContainer.initialize()` / startup effects or a future explicit + * async factory root, never silently inside a layer. Eager building also + * sets `cachedContext`, so every `runtime.runX` is `Effect.run…With(context)` + * and a fiber started through it runs synchronously up to its first async + * boundary (the sync-start fact the codebase's deterministic-winner funnels + * rely on; pinned in `effectRunner.test.ts`). + * - **I2 — Services never hold the `ManagedRuntime`.** After `dispose()` every + * `runX` on it dies with "ManagedRuntime disposed", so a late worker callback + * would defect. Workers hold an `EffectRunner` (`./effectRunner.ts`, + * default `defaultEffectRunner` = the global `Effect.runX`) whose `runX` is + * `Effect.run…With(ctx)` — same sync-start semantics, still valid after the + * runtime is gone. Supervision, when needed, is explicit via + * `AppFiberScope` (`./appFiberScope.ts`). + * - **I3 — Per-call pipelines are untouched.** `Effect.runPromise(this.effects…)` + * facades and the `memoryConsolidationService` check-and-reserve funnels are + * not routed through DI; no lookup, runner call, or `await` may be inserted + * before `inFlight.set` / `harvestInFlight.set`. Only lifecycle forks in the + * clock-driven workers (heartbeat, idle compaction, retry backoff, + * `StreamManager.schedulePartialWrite`) go through `this.runner.runX`. + * - **I4 — Signatures unchanged.** Constructors, Promise facades, private + * methods (spy seams) and module exports keep their shapes; a runner is an + * optional trailing constructor parameter defaulting to `defaultEffectRunner`. + * - **I5 — No layer finalizers.** Teardown order stays explicit in + * `ServiceContainer.dispose()`/`shutdown()` and the CLI cleanup lists; layer + * bodies and wiring layers are `Effect.sync`-only and register no finalizers + * or forks, so `disposeAppRuntime` (the last step) reorders nothing. The one + * supervised resource, `AppFiberScope`, is closed at a fixed early position + * (see "Shutdown order"). + * - **I6 — Construction order is declared, never implied.** Wiring layers + * replay the former roots' setter/listener statements in order; a + * constructor may touch only its *declared* dependencies (built earlier by + * staging). Dependency order is expressed only with `Layer.provide` / + * `Layer.provideMerge` stages — never through `Layer.mergeAll` argument + * order, whose siblings may build in any order. + * - **I7 — In-process only.** DI changes no persisted data, IPC wire shapes, or + * oRPC handler bodies (beyond the `effect/context` source). + * - **I8 — One set of Layer definitions per service.** Every process root + * builds from the same layers (`CoreLive` is shared by `AppLive` and the CLI + * root). Unit harnesses (`createTestHistoryService`, `createTestToolConfig`, + * `createAgentSessionHarness`, …) intentionally bypass Layers and construct + * services directly. + * + * **R6 firewall.** In production code `Layer`, `ManagedRuntime` and + * `TestClock` are imported only under `src/node/services/di/`, and every + * `Context.Service` tag is declared there (`di/tags.ts`, plus the two seam + * tags in `effectRunner.ts`/`appFiberScope.ts`; `orpc/effectContext.ts` + * re-exports `MemoryMeta` and builds a narrow test-only context), so an effect + * RC rename touches one directory. Tests may inject a `TestClock` beneath the + * real graph (`serviceContainer.test.ts`) but go through `di/` helpers. + * + * ## Two seams, deliberately asymmetric + * + * - `EffectRunner` is **unsupervised**: fibers forked through it belong to the + * worker's own `Scope` (explicit `start()`/`stop()`, which stay synchronous + * because those fibers suspend only on the clock). Neither + * `closeScopeBounded(appFiberScope)` nor `disposeAppRuntime` interrupts or + * awaits them (pinned in `appFiberScope.test.ts`). Its `R = never` signature + * is what makes "not a service locator" a type error rather than a review + * item, and what lets a worker run on a `TestClock` (`./testEffectRunner.ts`). + * - `AppFiberScope` is **supervised**: a child of the runtime's layer scope; + * fibers forked into it with `Effect.forkIn` are interrupted *and awaited* + * by `closeScopeBounded` early in `dispose()`, while every dependency they + * might touch during finalization is still alive. No production occupant in + * Phase 11; the first candidate is the streamManager engine core. **Rule for + * occupants:** tolerate interruption at any suspension point, do not depend + * on resources torn down before step 2 below, and never fork long-lived I/O + * work through `EffectRunner` expecting shutdown to await it. + * + * ## Shutdown order (`ServiceContainer.dispose()`, one shared teardown behind + * a latch so concurrent/repeated calls — the desktop's two `before-quit` + * listeners, tests' dispose-then-shutdown — await the same sequence) + * + * 1. `backgroundProcessManager.beginShutdown()` — first; the latch that keeps + * persisted armed-monitor records from being erased by session teardown. + * 2. `closeScopeBounded(appFiberScope, APP_FIBER_SCOPE_CLOSE_TIMEOUT_MS)`. + * 3. The explicit sequence verbatim (`desktopBridgeServer.stop()` … + * `terminateAll()` … `timelineService.flush()` last), each step timed as a + * `[shutdown] {ms}` debug line (`shutdownStep.ts`). + * 4. `disposeAppRuntime(runtime, APP_RUNTIME_DISPOSE_TIMEOUT_MS)` — last; also + * re-closes `AppFiberScope` idempotently as a backstop. + * Both bounded teardowns share `boundedTeardown` below: `Effect.uninterruptible` + * shell, detached close fiber, `Effect.interruptible` join + `Effect.timeout`, + * defects folded into `log.warn`, never rejects. Budget: the two bounds + * (`APP_FIBER_SCOPE_CLOSE_TIMEOUT_MS` + `APP_RUNTIME_DISPOSE_TIMEOUT_MS`, + * `src/constants/terminationTimeouts.ts`) must add up to less than the callers' + * outer quit budgets (`desktop/main.ts` before-quit race, `cli/server.ts` + * force-exit timer), which stay the last line of defense. The CLI roots + * (`xum run`/`xum workflow`) mirror steps 1, 2 and 4 in + * their best-effort cleanup lists (`cli/runCleanup.ts`). `shutdown()` never + * touches the runtime or `AppFiberScope`. Crash paths (`uncaughtException`, + * SIGKILL) run no finalizers; durable state must stay crash-safe without them. + * + * ## Cost of the Layer machinery (recorded per PR; R7/R8) + * + * `[startup] AppRuntime built` grew 4 ms (PR 1, one layer) → 11 ms (PR 3, + * coarse core) → 18 → 23 ms (PR 4a/4b, 19 core layers + 8 stages + wiring) and + * reads 16–24 ms for the whole graph in `xum server`. Cold `new + * ServiceContainer(stores)` went 27 → 35 ms when the six desktop group layers + * + three composition nodes replaced the imperative constructor (PR 5: + * ≈ +8 ms cold / +0.3 ms warm for ~40 services; a `provideMerge`-only chain + * costs the same, so the cost is Effect first-use per layer, not sibling + * concurrency). `make typecheck` stayed flat (±4 %). Group layers, not + * per-service layers, are therefore the right granularity for tails whose + * teardown is hand-tuned anyway. + * + * ## Deliberately not done in Phase 11 + * + * `initialize()` as a Layer/startup effect (would break I1's failure + * semantics), layer finalizers for the existing `dispose()` steps (I5), + * `streamBridge` on the runtime, per-service optional tags (optional + * cross-cutting services stay optional via `CoreOptionsTag`), the streamManager + * engine core as the first `AppFiberScope` occupant. */ import assert from "@/common/utils/assert"; import { Context, Duration, Effect, Exit, Fiber, ManagedRuntime, Scope } from "effect"; diff --git a/src/node/services/heartbeatService.test.ts b/src/node/services/heartbeatService.test.ts index 51f83de6562..c9a9cd02043 100644 --- a/src/node/services/heartbeatService.test.ts +++ b/src/node/services/heartbeatService.test.ts @@ -1115,6 +1115,9 @@ describe("HeartbeatService", () => { }); test("startup does not fire heartbeats immediately", async () => { + // Default-runner smoke: the scheduler sleeps STARTUP_DELAY_MS on Effect's + // default (real) clock, so nothing may fire this early. Cadence itself is + // covered on virtual time in heartbeatService.testClock.test.ts. service.start(); await new Promise((resolve) => setTimeout(resolve, 100)); diff --git a/src/node/services/heartbeatService.testClock.test.ts b/src/node/services/heartbeatService.testClock.test.ts index 14c670d339e..13f0254ca53 100644 --- a/src/node/services/heartbeatService.testClock.test.ts +++ b/src/node/services/heartbeatService.testClock.test.ts @@ -10,9 +10,11 @@ import type { TaskService } from "./taskService"; import type { WorkspaceService } from "./workspaceService"; /** - * Cadence on virtual time. The real-timer suite (`heartbeatService.test.ts`) - * keeps exercising the default runner; this one drives the scheduler fiber - * through a TestClock-bound `EffectRunner`. + * Cadence on virtual time: this suite drives the scheduler fiber through a + * TestClock-bound `EffectRunner`. The default-runner smoke in + * `heartbeatService.test.ts` ("startup does not fire heartbeats immediately") + * keeps the real-clock production path covered; every other real sleep there + * waits on Promise settlement or `Date.now()` deadline math, not on the clock. */ describe("HeartbeatService on a TestClock", () => { let clock: TestEffectRunner; diff --git a/src/node/services/idleCompactionService.test.ts b/src/node/services/idleCompactionService.test.ts index 6c8265eef19..218d182e533 100644 --- a/src/node/services/idleCompactionService.test.ts +++ b/src/node/services/idleCompactionService.test.ts @@ -32,6 +32,7 @@ describe("IdleCompactionService", () => { let historyService: HistoryService; let mockExtensionMetadata: ExtensionMetadataService; let executeIdleCompactionMock: ReturnType Promise>>; + let loadConfigMock: ReturnType ProjectsConfig>>; let service: IdleCompactionService; let cleanup: () => Promise; @@ -43,8 +44,8 @@ describe("IdleCompactionService", () => { beforeEach(async () => { // Create mock config - mockConfig = { - loadConfigOrDefault: mock(() => ({ + loadConfigMock = mock( + (): ProjectsConfig => ({ projects: new Map([ [ testProjectPath, @@ -54,8 +55,9 @@ describe("IdleCompactionService", () => { }, ], ]), - })), - } as unknown as Config; + }) + ); + mockConfig = { loadConfigOrDefault: loadConfigMock } as unknown as Config; // Create real history service and seed default idle messages (25 hours ago) ({ historyService, cleanup } = await createTestHistoryService()); @@ -98,6 +100,22 @@ describe("IdleCompactionService", () => { await cleanup(); }); + describe("start/stop on the default runner", () => { + // Default-runner smoke (cadence itself is covered on virtual time in + // idleCompactionService.testClock.test.ts): with no runner injected the + // checker sleeps on Effect's default clock, so nothing may run this early + // in INITIAL_CHECK_DELAY_MS, and stop() must close the scope synchronously. + test("start() arms the checker on the real clock without an early sweep", async () => { + service.start(); + + await new Promise((resolve) => setTimeout(resolve, 20)); + + expect(loadConfigMock).not.toHaveBeenCalled(); + expect(executeIdleCompactionMock).not.toHaveBeenCalled(); + service.stop(); + }); + }); + describe("checkEligibility", () => { const threshold24h = 24 * oneHourMs; diff --git a/src/node/services/idleCompactionService.testClock.test.ts b/src/node/services/idleCompactionService.testClock.test.ts index 0dcb439e8d1..a837466f25d 100644 --- a/src/node/services/idleCompactionService.testClock.test.ts +++ b/src/node/services/idleCompactionService.testClock.test.ts @@ -12,8 +12,9 @@ import { } from "./idleCompactionService"; /** - * Checker cadence on virtual time (the real-timer suite in - * `idleCompactionService.test.ts` keeps covering the default runner). + * Checker cadence on virtual time. The default-runner smoke in + * `idleCompactionService.test.ts` ("start/stop on the default runner") keeps + * the real-clock production path covered. */ describe("IdleCompactionService on a TestClock", () => { let clock: TestEffectRunner; diff --git a/src/node/services/retryManager.test.ts b/src/node/services/retryManager.test.ts index 2699df4a1d9..bd540866576 100644 --- a/src/node/services/retryManager.test.ts +++ b/src/node/services/retryManager.test.ts @@ -1,67 +1,29 @@ -import { afterEach, beforeEach, describe, expect, it, setSystemTime, vi } from "bun:test"; +import { afterEach, beforeEach, describe, expect, it, setSystemTime, spyOn, vi } from "bun:test"; +import { Duration } from "effect"; import { calculateBackoffDelay } from "@/common/utils/messages/retryState"; +import { makeTestEffectRunner, type TestEffectRunner } from "./di/testEffectRunner"; import { RetryManager, type RetryStatusEvent } from "./retryManager"; -interface ScheduledTimer { - callback: () => void; - delayMs: number; -} - +/** + * The backoff sleep runs on the injected `EffectRunner`'s clock, so the suite + * drives it with a `TestClock` (`clock.adjust`) instead of intercepting + * `setTimeout`. `setSystemTime` only pins `Date.now()` for the `scheduledAt` + * stamp; it never drove timing. One default-runner smoke at the bottom keeps + * the production path (Effect's default clock → real `setTimeout`) covered. + */ describe("RetryManager", () => { - let scheduledTimers: Map; - let nextTimerId: number; + let clock: TestEffectRunner; beforeEach(() => { setSystemTime(new Date("2026-01-01T00:00:00Z")); - - scheduledTimers = new Map(); - nextTimerId = 1; - - vi.spyOn(globalThis, "setTimeout").mockImplementation((( - handler: TimerHandler, - timeout?: number - ) => { - if (typeof handler !== "function") { - throw new Error("RetryManager tests only support function timer handlers"); - } - const fn = handler as () => void; - - const timerId = nextTimerId; - nextTimerId += 1; - scheduledTimers.set(timerId, { - callback: () => { - fn(); - }, - delayMs: timeout ?? 0, - }); - - return timerId as unknown as ReturnType; - }) as unknown as typeof setTimeout); - - vi.spyOn(globalThis, "clearTimeout").mockImplementation((( - timer: ReturnType - ) => { - const timerId = Number(timer); - scheduledTimers.delete(timerId); - }) as typeof clearTimeout); + clock = makeTestEffectRunner(); }); - afterEach(() => { + afterEach(async () => { setSystemTime(); - vi.restoreAllMocks(); + await clock.dispose(); }); - function runNextTimer(): void { - const next = [...scheduledTimers.entries()].sort((left, right) => left[0] - right[0])[0]; - if (!next) { - throw new Error("Expected at least one scheduled timer"); - } - - const [timerId, timer] = next; - scheduledTimers.delete(timerId); - timer.callback(); - } - function createRetryManager() { const onRetry = vi.fn(() => Promise.resolve()); const events: RetryStatusEvent[] = []; @@ -70,13 +32,16 @@ describe("RetryManager", () => { }); return { - manager: new RetryManager("workspace-1", onRetry, onStatusChange), + manager: new RetryManager("workspace-1", onRetry, onStatusChange, clock.runner), onRetry, onStatusChange, events, }; } + /** Advance far past any backoff: a retry that is still armed would fire. */ + const adjustPastAnyBackoff = () => clock.adjust(Duration.millis(calculateBackoffDelay(6) * 2)); + it("uses exponential backoff delays from common retry state utilities", () => { expect(calculateBackoffDelay(0)).toBe(1000); expect(calculateBackoffDelay(1)).toBe(2000); @@ -84,7 +49,7 @@ describe("RetryManager", () => { expect(calculateBackoffDelay(6)).toBe(60000); }); - it("abandons non-retryable errors", () => { + it("abandons non-retryable errors", async () => { const { manager, onRetry, onStatusChange, events } = createRetryManager(); manager.handleStreamFailure({ type: "api_key_not_found" }); @@ -92,12 +57,12 @@ describe("RetryManager", () => { expect(onStatusChange).toHaveBeenCalledTimes(1); expect(events).toEqual([{ type: "auto-retry-abandoned", reason: "api_key_not_found" }]); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); + await adjustPastAnyBackoff(); expect(onRetry).not.toHaveBeenCalled(); }); - it("non-retryable error cancels pending retryable timer", () => { - const { manager, events } = createRetryManager(); + it("non-retryable error cancels pending retryable timer", async () => { + const { manager, onRetry, events } = createRetryManager(); // Schedule a retryable error first manager.handleStreamFailure({ type: "unknown" }); @@ -106,11 +71,12 @@ describe("RetryManager", () => { // Then a non-retryable error arrives — should cancel the pending timer manager.handleStreamFailure({ type: "api_key_not_found" }); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); expect(events).toContainEqual({ type: "auto-retry-abandoned", reason: "api_key_not_found" }); + await adjustPastAnyBackoff(); + expect(onRetry).not.toHaveBeenCalled(); }); - it("schedules and runs retry after backoff delay", async () => { + it("schedules and runs retry exactly at the backoff delay", async () => { const { manager, onRetry, events } = createRetryManager(); manager.handleStreamFailure({ type: "unknown", message: "transient" }); @@ -125,19 +91,18 @@ describe("RetryManager", () => { }, ]); expect(manager.isRetryPending).toBe(true); - expect(scheduledTimers.size).toBe(1); - expect(scheduledTimers.get(1)?.delayMs).toBe(expectedDelay); - runNextTimer(); - await Promise.resolve(); + await clock.adjust(Duration.millis(expectedDelay - 1)); + expect(onRetry).not.toHaveBeenCalled(); + expect(manager.isRetryPending).toBe(true); + await clock.adjust(Duration.millis(1)); expect(onRetry).toHaveBeenCalledTimes(1); expect(events).toContainEqual({ type: "auto-retry-starting", attempt: 1 }); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); }); - it("exposes pending scheduled retry for reconnect snapshots", () => { + it("exposes pending scheduled retry for reconnect snapshots", async () => { const { manager } = createRetryManager(); manager.handleStreamFailure({ type: "unknown", message: "transient" }); @@ -163,7 +128,7 @@ describe("RetryManager", () => { scheduledAt: Date.now(), }); - runNextTimer(); + await clock.adjust(Duration.millis(calculateBackoffDelay(1))); expect(manager.getScheduledStatusSnapshot()).toBeNull(); }); @@ -177,53 +142,54 @@ describe("RetryManager", () => { expect(manager.getScheduledStatusSnapshot()).toBeNull(); }); - it("cancel clears pending retry timer", () => { + it("cancel clears pending retry timer", async () => { const { manager, onRetry } = createRetryManager(); manager.handleStreamFailure({ type: "unknown" }); expect(manager.isRetryPending).toBe(true); - expect(scheduledTimers.size).toBe(1); manager.cancel(); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); + await adjustPastAnyBackoff(); expect(onRetry).not.toHaveBeenCalled(); }); - it("setEnabled(false) prevents scheduling", () => { - const { manager, onStatusChange } = createRetryManager(); + it("setEnabled(false) prevents scheduling", async () => { + const { manager, onRetry, onStatusChange } = createRetryManager(); manager.setEnabled(false); manager.handleStreamFailure({ type: "unknown" }); expect(onStatusChange).not.toHaveBeenCalled(); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); + await adjustPastAnyBackoff(); + expect(onRetry).not.toHaveBeenCalled(); }); - it("setEnabled(false) cancels pending retry and emits abandoned event", () => { - const { manager, events } = createRetryManager(); + it("setEnabled(false) cancels pending retry and emits abandoned event", async () => { + const { manager, onRetry, events } = createRetryManager(); manager.handleStreamFailure({ type: "unknown" }); expect(manager.isRetryPending).toBe(true); manager.setEnabled(false); expect(manager.isRetryPending).toBe(false); - expect(scheduledTimers.size).toBe(0); expect(events).toContainEqual({ type: "auto-retry-abandoned", reason: "disabled_by_user", }); + await adjustPastAnyBackoff(); + expect(onRetry).not.toHaveBeenCalled(); }); - it("setEnabled(false) emits abandoned even after timer has fired (in-flight retry)", () => { + it("setEnabled(false) emits abandoned even after timer has fired (in-flight retry)", async () => { const { manager, events } = createRetryManager(); - // Schedule a retry, then fire the timer so retryTimer is null - // but state.attempt > 0 (retry callback is in-flight). + // Schedule a retry, then let the backoff elapse so the fiber is past its + // sleep but state.attempt > 0 (retry callback is in-flight). manager.handleStreamFailure({ type: "unknown" }); expect(manager.isRetryPending).toBe(true); - runNextTimer(); + await clock.adjust(Duration.millis(calculateBackoffDelay(1))); expect(manager.isRetryPending).toBe(false); // Disable while the retry callback is executing. Even though the timer @@ -235,7 +201,7 @@ describe("RetryManager", () => { }); }); - it("setEnabled(false) during auto-retry-starting prevents queued resume", () => { + it("setEnabled(false) during auto-retry-starting prevents queued resume", async () => { const onRetry = vi.fn(() => Promise.resolve()); const events: RetryStatusEvent[] = []; @@ -247,11 +213,11 @@ describe("RetryManager", () => { } }); - const manager = new RetryManager("workspace-1", onRetry, onStatusChange); + const manager = new RetryManager("workspace-1", onRetry, onStatusChange, clock.runner); managerRef.current = manager; manager.handleStreamFailure({ type: "unknown" }); - runNextTimer(); + await clock.adjust(Duration.millis(calculateBackoffDelay(1))); expect(onRetry).not.toHaveBeenCalled(); expect(events).toContainEqual({ @@ -274,10 +240,10 @@ describe("RetryManager", () => { events.push(event); }); - const manager = new RetryManager("workspace-1", onRetry, onStatusChange); + const manager = new RetryManager("workspace-1", onRetry, onStatusChange, clock.runner); manager.handleStreamFailure({ type: "unknown" }); - runNextTimer(); + await clock.adjust(Duration.millis(calculateBackoffDelay(1))); expect(onRetry).toHaveBeenCalledTimes(1); manager.setEnabled(false); @@ -296,18 +262,17 @@ describe("RetryManager", () => { expect(abandonedReasons).not.toContain("late_retry_failure"); }); - it("reschedules when a second failure arrives while retry is pending", () => { - const { manager, events } = createRetryManager(); + it("reschedules when a second failure arrives while retry is pending", async () => { + const { manager, onRetry, events } = createRetryManager(); // First failure schedules a retry manager.handleStreamFailure({ type: "unknown" }); expect(manager.isRetryPending).toBe(true); - expect(scheduledTimers.size).toBe(1); + await clock.adjust(Duration.millis(calculateBackoffDelay(1) - 1)); // Second failure should cancel the first and reschedule with higher backoff manager.handleStreamFailure({ type: "network" }); expect(manager.isRetryPending).toBe(true); - expect(scheduledTimers.size).toBe(1); // only one timer active const scheduleEvents = events.filter( (event): event is Extract => @@ -316,13 +281,20 @@ describe("RetryManager", () => { expect(scheduleEvents).toHaveLength(2); // Second attempt should have higher backoff than first expect(scheduleEvents[1].attempt).toBeGreaterThan(scheduleEvents[0].attempt); + + // The superseded timer is gone: only the new one can fire, and only once. + const secondDelayMs = calculateBackoffDelay(2); + await clock.adjust(Duration.millis(secondDelayMs - 1)); + expect(onRetry).not.toHaveBeenCalled(); + await clock.adjust(Duration.millis(1)); + expect(onRetry).toHaveBeenCalledTimes(1); }); - it("handleStreamSuccess resets retry attempt progression", () => { + it("handleStreamSuccess resets retry attempt progression", async () => { const { manager, events } = createRetryManager(); manager.handleStreamFailure({ type: "unknown" }); - runNextTimer(); + await clock.adjust(Duration.millis(calculateBackoffDelay(1))); manager.handleStreamSuccess(); manager.handleStreamFailure({ type: "unknown" }); @@ -337,3 +309,41 @@ describe("RetryManager", () => { expect(scheduleEvents[1]?.attempt).toBe(1); }); }); + +/** + * Default-runner smoke: with no runner injected (direct construction, the + * aiService fallback) the backoff sleeps on Effect's default clock, i.e. a + * real `setTimeout`. Intercepting the timer registration proves that path + * without a two-second wall-clock wait. + */ +describe("RetryManager on the default runner", () => { + it("arms the backoff as a real setTimeout and runs onRetry when it fires", async () => { + const timers: Array<{ delayMs: number; fire: () => void }> = []; + const setTimeoutSpy = spyOn(globalThis, "setTimeout").mockImplementation((( + handler: TimerHandler, + timeout?: number + ) => { + if (typeof handler !== "function") { + throw new Error("RetryManager smoke only supports function timer handlers"); + } + timers.push({ delayMs: timeout ?? 0, fire: handler as () => void }); + return timers.length as unknown as ReturnType; + }) as unknown as typeof setTimeout); + try { + const onRetry = vi.fn(() => Promise.resolve()); + const manager = new RetryManager("workspace-1", onRetry, () => undefined); + + manager.handleStreamFailure({ type: "unknown" }); + expect(manager.isRetryPending).toBe(true); + expect(timers.map((timer) => timer.delayMs)).toEqual([calculateBackoffDelay(1)]); + + timers[0].fire(); + await Promise.resolve(); + expect(onRetry).toHaveBeenCalledTimes(1); + expect(manager.isRetryPending).toBe(false); + manager.dispose(); + } finally { + setTimeoutSpy.mockRestore(); + } + }); +}); diff --git a/src/node/services/retryManager.testClock.test.ts b/src/node/services/retryManager.testClock.test.ts deleted file mode 100644 index c8812fd92a0..00000000000 --- a/src/node/services/retryManager.testClock.test.ts +++ /dev/null @@ -1,79 +0,0 @@ -import { afterEach, beforeEach, describe, expect, it, mock } from "bun:test"; -import { Duration } from "effect"; -import { calculateBackoffDelay } from "@/common/utils/messages/retryState"; -import { makeTestEffectRunner, type TestEffectRunner } from "./di/testEffectRunner"; -import { RetryManager, type RetryStatusEvent } from "./retryManager"; - -/** - * Backoff timing on virtual time (the real-timer suite in - * `retryManager.test.ts` keeps covering the default runner, which today's - * streamManager call site still uses). - */ -describe("RetryManager on a TestClock", () => { - let clock: TestEffectRunner; - let manager: RetryManager; - let onRetry: ReturnType Promise>>; - let events: RetryStatusEvent[]; - - beforeEach(() => { - clock = makeTestEffectRunner(); - onRetry = mock(() => Promise.resolve()); - events = []; - manager = new RetryManager( - "workspace-1", - onRetry, - (event) => { - events.push(event); - }, - clock.runner - ); - }); - - afterEach(async () => { - manager.dispose(); - await clock.dispose(); - }); - - it("fires exactly at the backoff delay", async () => { - manager.handleStreamFailure({ type: "unknown", message: "transient" }); - const delayMs = calculateBackoffDelay(1); - expect(events.map((event) => event.type)).toEqual(["auto-retry-scheduled"]); - expect(manager.isRetryPending).toBe(true); - - await clock.adjust(Duration.millis(delayMs - 1)); - expect(onRetry).not.toHaveBeenCalled(); - expect(manager.isRetryPending).toBe(true); - - await clock.adjust(Duration.millis(1)); - expect(onRetry).toHaveBeenCalledTimes(1); - expect(manager.isRetryPending).toBe(false); - expect(events.map((event) => event.type)).toEqual([ - "auto-retry-scheduled", - "auto-retry-starting", - ]); - }); - - it("cancel() before the delay elapses means the retry never fires", async () => { - manager.handleStreamFailure({ type: "unknown", message: "transient" }); - manager.cancel(); - expect(manager.isRetryPending).toBe(false); - - await clock.adjust(Duration.millis(calculateBackoffDelay(1) * 10)); - - expect(onRetry).not.toHaveBeenCalled(); - expect(events.map((event) => event.type)).toEqual(["auto-retry-scheduled"]); - }); - - it("a second failure before the delay reschedules with the next backoff", async () => { - manager.handleStreamFailure({ type: "unknown" }); - await clock.adjust(Duration.millis(calculateBackoffDelay(1) - 1)); - manager.handleStreamFailure({ type: "unknown" }); - const secondDelayMs = calculateBackoffDelay(2); - - // The superseded timer is gone: only the new one can fire. - await clock.adjust(Duration.millis(secondDelayMs - 1)); - expect(onRetry).not.toHaveBeenCalled(); - await clock.adjust(Duration.millis(1)); - expect(onRetry).toHaveBeenCalledTimes(1); - }); -}); diff --git a/src/node/services/serviceContainer.ts b/src/node/services/serviceContainer.ts index bb1f36db870..2e2ea75d559 100644 --- a/src/node/services/serviceContainer.ts +++ b/src/node/services/serviceContainer.ts @@ -56,6 +56,7 @@ import { type AppRuntime, } from "@/node/services/di/appRuntime"; import { AppLive } from "@/node/services/di/layers/app"; +import { shutdownStep } from "@/node/services/shutdownStep"; import { AgentBrowserSessionDiscovery, AgentPluginInstall, @@ -468,47 +469,70 @@ export class ServiceContainer { return this.disposePromise; } + /** + * The §5 teardown order (di/appRuntime.ts). Every step reports its duration + * as a `[shutdown]` debug line via `shutdownStep` (synchronous steps without + * a suspension point), so a quit transcript localizes a slow or hung step; + * `closeScopeBounded`/`disposeAppRuntime` write their own lines. + */ private async disposeOnce(): Promise { + const disposeStartedAt = performance.now(); + log.debug("[shutdown] ServiceContainer.dispose starting"); // Must run before any session teardown: AgentSession.dispose() triggers // backgroundProcessManager.cleanup(), which would otherwise erase the persisted // armed-monitor registry records that drive post-restart "monitor lost" wakes. - this.backgroundProcessManager.beginShutdown(); + shutdownStep("backgroundProcessManager.beginShutdown", () => + this.backgroundProcessManager.beginShutdown() + ); // Interrupt and await the runtime's supervised fibers while every dependency // they might touch during finalization is still alive. Fixed here (before // the explicit teardown) so later occupants do not re-derive the position; // bounded and idempotent, and never rejects (di/appRuntime.ts). await closeScopeBounded(this.appFiberScope); // Stop the bridge before closing sessions so desktop clients get a clean disconnect. - await this.desktopBridgeServer.stop(); - this.desktopTokenManager.dispose(); - await this.desktopSessionManager.closeAll(); + await shutdownStep("desktopBridgeServer.stop", () => this.desktopBridgeServer.stop()); + shutdownStep("desktopTokenManager.dispose", () => this.desktopTokenManager.dispose()); + await shutdownStep("desktopSessionManager.closeAll", () => + this.desktopSessionManager.closeAll() + ); // Stop the periodic AgentStatusService loop here too (not just in // shutdown()): dispose() is the path used by the desktop before-quit // and ACP in-process close handlers, and the ref'd setInterval would // otherwise keep the process alive and continue calling // generateWorkspaceStatus against services that are about to be torn // down below. - this.agentStatusService.stop(); - await this.browserBridgeServer.stop(); - this.browserSessionStateHub.dispose(); - this.browserBridgeTokenManager.dispose(); - await this.analyticsService.dispose(); - this.policyService.dispose(); - this.mcpServerManager.dispose(); - await this.mcpOauthService.dispose(); - await this.muxGatewayOauthService.dispose(); - await this.muxGovernorOauthService.dispose(); - await this.codexOauthService.dispose(); - await this.coderOauthService.dispose(); + shutdownStep("agentStatusService.stop", () => this.agentStatusService.stop()); + await shutdownStep("browserBridgeServer.stop", () => this.browserBridgeServer.stop()); + shutdownStep("browserSessionStateHub.dispose", () => this.browserSessionStateHub.dispose()); + shutdownStep("browserBridgeTokenManager.dispose", () => + this.browserBridgeTokenManager.dispose() + ); + await shutdownStep("analyticsService.dispose", () => this.analyticsService.dispose()); + shutdownStep("policyService.dispose", () => this.policyService.dispose()); + shutdownStep("mcpServerManager.dispose", () => this.mcpServerManager.dispose()); + await shutdownStep("mcpOauthService.dispose", () => this.mcpOauthService.dispose()); + await shutdownStep("muxGatewayOauthService.dispose", () => + this.muxGatewayOauthService.dispose() + ); + await shutdownStep("muxGovernorOauthService.dispose", () => + this.muxGovernorOauthService.dispose() + ); + await shutdownStep("codexOauthService.dispose", () => this.codexOauthService.dispose()); + await shutdownStep("coderOauthService.dispose", () => this.coderOauthService.dispose()); - this.copilotOauthService.dispose(); - this.serverAuthService.dispose(); - this.providerService.dispose(); - await this.backgroundProcessManager.terminateAll(); - await this.timelineService.flush(); + shutdownStep("copilotOauthService.dispose", () => this.copilotOauthService.dispose()); + shutdownStep("serverAuthService.dispose", () => this.serverAuthService.dispose()); + shutdownStep("providerService.dispose", () => this.providerService.dispose()); + await shutdownStep("backgroundProcessManager.terminateAll", () => + this.backgroundProcessManager.terminateAll() + ); + await shutdownStep("timelineService.flush", () => this.timelineService.flush()); // Last: close the Effect runtime's scope. No layer owns finalizers yet, so // this only releases the runtime; the position (after every explicit // teardown step) is fixed now for later scope-owned occupants. await disposeAppRuntime(this.runtime.managed); + log.debug("[shutdown] ServiceContainer.dispose completed", { + totalMs: Math.round(performance.now() - disposeStartedAt), + }); } } diff --git a/src/node/services/shutdownStep.test.ts b/src/node/services/shutdownStep.test.ts new file mode 100644 index 00000000000..0be9dbbe112 --- /dev/null +++ b/src/node/services/shutdownStep.test.ts @@ -0,0 +1,45 @@ +import { describe, expect, test } from "bun:test"; +import { shutdownStep } from "./shutdownStep"; + +describe("shutdownStep", () => { + test("a synchronous step runs to completion before returning and yields no Promise", () => { + const order: string[] = []; + const result = shutdownStep("sync", () => { + order.push("ran"); + }); + order.push("returned"); + expect(result).toBeUndefined(); + expect(order).toEqual(["ran", "returned"]); + }); + + test("an async step is awaited, including a thenable from another realm", async () => { + let settled = false; + const foreignThenable = { + then(resolve: (value: void) => void) { + setTimeout(() => { + settled = true; + resolve(); + }, 5); + }, + } as unknown as Promise; + + await shutdownStep("thenable", () => foreignThenable); + expect(settled).toBe(true); + }); + + test("errors propagate unchanged", async () => { + expect(() => + shutdownStep("sync-throw", () => { + throw new Error("sync boom"); + }) + ).toThrow("sync boom"); + const rejection = await shutdownStep("async-reject", () => + Promise.reject(new Error("async boom")) + ).then( + () => undefined, + (error: unknown) => error + ); + expect(rejection).toBeInstanceOf(Error); + expect((rejection as Error).message).toBe("async boom"); + }); +}); diff --git a/src/node/services/shutdownStep.ts b/src/node/services/shutdownStep.ts new file mode 100644 index 00000000000..8c002dd1006 --- /dev/null +++ b/src/node/services/shutdownStep.ts @@ -0,0 +1,53 @@ +/** + * Per-step `[shutdown]` timing for the hand-ordered teardown lists + * (`ServiceContainer.dispose()`, the CLI roots' cleanup lists, `xum server`'s + * signal handler). Each step writes a start marker before it runs and a + * completion line with its duration, so a shutdown transcript shows where the + * time goes and — when a step hangs, whether in an awaited disposer that never + * settles or in a blocking synchronous call — the last line before silence + * names the culprit rather than its predecessor. Debug level: production logs + * stay quiet unless the log level is raised. + * + * A synchronous step is timed and logged before this returns and no Promise is + * created, so wrapping one adds no suspension point: adjacent synchronous + * teardown statements still run back-to-back on the same tick and their + * interleaving with a concurrently running `shutdown()` is unchanged. The + * Promise overload is listed first so an async step can never bind to the + * synchronous signature (a `Promise` return is assignable to `void`); + * `@typescript-eslint/no-misused-promises` guards the reverse direction. + * + * Errors propagate unchanged after the completion line is written; + * containment (or not) stays with the caller exactly as before. + */ +import { log } from "./log"; + +export function shutdownStep(name: string, run: () => Promise): Promise; +export function shutdownStep(name: string, run: () => void): void; +export function shutdownStep(name: string, run: () => void | Promise): void | Promise { + log.debug(`[shutdown] ${name} starting`); + const startedAt = performance.now(); + const done = () => { + log.debug(`[shutdown] ${name}`, { ms: Math.round(performance.now() - startedAt) }); + }; + let result: void | Promise; + try { + result = run(); + } catch (error) { + done(); + throw error; + } + if (isThenable(result)) { + // Thenable check rather than `instanceof Promise`: a promise created in + // another realm (vm context, worker boundary) must still be awaited. + return Promise.resolve(result).finally(done); + } + done(); +} + +function isThenable(value: unknown): value is PromiseLike { + return ( + typeof value === "object" && + value !== null && + typeof (value as { then?: unknown }).then === "function" + ); +} diff --git a/src/node/services/streamManager.test.ts b/src/node/services/streamManager.test.ts index cd100e18854..4f5337ffc08 100644 --- a/src/node/services/streamManager.test.ts +++ b/src/node/services/streamManager.test.ts @@ -1059,56 +1059,124 @@ describe("StreamManager - stream resource scope", () => { // A debounced partial flush scheduled during streaming is tied to the // stream's resource scope. Once the stream ends, the pending flush must be // interrupted with the scope — a late write would resurrect partial state - // for a dead stream. - const workspaceId = "scope-debounce-interrupt-workspace"; - const streamManager = new StreamManager(historyService); - Reflect.set(streamManager, "tokenTracker", { - setModel: () => Promise.resolve(undefined), - countTokens: () => Promise.resolve(0), - }); - Reflect.set(streamManager, "createTempDirForStream", () => - Promise.resolve("/tmp/phase10-scope-tempdir") - ); - Reflect.set(streamManager, "cleanupStreamTempDir", () => undefined); + // for a dead stream. The debounce sleeps on the injected runner's + // TestClock, so "later" is a virtual-time adjust, not a real wait. + const testRunner = makeTestEffectRunner(); + try { + const workspaceId = "scope-debounce-interrupt-workspace"; + const streamManager = new StreamManager( + historyService, + undefined, + undefined, + undefined, + testRunner.runner + ); + Reflect.set(streamManager, "tokenTracker", { + setModel: () => Promise.resolve(undefined), + countTokens: () => Promise.resolve(0), + }); + Reflect.set(streamManager, "createTempDirForStream", () => + Promise.resolve("/tmp/phase10-scope-tempdir") + ); + Reflect.set(streamManager, "cleanupStreamTempDir", () => undefined); - const workspaceStreams = getWorkspaceStreamsForTests(streamManager); - const streamInfoForTests = () => - workspaceStreams.get(workspaceId) as - | { lastPartialWriteTime?: number; partialWriteFiber?: unknown } - | undefined; + const workspaceStreams = getWorkspaceStreamsForTests(streamManager); + const streamInfoForTests = () => + workspaceStreams.get(workspaceId) as + | { lastPartialWriteTime?: number; partialWriteFiber?: unknown } + | undefined; - let debounceArmedBeforeFinish = false; - Reflect.set(streamManager, "createStreamResult", () => - createStreamResultForTests( - (async function* () { - // First delta writes immediately (lastPartialWriteTime starts at 0). - yield { type: "text-delta", text: "first" }; - // Wait until that write stamps the throttle clock so the second - // delta deterministically lands inside the throttle window. - while ((streamInfoForTests()?.lastPartialWriteTime ?? 0) === 0) { - await new Promise((resolve) => setTimeout(resolve, 5)); - } - yield { type: "text-delta", text: "second" }; - // The consumer fully processed the second delta before pulling the - // next part, and the debounce arms synchronously. - debounceArmedBeforeFinish = streamInfoForTests()?.partialWriteFiber != null; - yield { type: "finish", finishReason: "stop" }; - })() - ) - ); - const writePartialSpy = spyOn(historyService, "writePartial"); + let debounceArmedBeforeFinish = false; + Reflect.set(streamManager, "createStreamResult", () => + createStreamResultForTests( + (async function* () { + // First delta writes immediately (lastPartialWriteTime starts at 0). + yield { type: "text-delta", text: "first" }; + // Wait until that write stamps the throttle clock so the second + // delta deterministically lands inside the throttle window. + while ((streamInfoForTests()?.lastPartialWriteTime ?? 0) === 0) { + await new Promise((resolve) => setTimeout(resolve, 5)); + } + yield { type: "text-delta", text: "second" }; + // The consumer fully processed the second delta before pulling the + // next part, and the debounce arms synchronously. + debounceArmedBeforeFinish = streamInfoForTests()?.partialWriteFiber != null; + yield { type: "finish", finishReason: "stop" }; + })() + ) + ); + const writePartialSpy = spyOn(historyService, "writePartial"); + + const throttleMs: unknown = Reflect.get(streamManager, "PARTIAL_WRITE_THROTTLE_MS"); + if (typeof throttleMs !== "number") { + throw new Error("Expected StreamManager.PARTIAL_WRITE_THROTTLE_MS to be a number"); + } - const throttleMs: unknown = Reflect.get(streamManager, "PARTIAL_WRITE_THROTTLE_MS"); - if (typeof throttleMs !== "number") { - throw new Error("Expected StreamManager.PARTIAL_WRITE_THROTTLE_MS to be a number"); + await runLifecycleStreamForTests(streamManager, workspaceId); + + expect(debounceArmedBeforeFinish).toBe(true); + const writesAtStreamEnd = writePartialSpy.mock.calls.length; + await testRunner.adjust(throttleMs * 2); + // A flush that survived the scope close would settle on the next macrotask. + await new Promise((resolve) => setTimeout(resolve, 0)); + expect(writePartialSpy.mock.calls.length).toBe(writesAtStreamEnd); + } finally { + await testRunner.dispose(); } + }); - await runLifecycleStreamForTests(streamManager, workspaceId); + test("a debounced partial write arms a real setTimeout through the default runner", async () => { + // Default-runner smoke: with nothing injected the debounce sleeps on + // Effect's default clock, i.e. a real setTimeout. Intercepting the timer + // registration (as the RetryManager smoke does) keeps this deterministic: + // no wall-clock window that a loaded host could overrun. + const realSetTimeout = globalThis.setTimeout; + const timers: Array<{ delayMs: number; fire: () => void }> = []; + const setTimeoutSpy = spyOn(globalThis, "setTimeout").mockImplementation((( + handler: TimerHandler, + timeout?: number + ) => { + if (typeof handler !== "function") { + throw new Error("debounce smoke only supports function timer handlers"); + } + timers.push({ delayMs: timeout ?? 0, fire: handler as () => void }); + return timers.length as unknown as ReturnType; + }) as unknown as typeof setTimeout); + try { + const streamManager = new StreamManager(historyService); + const workspaceId = "default-runner-debounce-workspace"; + const throttleMs: unknown = Reflect.get(streamManager, "PARTIAL_WRITE_THROTTLE_MS"); + if (typeof throttleMs !== "number") { + throw new Error("Expected StreamManager.PARTIAL_WRITE_THROTTLE_MS to be a number"); + } + // A write just happened: the whole throttle window is still ahead. + const streamInfo = createStreamInfoForTests({ lastPartialWriteTime: Date.now() }); + getWorkspaceStreamsForTests(streamManager).set(workspaceId, streamInfo); + const schedulePartialWrite = getPrivateMethodForTests< + (workspaceId: string, streamInfo: Record) => Promise + >(streamManager, "schedulePartialWrite"); + const writePartialSpy = spyOn(historyService, "writePartial"); - expect(debounceArmedBeforeFinish).toBe(true); - const writesAtStreamEnd = writePartialSpy.mock.calls.length; - await new Promise((resolve) => setTimeout(resolve, throttleMs + 200)); - expect(writePartialSpy.mock.calls.length).toBe(writesAtStreamEnd); + await schedulePartialWrite.call(streamManager, workspaceId, streamInfo); + expect(streamInfo.partialWriteFiber).toBeDefined(); + expect(writePartialSpy).not.toHaveBeenCalled(); + // Exactly one timer, for the remaining throttle window. + expect(timers).toHaveLength(1); + expect(timers[0].delayMs).toBeGreaterThan(0); + expect(timers[0].delayMs).toBeLessThanOrEqual(throttleMs); + + timers[0].fire(); + setTimeoutSpy.mockRestore(); + // The flush's Effect.promise settles asynchronously. + const deadline = Date.now() + 2_000; + while (writePartialSpy.mock.calls.length === 0 && Date.now() < deadline) { + await new Promise((resolve) => realSetTimeout(resolve, 5)); + } + expect(writePartialSpy).toHaveBeenCalledTimes(1); + expect(streamInfo.partialWriteFiber).toBeUndefined(); + } finally { + setTimeoutSpy.mockRestore(); + } }); test("runs the partial-write debounce on the injected runner's clock", async () => {