diff --git a/.changeset/576-proxy-upstream-timeout.md b/.changeset/576-proxy-upstream-timeout.md new file mode 100644 index 000000000..05fa83f1e --- /dev/null +++ b/.changeset/576-proxy-upstream-timeout.md @@ -0,0 +1,5 @@ +--- +"agent-bundle": patch +--- + +Make the dev runtime client-surface proxy's upstream request timeout configurable: `RuntimeClientSurfaceProxy.open` accepts a trailing `RuntimeClientSurfaceProxyOptions` with `upstreamRequestTimeoutMs` (default `defaultRuntimeClientSurfaceUpstreamRequestTimeoutMs`, 15 000 ms; a value that is not a positive safe integer within the `setTimeout` ceiling is rejected before the proxy opens). The dev server keeps the 15 s default (#584) diff --git a/packages/agent-bundle/src/dev/runtime-client-surface-proxy.ts b/packages/agent-bundle/src/dev/runtime-client-surface-proxy.ts index dbf38d172..2b60e2c72 100644 --- a/packages/agent-bundle/src/dev/runtime-client-surface-proxy.ts +++ b/packages/agent-bundle/src/dev/runtime-client-surface-proxy.ts @@ -23,7 +23,10 @@ import { const appAssetLimit = 4 * 1024 * 1024; const headerLimit = 16 * 1024; -const upstreamRequestTimeout = 15_000; +/** Bound on each upstream compiler request unless `RuntimeClientSurfaceProxyOptions` overrides it. */ +export const defaultRuntimeClientSurfaceUpstreamRequestTimeoutMs = 15_000; +/** Node collapses longer `setTimeout` delays to 1 ms, which would silently drop the bound. */ +const maximumTimerDelayMs = 2_147_483_647; const loopbackHosts = new Set(['127.0.0.1', '::1']); /** * Proxy-owned browser push channel. The proxy authors both ends: its server @@ -60,6 +63,16 @@ export interface RuntimeClientSurfaceConnectionEvent { readonly type: 'connected' | 'disconnected'; } +/** Server-only tuning for `RuntimeClientSurfaceProxy.open`; production callers take the defaults. */ +export interface RuntimeClientSurfaceProxyOptions { + /** + * Bound on each upstream compiler request — the bootstrap entry fetch and + * every proxied asset — from dispatch until its body has been read. A + * request still open at the deadline is aborted and answered 502. + */ + readonly upstreamRequestTimeoutMs?: number; +} + interface ValidatedEndpoint { readonly entryPath: string; readonly host: string; @@ -134,6 +147,14 @@ const contentSecurityPolicy = (input: RuntimeClientSurfaceContentPolicy): string return value; }; +const upstreamRequestTimeoutMs = (options: RuntimeClientSurfaceProxyOptions): number => { + const timeout = options.upstreamRequestTimeoutMs ?? defaultRuntimeClientSurfaceUpstreamRequestTimeoutMs; + if (!Number.isSafeInteger(timeout) || timeout < 1 || timeout > maximumTimerDelayMs) { + throw new TypeError(`Runtime client surface proxy options must use an integer upstreamRequestTimeoutMs from 1 to ${String(maximumTimerDelayMs)}.`); + } + return timeout; +}; + const response = (target: ServerResponse, status: number): void => { if (target.destroyed || target.writableEnded) return; target.writeHead(status, { 'content-type': 'text/plain; charset=utf-8', 'x-content-type-options': 'nosniff' }); @@ -591,10 +612,12 @@ export class RuntimeClientSurfaceProxy { listener: (event: RuntimeClientSurfaceConnectionEvent) => void, hostOrigin: string, policy: RuntimeClientSurfaceContentPolicy = strictRuntimeClientSurfaceContentPolicy, + options: RuntimeClientSurfaceProxyOptions = {}, ): Promise { const trusted = endpoint(input); const trustedHostOrigin = canonicalHostOrigin(hostOrigin); const trustedContentSecurityPolicy = contentSecurityPolicy(policy); + const trustedUpstreamRequestTimeoutMs = upstreamRequestTimeoutMs(options); const bootstrapCapability = randomBytes(32).toString('base64url'); const sessionCapability = randomBytes(32).toString('base64url'); const bootstrapPath = `/__agent_bundle_runtime/bootstrap/${bootstrapCapability}`; @@ -656,7 +679,7 @@ export class RuntimeClientSurfaceProxy { const deadline = setTimeout(() => { abort(); rejectPromise(new Error('Runtime client entry timed out.')); - }, upstreamRequestTimeout); + }, trustedUpstreamRequestTimeoutMs); const upstreamRequest = requestUpstream({ agent: upstreamAgent, headers: { accept: 'text/html' }, @@ -772,7 +795,7 @@ export class RuntimeClientSurfaceProxy { timedOut = true; response(target, 502); abort(); - }, upstreamRequestTimeout); + }, trustedUpstreamRequestTimeoutMs); const upstreamRequest = requestUpstream({ agent: upstreamAgent, headers: { diff --git a/packages/agent-bundle/tests/dev-host-install.test.ts b/packages/agent-bundle/tests/dev-host-install.test.ts index 0ecc39858..c3bd0cb7d 100644 --- a/packages/agent-bundle/tests/dev-host-install.test.ts +++ b/packages/agent-bundle/tests/dev-host-install.test.ts @@ -316,6 +316,10 @@ it('re-syncs the isolated Cursor install from coordinator epochs and ignores a f }); const coordinator = new DevCoordinator({ acquireLock: async () => ({ close: async () => undefined }), + // A no-op watcher: the real ProjectWatcher would turn this test's own source + // writes into an unrequested second rebuild that races the explicit + // rebuild() calls and can rewrite the install marker after settled() (#576). + createWatcher: () => ({ close: async () => undefined }), epochStore, eventHub, prepareCommand: 'dev', diff --git a/packages/agent-bundle/tests/runtime-client-surface-proxy.test.ts b/packages/agent-bundle/tests/runtime-client-surface-proxy.test.ts index ccbc99194..2656e2a0e 100644 --- a/packages/agent-bundle/tests/runtime-client-surface-proxy.test.ts +++ b/packages/agent-bundle/tests/runtime-client-surface-proxy.test.ts @@ -10,10 +10,20 @@ import { type DevRuntimeClientSurfaceEndpoint, } from '../src/dev/index.ts'; import { runtimeAppMessageLimits } from '../src/dev/runtime-app-message-limits.ts'; +import { + defaultRuntimeClientSurfaceUpstreamRequestTimeoutMs, + type RuntimeClientSurfaceProxyOptions, +} from '../src/dev/runtime-client-surface-proxy.ts'; const foregroundOrigin = 'http://127.0.0.1:41999'; const noopSubscribeReload = (): (() => void) => () => undefined; const reloadFrame = (generation: number): string => JSON.stringify({ generation, kind: 'runtime-app-reload' }); +/** + * Deadline tests bound the upstream far below the production default: long + * enough for the loopback bootstrap fetch that shares the bound, short enough + * that the file no longer waits on the real 15 s. + */ +const shortUpstreamRequestTimeout: RuntimeClientSurfaceProxyOptions = Object.freeze({ upstreamRequestTimeoutMs: 500 }); /** Provider-side reload authority stub: the trusted channel the proxy relays. */ const createReloadSource = () => { @@ -31,7 +41,8 @@ const RuntimeClientSurfaceProxy = Object.freeze({ open: ( input: DevRuntimeClientSurfaceEndpoint, listener: Parameters[1], - ) => RuntimeClientSurfaceProxyImplementation.open(input, listener, foregroundOrigin), + options?: RuntimeClientSurfaceProxyOptions, + ) => RuntimeClientSurfaceProxyImplementation.open(input, listener, foregroundOrigin, undefined, options), }); const listen = async (server: ReturnType): Promise => { @@ -573,6 +584,19 @@ it('rejects a custom-prototype child policy before opening a proxy binding', asy }, () => undefined, foregroundOrigin, policy as never)).rejects.toThrow('plain policy record'); }); +it('bounds upstream requests at 15 s by default and rejects out-of-range overrides before opening', async () => { + expect(defaultRuntimeClientSurfaceUpstreamRequestTimeoutMs).toBe(15_000); + for (const upstreamRequestTimeoutMs of [0, -1, 1.5, Number.NaN, Number.POSITIVE_INFINITY, 2_147_483_648]) { + await expect(RuntimeClientSurfaceProxy.open({ + entryPath: '/app/index.html', + httpOrigin: 'http://127.0.0.1:41998', + httpPathPrefixes: ['/app/'], + surfaceId: 'app.weather', + subscribeReload: noopSubscribeReload, + }, () => undefined, { upstreamRequestTimeoutMs })).rejects.toThrow('upstreamRequestTimeoutMs from 1 to'); + } +}); + it('does not reinstall the opaque child when a held refresh fetch resolves after pagehide', async () => { const upstream = createServer((request, response) => { if (serveBootstrapEntry(request, response)) return; @@ -1020,19 +1044,20 @@ it('bounds an upstream HTTP request before headers arrive', async () => { httpPathPrefixes: ['/app/'], surfaceId: 'app.weather', subscribeReload: noopSubscribeReload, - }, () => undefined); + }, () => undefined, shortUpstreamRequestTimeout); try { const cookie = await bootstrapCookie(binding); const pending = fetch(`${binding.origin}/app/index.html`, { headers: { cookie } }); void pending.catch(() => undefined); - await expect(within(pending, 16_000)).resolves.toMatchObject({ status: 502 }); + // Well under the 15 s default: a proxy that ignored the override would fail here. + await expect(within(pending, 2_000)).resolves.toMatchObject({ status: 502 }); } finally { await binding.close(); upstream.closeAllConnections(); await close(upstream); } -}, 20_000); +}); it('releases a reload-channel client that writes into the strictly one-way channel', async () => { const upstream = createServer((request, response) => { @@ -1162,7 +1187,7 @@ it('keeps a completed 502 response intact when a response body stalls after head httpPathPrefixes: ['/app/'], surfaceId: 'app.weather', subscribeReload: noopSubscribeReload, - }, () => undefined); + }, () => undefined, shortUpstreamRequestTimeout); try { const cookie = await bootstrapCookie(binding); @@ -1171,14 +1196,15 @@ it('keeps a completed 502 response intact when a response body stalls after head status: response.status, })); void pending.catch(() => undefined); - await expect(within(pending, 16_000)).resolves.toEqual({ body: 'Not Found', status: 502 }); + // Well under the 15 s default: a proxy that ignored the override would fail here. + await expect(within(pending, 2_000)).resolves.toEqual({ body: 'Not Found', status: 502 }); await expect(within(socketClosed, 250)).resolves.toBeUndefined(); } finally { await binding.close(); upstream.closeAllConnections(); await close(upstream); } -}, 20_000); +}); it('bounds chunked upstream assets and releases their socket immediately', async () => { let resolveSocketClosed: (() => void) | undefined; diff --git a/packages/create-agent-bundle/tests/scaffold-fixture.test.ts b/packages/create-agent-bundle/tests/scaffold-fixture.test.ts new file mode 100644 index 000000000..136bfd547 --- /dev/null +++ b/packages/create-agent-bundle/tests/scaffold-fixture.test.ts @@ -0,0 +1,89 @@ +import { mkdtemp, rm, writeFile } from 'node:fs/promises'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; + +import { afterAll, beforeAll, describe, expect, it } from '@rstest/core'; + +import { expectPassedPool } from './support/scaffold-fixture.ts'; + +/** + * `expectPassedPool` is the release matrix's verdict on a scaffolded pool, so + * its own fence is pinned here against a stub project whose npm scripts print + * a Rstest-shaped JSON report and exit as instructed. The scaffolded pools + * themselves run in scaffold-packed-matrix.e2e.test.ts. + */ +const poolScript = ` +const scenario = process.argv[2]; +const report = (tests) => JSON.stringify({ + files: [{ status: tests.some((test) => test.status === 'fail') ? 'fail' : 'pass' }], + status: tests.some((test) => test.status === 'fail') ? 'fail' : 'pass', + summary: { failedTests: tests.filter((test) => test.status === 'fail').length }, + tests, +}, null, 2); +console.log('Rstest v0.0.0'); +switch (scenario) { + case 'pass': + console.log(report([{ name: 'greets', status: 'pass' }])); + break; + case 'pass-exit-1': + console.log(report([{ name: 'greets', status: 'pass' }])); + process.exitCode = 1; + break; + case 'fail': + console.log(report([{ name: 'greets', status: 'fail' }])); + process.exitCode = 1; + break; + case 'no-report': + console.error('failed to load rstest.config.ts'); + process.exitCode = 2; + break; + default: + throw new Error('unknown scenario ' + String(scenario)); +} +`; + +describe('expectPassedPool', () => { + let projectRoot = ''; + + beforeAll(async () => { + projectRoot = await mkdtemp(join(tmpdir(), 'scaffold-fixture-pool-')); + await writeFile(join(projectRoot, 'pool.mjs'), poolScript); + await writeFile(join(projectRoot, 'package.json'), JSON.stringify({ + name: 'pool-fixture', + private: true, + scripts: { + 'pool:fail': 'node pool.mjs fail', + 'pool:no-report': 'node pool.mjs no-report', + 'pool:pass': 'node pool.mjs pass', + 'pool:pass-exit-1': 'node pool.mjs pass-exit-1', + }, + version: '0.0.0', + }, null, 2)); + }); + + afterAll(async () => { + await rm(projectRoot, { force: true, recursive: true }); + }); + + it('accepts a passing report whose script exited 0 and names the expected tests', async () => { + await expect(expectPassedPool(projectRoot, 'pool:pass', ['greets'])).resolves.toBeUndefined(); + }); + + it('rejects a passing report whose script exited non-zero', async () => { + await expect(expectPassedPool(projectRoot, 'pool:pass-exit-1', ['greets'])) + .rejects.toThrow(/`npm run pool:pass-exit-1` exited 1 although its report says pass/u); + }); + + it('rejects a passing report that does not name an expected test', async () => { + await expect(expectPassedPool(projectRoot, 'pool:pass', ['greets', 'lists'])).rejects.toThrow(/lists/u); + }); + + it('reports the failing test entry before the exit code', async () => { + await expect(expectPassedPool(projectRoot, 'pool:fail', ['greets'])).rejects.toThrow(/greets[\s\S]*to deeply equal \[\]/u); + }); + + it('rejects a script that wrote no report, quoting its exit and stderr', async () => { + await expect(expectPassedPool(projectRoot, 'pool:no-report', ['greets'])) + .rejects.toThrow(/wrote no Rstest JSON report \(exit 2\)[\s\S]*failed to load rstest\.config\.ts/u); + }); +}); diff --git a/packages/create-agent-bundle/tests/scaffold-packed-matrix.e2e.test.ts b/packages/create-agent-bundle/tests/scaffold-packed-matrix.e2e.test.ts index b425bd3c6..a9aea40e9 100644 --- a/packages/create-agent-bundle/tests/scaffold-packed-matrix.e2e.test.ts +++ b/packages/create-agent-bundle/tests/scaffold-packed-matrix.e2e.test.ts @@ -11,6 +11,7 @@ import { installedEnvironment, packOutputFromJson } from '../../agent-bundle/tes import { cleanupScaffoldFixture, expectCleanValidate, + expectPassedPool, installScaffoldedProject, npmRun, scaffoldProject, @@ -45,12 +46,10 @@ it.concurrent('scaffolds the mcp-server template and serves the conventional ent expect(checked).toContain('tests/projection/mcp-in-memory.test.ts'); // The route-unit pool renders through the framework's own generated setup, // resolved from the packed tarball's `agent-bundle/rstest` export. - const routes = await npmRun(projectRoot, 'test:routes'); - expect(routes).toContain('renders a known service into a final Agent Document'); - expect(routes).toContain('"failedTests": 0'); - const projection = await npmRun(projectRoot, 'test:projection'); - expect(projection).toContain('projects the rendered document into the protocol result the server returns'); - expect(projection).toContain('"failedTests": 0'); + await expectPassedPool(projectRoot, 'test:routes', ['renders a known service into a final Agent Document']); + await expectPassedPool(projectRoot, 'test:projection', [ + 'projects the rendered document into the protocol result the server returns', + ]); const artifact = join(projectRoot, 'artifact'); const manifest = JSON.parse(await readFile(join(artifact, 'portable', 'mcp.json'), 'utf8')) as { @@ -92,10 +91,10 @@ it.concurrent('scaffolds the cli-tool template with a routed bin, lib, and artif await npmRun(projectRoot, 'prepack'); // The projection pool dispatches through the framework's own generated // setup, resolved from the packed tarball's `agent-bundle/rstest` export. - const projection = await npmRun(projectRoot, 'test:projection'); - expect(projection).toContain('greets through the routed CLI shell and prints one canonical JSON line'); - expect(projection).toContain('greets through the main process envelope'); - expect(projection).toContain('"failedTests": 0'); + await expectPassedPool(projectRoot, 'test:projection', [ + 'greets through the routed CLI shell and prints one canonical JSON line', + 'greets through the main process envelope', + ]); // The src/cli/** convention produced the routed executable package bin: // generated help, the compiled argv grammar, and one canonical JSON line. diff --git a/packages/create-agent-bundle/tests/support/scaffold-fixture.ts b/packages/create-agent-bundle/tests/support/scaffold-fixture.ts index af0ef6fdd..7b0977706 100644 --- a/packages/create-agent-bundle/tests/support/scaffold-fixture.ts +++ b/packages/create-agent-bundle/tests/support/scaffold-fixture.ts @@ -146,6 +146,75 @@ export const npmRun = async (projectRoot: string, script: string): Promise => { + const run = await execFile('npm', ['run', script, '--', '--reporter=json'], { + cwd: projectRoot, + env: installedEnvironment(), + }).then( + (result) => ({ exit: 0, stderr: result.stderr, stdout: result.stdout }), + (error: unknown) => { + const failed = error as { readonly code?: number | string; readonly signal?: string; readonly stderr?: string; readonly stdout?: string }; + if (typeof failed.stdout !== 'string') throw error; + return { exit: failed.code ?? failed.signal ?? 'unknown', stderr: failed.stderr ?? '', stdout: failed.stdout }; + }, + ); + // npm's script banner and Rstest's own precede the report on stdout; the + // report is the only thing there that opens a line with `{`. + const start = run.stdout.search(/^\{$/mu); + if (start === -1) { + throw new Error(`\`npm run ${script}\` wrote no Rstest JSON report (exit ${String(run.exit)}):\n${run.stdout}${run.stderr}`); + } + return { exit: run.exit, report: JSON.parse(run.stdout.slice(start)) as PoolReport, stderr: run.stderr }; +}; + +/** + * The pool passed and ran the named tests. Failing entries come first — a + * test's, then a file's, for a file that failed before it had tests — because + * they carry the error where the counts would only say that something + * failed. The names catch a dropped or empty pool, which Rstest reports as + * `fail` with zero tests — and `failedTests: 0`. Last, the script itself must + * have exited 0: a report that says `pass` while npm exited non-zero (a + * lifecycle script, a crash after the report was written) is not a pass. + */ +export const expectPassedPool = async ( + projectRoot: string, + script: string, + testNames: readonly string[], +): Promise => { + const { exit, report, stderr } = await poolRun(projectRoot, script); + expect(report.tests.filter((test) => test.status === 'fail')).toEqual([]); + expect(report.files.filter((file) => file.status === 'fail')).toEqual([]); + expect(report.tests.map((test) => test.name)).toEqual(expect.arrayContaining([...testNames])); + expect(report).toMatchObject({ status: 'pass', summary: { failedTests: 0 } }); + if (exit !== 0) throw new Error(`\`npm run ${script}\` exited ${String(exit)} although its report says pass:\n${stderr}`); +}; + /** Zero diagnostics — including the informational AB473x migration nudges. */ export const expectCleanValidate = async (projectRoot: string): Promise => { const cli = join(projectRoot, 'node_modules', '.bin', 'agent-bundle'); diff --git a/packages/workbench/src/mcp/mcp-app-frame.tsx b/packages/workbench/src/mcp/mcp-app-frame.tsx index 7c84c2454..cc8186835 100644 --- a/packages/workbench/src/mcp/mcp-app-frame.tsx +++ b/packages/workbench/src/mcp/mcp-app-frame.tsx @@ -29,6 +29,8 @@ export interface McpAppFrameTarget { export interface McpAppFrameIframe { readonly contentWindow: McpAppFrameTarget | null; + /** A DOM iframe publishes the relay lifecycle through this (`relayStateAttribute`); fakes may omit it. */ + setAttribute?(name: string, value: string): void; } export interface McpAppFrameWindow { @@ -75,6 +77,18 @@ export interface SecureAppRendererProps { type RelayState = 'closed' | 'closing' | 'open'; +/** + * Relay lifecycle as published on the outer iframe's `data-mcp-app-relay-state` + * attribute, so the host UI and browser tests observe the state the relay is + * in instead of inferring it from route traffic. `loading`: listening, but the + * proxy has not signalled readiness, so `close()` releases the binding with a + * forced DELETE. `ready`: the proxy holds the resource, so `close()` runs the + * graceful `POST …/close` teardown handshake. `closing` and `closed` mirror + * `RelayState`. + */ +type RelayFrameState = 'closed' | 'closing' | 'loading' | 'ready'; +const relayStateAttribute = 'data-mcp-app-relay-state'; + interface CanonicalResource { readonly csp?: McpAppJsonValue; readonly html: string; @@ -193,6 +207,7 @@ export class McpAppFrameRelay { if (this.#state !== 'open' || this.#listening) return false; this.#window.addEventListener('message', this.#listener); this.#listening = true; + this.#publishFrameState(); return true; } @@ -209,6 +224,7 @@ export class McpAppFrameRelay { if (isProxyReady(message)) { if (this.#resourceProvided) return false; this.#resourceProvided = true; + this.#publishFrameState(); return this.#post(messageForResource(this.#frame, this.#resource), false); } if (!this.#resourceProvided) return false; @@ -219,6 +235,7 @@ export class McpAppFrameRelay { if (this.#state === 'closed') return closedRelay; if (this.#closePromise !== undefined) return this.#closePromise; this.#state = 'closing'; + this.#publishFrameState(); this.#closePromise = new Promise((resolve) => { this.#finishClose = resolve; }); // Before the proxy signals readiness there is no app to tear down and no // window that can acknowledge a teardown frame: the proxy document is @@ -361,6 +378,7 @@ export class McpAppFrameRelay { #completeClose(): void { if (this.#state === 'closed') return; this.#state = 'closed'; + this.#publishFrameState(); this.#queue.length = 0; if (this.#closeTimer !== undefined) clearTimeout(this.#closeTimer); this.#closeTimer = undefined; @@ -370,6 +388,12 @@ export class McpAppFrameRelay { this.#finishClose = undefined; } + /** Mirrors `#state` and `#resourceProvided` onto the iframe on the same event that changes them. */ + #publishFrameState(): void { + const state: RelayFrameState = this.#state === 'open' ? (this.#resourceProvided ? 'ready' : 'loading') : this.#state; + this.#iframe.setAttribute?.(relayStateAttribute, state); + } + #teardownId(): string { return `mcp-app-frame-close:${this.#bindingId}`; } diff --git a/packages/workbench/tests/mcp-app-frame.test.ts b/packages/workbench/tests/mcp-app-frame.test.ts index aa28a37c2..868782b5d 100644 --- a/packages/workbench/tests/mcp-app-frame.test.ts +++ b/packages/workbench/tests/mcp-app-frame.test.ts @@ -18,6 +18,7 @@ import { applyMcpAppFramePolicy, McpAppFrame, SecureAppRenderer, + type McpAppFrameIframe, type McpAppFrameMessageListener, type McpAppFrameRelayRoutes, type McpAppFrameWindow, @@ -365,6 +366,82 @@ describe('MCP App frame relay', () => { expect(messages).toHaveLength(1); }); + // The attribute is what mcp-app-real.e2e waits on before it closes a + // preview; each transition is published on the event that changes it. + const publishedRelayStates = (browser: ReturnType): Readonly<{ readonly iframe: McpAppFrameIframe; readonly states: readonly string[] }> => { + const states: string[] = []; + return Object.freeze({ + iframe: Object.freeze({ + contentWindow: browser.iframe.contentWindow, + setAttribute: (name: string, value: string) => { + expect(name).toBe('data-mcp-app-relay-state'); + states.push(value); + }, + }), + states, + }); + }; + + it('publishes loading, ready, closing, and closed on the iframe as the relay moves through a graceful close', async () => { + const browser = fakeBrowser(); + const published = publishedRelayStates(browser); + const closeCalls: { readonly id: string }[] = []; + const routes: McpAppFrameRelayRoutes = { + close: async (_bindingId, options) => { + closeCalls.push(options); + return closeResult({ id: options.id, jsonrpc: '2.0', method: 'ui/resource-teardown', params: {} }); + }, + forceClose: async () => true, + message: async () => messageResult([], 'closed'), + }; + const relay = createMcpAppFrameRelay({ bindingId: 'binding-weather', closeTimeoutMs: 100, frame, iframe: published.iframe, resource, routes, window: browser.window }); + expect(published.states).toEqual([]); + expect(relay.start()).toBe(true); + expect(published.states).toEqual(['loading']); + expect(relay.start()).toBe(false); + expect(published.states).toEqual(['loading']); + browser.emit({ data: proxyReady(), origin: frame.targetOrigin, source: browser.child }); + expect(published.states).toEqual(['loading', 'ready']); + browser.emit({ data: proxyReady(), origin: frame.targetOrigin, source: browser.child }); + expect(published.states).toEqual(['loading', 'ready']); + + const closing = relay.close(); + expect(published.states).toEqual(['loading', 'ready', 'closing']); + await eventually(() => closeCalls.length === 1); + expect(published.states).toEqual(['loading', 'ready', 'closing']); + browser.emit({ data: { id: closeCalls[0]!.id, jsonrpc: '2.0', result: {} }, origin: frame.targetOrigin, source: browser.child }); + await closing; + expect(published.states).toEqual(['loading', 'ready', 'closing', 'closed']); + await relay.close(); + expect(published.states).toEqual(['loading', 'ready', 'closing', 'closed']); + }); + + it('publishes closing and closed, never ready, around the forced DELETE of a proxy that never signaled readiness', async () => { + const browser = fakeBrowser(); + const published = publishedRelayStates(browser); + let closeCalls = 0; + let forceCloseCalls = 0; + const routes: McpAppFrameRelayRoutes = { + close: async () => { + closeCalls += 1; + return closeResult(); + }, + forceClose: async () => { + forceCloseCalls += 1; + return true; + }, + message: async () => messageResult(), + }; + const relay = createMcpAppFrameRelay({ bindingId: 'binding-weather', closeTimeoutMs: 30_000, frame, iframe: published.iframe, resource, routes, window: browser.window }); + relay.start(); + const closing = relay.close(); + expect(published.states).toEqual(['loading', 'closing']); + await closing; + expect(published.states).toEqual(['loading', 'closing', 'closed']); + expect(closeCalls).toBe(0); + expect(forceCloseCalls).toBe(1); + }); + it('force-deletes a closing binding when the ready proxy never acknowledges the teardown frame', async () => { const browser = fakeBrowser(); let closeCalls = 0; diff --git a/packages/workbench/tests/mcp-app-real.e2e.test.ts b/packages/workbench/tests/mcp-app-real.e2e.test.ts index 1005056d1..5adf93c13 100644 --- a/packages/workbench/tests/mcp-app-real.e2e.test.ts +++ b/packages/workbench/tests/mcp-app-real.e2e.test.ts @@ -165,6 +165,7 @@ const writeBundledAppProject = async (root: string): Promise => { interface AppRouteRequest { readonly body: unknown; + readonly method: string; readonly path: string; } @@ -174,7 +175,6 @@ interface AppRouteResponse extends AppRouteRequest { interface RuntimeAppRouteRequest extends AppRouteRequest { readonly headers: Readonly>; - readonly method: string; } interface RuntimeAppRouteResponse extends RuntimeAppRouteRequest { @@ -233,7 +233,7 @@ e2e('runs a generated SDK-v2 App through the real foreground session and separat page.on('request', (request) => { const requestUrl = new URL(request.url()); if (requestUrl.origin !== foregroundOrigin || !requestUrl.pathname.startsWith('/api/mcp/apps/')) return; - appRequests.push({ body: requestBody(request.postData()), path: requestUrl.pathname }); + appRequests.push({ body: requestBody(request.postData()), method: request.method(), path: requestUrl.pathname }); }); page.on('response', (response) => { const responseUrl = new URL(response.url()); @@ -244,7 +244,7 @@ e2e('runs a generated SDK-v2 App through the real foreground session and separat const responseUrl = new URL(response.url()); if (responseUrl.origin !== foregroundOrigin || !responseUrl.pathname.endsWith('/messages')) return; void response.json().then((body) => { - appResponses.push({ body: requestBody(response.request().postData()), path: responseUrl.pathname, response: body }); + appResponses.push({ body: requestBody(response.request().postData()), method: response.request().method(), path: responseUrl.pathname, response: body }); }).catch(() => undefined); }); @@ -432,22 +432,53 @@ e2e('runs a generated SDK-v2 App through the real foreground session and separat await expect(historyEntries).toHaveCount(2, { timeout: browserTimeout }); await expect(page.locator('.mcp-page-phase')).toContainText('Session ready', { timeout: browserTimeout }); + const reopenedPreview = page.waitForResponse((response) => + response.url() === `${foregroundOrigin}/api/mcp/sessions/${openedSession.session.id}/apps` && response.request().method() === 'POST', { timeout: browserTimeout }); await page.getByRole('button', { name: 'Open App preview for mcp-page-1' }).click(); + const reopened = await (await reopenedPreview).json() as Readonly<{ readonly preview: Readonly<{ readonly bindingId: string }> }>; + const reopenedAppPath = `/api/mcp/apps/${encodeURIComponent(reopened.preview.bindingId)}`; await expect(outerFrame).toBeVisible({ timeout: browserTimeout }); - // A visible iframe only proves the element mounted. The graceful /close - // handshake below needs a proxy that has loaded and an app that has - // initialized (a preview closed before its proxy signals readiness is - // released by DELETE, with nothing to acknowledge a teardown), so wait for - // the reopened binding's own `initialized` notification first. - await expect.poll(() => appRequests.filter((request) => { + // A visible iframe only proves the element mounted. The relay sends the + // graceful POST …/close only once it has seen the proxy's ready + // notification; before that, close() releases the binding with a forced + // DELETE and nothing can acknowledge a teardown. McpAppFrameRelay publishes + // that state on the iframe, so wait on it directly, then on the reopened + // App's own `initialized` so the teardown below is acknowledged instead of + // riding out the force-close timer. + await expect(outerFrame).toHaveAttribute('data-mcp-app-relay-state', 'ready', { timeout: browserTimeout }); + await expect.poll(() => appRequests.some((request) => { const message = (request.body as { readonly message?: { readonly method?: string } } | undefined)?.message; - return request.path.endsWith('/messages') && message?.method === 'ui/notifications/initialized'; - }).length, { timeout: browserTimeout }).toBe(2); - const secondClose = page.waitForRequest((request) => request.url().startsWith(`${foregroundOrigin}/api/mcp/apps/`) && request.url().endsWith('/close'), { timeout: 30_000 * timeScale }); + return request.path === `${reopenedAppPath}/messages` && message?.method === 'ui/notifications/initialized'; + }), { message: 'The reopened App preview never sent ui/notifications/initialized.', timeout: browserTimeout }).toBe(true); const closedSession = page.waitForRequest((request) => - request.url() === `${foregroundOrigin}/api/mcp/sessions/${openedSession.session.id}` && request.method() === 'DELETE', { timeout: 30_000 * timeScale }); - await page.getByRole('button', { name: 'Close MCP session' }).click(); - await secondClose; + request.url() === `${foregroundOrigin}/api/mcp/sessions/${openedSession.session.id}` && request.method() === 'DELETE', { timeout: browserTimeout }); + // The session controls sit ~2000 px above the reopened App's cross-origin + // iframe. Letting click() scroll that far and dispatch in the same breath + // lets Chromium route the pointer to the frame that used to occupy the + // point (its hit-test regions update asynchronously), so the click is + // swallowed under load. Settle the scroll first, then confirm the click + // landed: run('close') disables the button synchronously and it stays + // disabled through the terminal phase. + const closeSession = page.getByRole('button', { name: 'Close MCP session' }); + await closeSession.scrollIntoViewIfNeeded(); + await expect(closeSession).toBeInViewport({ timeout: browserTimeout }); + await closeSession.click(); + await expect(closeSession, 'The Close MCP session click did not start the close action.').toBeDisabled({ timeout: browserTimeout }); + // The first route call the close makes for this binding decides its path. + // Observing the DELETE too makes a force-close fail here, in milliseconds, + // instead of waiting out a /close that will never be sent. + const reopenedClose = () => appRequests.find((request) => + (request.method === 'POST' && request.path === `${reopenedAppPath}/close`) || (request.method === 'DELETE' && request.path === reopenedAppPath)); + await expect.poll(reopenedClose, { message: 'Closing the session sent no close request for the reopened App preview.', timeout: browserTimeout }).toBeDefined(); + const secondClose = reopenedClose(); + if (secondClose?.method !== 'POST') { + throw new Error(`Expected the reopened App preview to close gracefully (POST ${reopenedAppPath}/close); the relay sent ${secondClose === undefined ? 'no close request' : `${secondClose.method} ${secondClose.path}`} instead.`); + } + const secondCloseBody = secondClose.body as Readonly<{ readonly id: string }>; + await expect.poll(() => appRequests.some((request) => { + const message = (request.body as { readonly message?: { readonly id?: string; readonly result?: unknown } } | undefined)?.message; + return request.path === `${reopenedAppPath}/messages` && message?.id === secondCloseBody.id && message.result !== undefined; + }), { message: 'The reopened App preview never acknowledged the graceful teardown.', timeout: browserTimeout }).toBe(true); await closedSession; await expect(page.locator('.mcp-page-phase')).toContainText('Session closed', { timeout: browserTimeout }); await expect(outerFrame).toBeHidden({ timeout: browserTimeout }); diff --git a/packages/workbench/tests/packed-outage-ledger.test.ts b/packages/workbench/tests/packed-outage-ledger.test.ts index e3cdc1976..eee242364 100644 --- a/packages/workbench/tests/packed-outage-ledger.test.ts +++ b/packages/workbench/tests/packed-outage-ledger.test.ts @@ -13,7 +13,8 @@ import { test('outage ledger rejects the legacy duplicate, cross-origin, and missing-cleanup false positives', () => { const valid = outageLedgerFixture(); - const oldStreamPath = `/api/mcp/sessions/${encodeURIComponent(valid.oldSessionId)}/stream`; + const oldSessionPath = `/api/mcp/sessions/${encodeURIComponent(valid.oldSessionId)}`; + const oldStreamPath = `${oldSessionPath}/stream`; const resetRequest = ledgerRequest({ at: 999, completedAt: 1_008, @@ -106,19 +107,77 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ...valid.requests, ]), }); - const resetSessionProbe = Object.freeze({ + // The fixture's single failed project/session probe, and the console error + // it logged, failing with `code` instead of REFUSED. + const withSessionProbeCode = (code: string): OutageLedger => Object.freeze({ ...valid, consoleErrors: Object.freeze(valid.consoleErrors.map((consoleError) => consoleError.url === `${valid.origin}/api/project/session` - ? Object.freeze({ ...consoleError, text: 'Failed to load resource: net::ERR_CONNECTION_RESET' }) + ? Object.freeze({ ...consoleError, text: `Failed to load resource: ${code}` }) : consoleError, )), requests: Object.freeze(valid.requests.map((request) => request.path === '/api/project/session' && request.error !== undefined - ? ledgerRequest({ ...request, error: 'net::ERR_CONNECTION_RESET' }) + ? ledgerRequest({ ...request, error: code }) : request, )), }); + const resetSessionProbe = withSessionProbeCode('net::ERR_CONNECTION_RESET'); + const socketNotConnectedSessionProbe = withSessionProbeCode('net::ERR_SOCKET_NOT_CONNECTED'); + // SOCKET_NOT_CONNECTED is a dying-server probe failure and nothing else: the + // old-session DELETE, a non-GET on the probe path, a probe that carries + // response headers, and a probe outside the outage window all stay rejected + // with their existing messages. + const socketNotConnectedDelete = Object.freeze({ + ...valid, + consoleErrors: Object.freeze(valid.consoleErrors.map((consoleError) => + consoleError.url === `${valid.origin}${oldSessionPath}` + ? Object.freeze({ ...consoleError, text: 'Failed to load resource: net::ERR_SOCKET_NOT_CONNECTED' }) + : consoleError, + )), + requests: Object.freeze(valid.requests.map((request) => + request.method === 'DELETE' ? ledgerRequest({ ...request, error: 'net::ERR_SOCKET_NOT_CONNECTED' }) : request, + )), + }); + const socketNotConnectedSessionPost = Object.freeze({ + ...valid, + consoleErrors: Object.freeze([ + ...valid.consoleErrors, + Object.freeze({ at: 1_022, text: 'Failed to load resource: net::ERR_SOCKET_NOT_CONNECTED', url: `${valid.origin}/api/project/session` }), + ]), + requests: Object.freeze([ + ...valid.requests, + ledgerRequest({ at: 1_020, completedAt: 1_021, error: 'net::ERR_SOCKET_NOT_CONNECTED', method: 'POST', path: '/api/project/session' }), + ]), + }); + const socketNotConnectedRespondedProbe = Object.freeze({ + ...socketNotConnectedSessionProbe, + requests: Object.freeze(socketNotConnectedSessionProbe.requests.map((request) => + request.error === 'net::ERR_SOCKET_NOT_CONNECTED' ? ledgerRequest({ ...request, respondedAt: request.at, status: 503 }) : request, + )), + }); + const socketNotConnectedPreOutageProbe = Object.freeze({ + ...valid, + consoleErrors: Object.freeze([ + Object.freeze({ at: 992, text: 'Failed to load resource: net::ERR_SOCKET_NOT_CONNECTED', url: `${valid.origin}/api/project/session` }), + ...valid.consoleErrors, + ]), + requests: Object.freeze([ + ledgerRequest({ at: 990, completedAt: 991, error: 'net::ERR_SOCKET_NOT_CONNECTED', method: 'GET', path: '/api/project/session' }), + ...valid.requests, + ]), + }); + // The code on the console error alone, or on the probe alone, pairs with + // nothing: a console error still needs its own request failure and a + // request failure its own console error. + const socketNotConnectedConsoleWithoutFailure = Object.freeze({ + ...valid, + consoleErrors: socketNotConnectedSessionProbe.consoleErrors, + }); + const socketNotConnectedProbeWithoutConsole = Object.freeze({ + ...socketNotConnectedSessionProbe, + consoleErrors: Object.freeze(valid.consoleErrors.filter((consoleError) => consoleError.url !== `${valid.origin}/api/project/session`)), + }); const knownPreOutageCatalogCancellation = Object.freeze({ ...valid, requests: Object.freeze([ @@ -157,6 +216,29 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ...valid.requests, ]), }); + // Leaving the Logs page before the replay answered: Chromium reports the + // abort with neither a status nor a response instant. + const knownPreOutageLogsReplayPreHeaderCancellation = Object.freeze({ + ...valid, + requests: Object.freeze([ + ledgerRequest({ at: 900, completedAt: 901, error: 'net::ERR_ABORTED', method: 'GET', path: '/api/logs/replay' }), + ...valid.requests, + ]), + }); + const logsReplayCancellationWithoutTerminal = Object.freeze({ + ...valid, + requests: Object.freeze([ + ledgerRequest({ at: 900, error: 'net::ERR_ABORTED', method: 'GET', path: '/api/logs/replay' }), + ...valid.requests, + ]), + }); + const logsReplayCancellationAfterFailure = Object.freeze({ + ...valid, + requests: Object.freeze([ + ledgerRequest({ at: 900, completedAt: 901, error: 'net::ERR_ABORTED', method: 'GET', path: '/api/logs/replay', respondedAt: 900, status: 500 }), + ...valid.requests, + ]), + }); const preStartedOutageStreamTermination = Object.freeze({ ...valid, requests: Object.freeze(valid.requests.map((request) => @@ -179,6 +261,8 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ledgerRequest({ at: 1_350, completedAt: 1_351, error: 'net::ERR_ABORTED', method: 'GET', path: '/api/unknown/stream' }), ]), }); + // Index of a request appended after the post-recovery fixture's own entries. + const appendedIndex = validPostRecovery.requests.length; const navigationLiveStreamCancellation = Object.freeze({ ...validPostRecovery, postRecovery: Object.freeze({ @@ -187,7 +271,8 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ...validPostRecovery.postRecovery!.navigation, Object.freeze({ leftAt: 1_350, - openedAt: 1_345, + leftIndex: appendedIndex + 1, + openedIndex: appendedIndex, respondedStream: true as const, url: `${valid.origin}/api/logs/stream?after=32`, }), @@ -209,7 +294,8 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ...validPostRecovery.postRecovery!.navigation, Object.freeze({ leftAt: 1_350, - openedAt: 1_345, + leftIndex: appendedIndex + 1, + openedIndex: appendedIndex, url: `${valid.origin}/api/playground/catalog?epochId=recovered-epoch`, }), ]), @@ -229,6 +315,43 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea ledgerRequest({ at: 1_335, completedAt: 1_336, error: 'net::ERR_ABORTED', method: 'POST', path: '/api/playground/runs' }), ]), }); + // A fresh-B stream abort delivered before the test clicked Close is not the + // close's doing, however close to the click it lands. + const preCloseFreshStreamCancellation = Object.freeze({ + ...validPostRecovery, + requests: Object.freeze(validPostRecovery.requests.map((request) => + request.path.startsWith('/api/mcp/sessions/fresh-browser-mcp-session/') ? ledgerRequest({ ...request, completedAt: 1_319 }) : request, + )), + }); + // The other edge: the page aborts both streams before it issues the DELETE, + // so an abort that completes after the DELETE completed was not the close's. + const postCloseFreshStreamCancellation = Object.freeze({ + ...validPostRecovery, + requests: Object.freeze(validPostRecovery.requests.map((request) => + request.path.startsWith('/api/mcp/sessions/fresh-browser-mcp-session/') ? ledgerRequest({ ...request, completedAt: 1_322 }) : request, + )), + }); + const hooksNavigation = validPostRecovery.postRecovery!.navigation[0]!; + const hooksRequest = validPostRecovery.requests.at(-1)!; + // The CI shape: the Hooks request and its response arrived in one batch and + // the awaiting test stamped its departure in the same millisecond. Delivery + // order still places the request before the stamp, so the visit owns it. + const sameMillisecondDepartedRequest = Object.freeze({ + ...validPostRecovery, + requests: Object.freeze([ + ...validPostRecovery.requests.slice(0, -1), + ledgerRequest({ ...hooksRequest, at: hooksNavigation.leftAt }), + ]), + }); + // The mirror image: a request handed over after the departure stamp is the + // next page's, however it is timestamped, and its abort stays unexplained. + const sameMillisecondNextPageRequest = Object.freeze({ + ...validPostRecovery, + requests: Object.freeze([ + ...validPostRecovery.requests, + ledgerRequest({ ...hooksRequest, at: hooksNavigation.leftAt, completedAt: hooksNavigation.leftAt + 1 }), + ]), + }); const navigationCancellationBeforeDeparture = Object.freeze({ ...validPostRecovery, postRecovery: Object.freeze({ @@ -238,6 +361,42 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea )), }), }); + // Replaces the fixture's single project/session probe with `probeAts` failed + // probes (each paired with its console error) and a success at `successAt`. + // A probe is refused unless `codes` names its failure at the same index. + const withRetryProbes = (probeAts: readonly number[], successAt: number, codes: readonly string[] = []): OutageLedger => Object.freeze({ + ...valid, + consoleErrors: Object.freeze([ + ...valid.consoleErrors.filter((consoleError) => consoleError.url !== `${valid.origin}/api/project/session`), + ...probeAts.map((at, index) => Object.freeze({ + at: at + 2, text: `Failed to load resource: ${codes[index] ?? 'net::ERR_CONNECTION_REFUSED'}`, url: `${valid.origin}/api/project/session`, + })), + ]), + recoveredAt: successAt + 1, + requests: Object.freeze([ + ...valid.requests.filter((request) => request.path !== '/api/project/session'), + ...probeAts.map((at, index) => ledgerRequest({ + at, completedAt: at + 1, error: codes[index] ?? 'net::ERR_CONNECTION_REFUSED', method: 'GET', path: '/api/project/session', + })), + ledgerRequest({ at: successAt, completedAt: successAt + 1, method: 'GET', path: '/api/project/session', status: 200 }), + ]), + }); + // The CI shape (Release gates, runs 33933481002 and 33936651225): the first + // probe of the outage went out over a keep-alive connection the closing + // server had already shut and failed with SOCKET_NOT_CONNECTED; every later + // probe found the port closed, and recovery answered 200. + const socketNotConnectedFirstRetry = withRetryProbes([1_010, 1_266, 1_518], 1_770, ['net::ERR_SOCKET_NOT_CONNECTED']); + // One probe's `request` event delivered 34 ms late: the gap before it reads + // 284 ms and the gap after it 222 ms, while the page kept its 250 ms delay. + const lateDeliveredRetry = withRetryProbes([1_010, 1_260, 1_544, 1_766], 2_016); + // The first probe's event delivered 100 ms late shortens only the first gap. + const lateDeliveredFirstRetry = withRetryProbes([1_110, 1_260], 1_510); + const burstRetry = withRetryProbes([1_010, 1_013], 1_263); + const underpacedRetries = withRetryProbes([1_010, 1_160, 1_310], 1_460); + // Two short gaps then a long one: lateness cannot be borrowed from a gap that + // has not happened yet, so the second short gap is rejected even though the + // three gaps average well above the client's delay. + const borrowedRetryLateness = withRetryProbes([1_010, 1_135, 1_260], 1_735); const malformedLedgers = [duplicateConsole, crossOriginConsole, missingCleanup]; expect(malformedLedgers.map(legacyOutageLedgerPasses)).toEqual([true, true, true]); @@ -245,14 +404,34 @@ test('outage ledger rejects the legacy duplicate, cross-origin, and missing-clea expect(() => validateOutageLedger(validOldStreamReset)).not.toThrow(); expect(() => validateOutageLedger(validOldStreamSocketNotConnected)).not.toThrow(); expect(() => validateOutageLedger(resetSessionProbe)).not.toThrow(); + expect(() => validateOutageLedger(socketNotConnectedSessionProbe)).not.toThrow(); + expect(() => validateOutageLedger(socketNotConnectedFirstRetry)).not.toThrow(); + expect(() => validateOutageLedger(socketNotConnectedDelete)).toThrow(/old-session DELETE must succeed or fail exactly with ERR_CONNECTION_REFUSED/u); + expect(() => validateOutageLedger(socketNotConnectedSessionPost)).toThrow(/unknown outage failure/u); + expect(() => validateOutageLedger(socketNotConnectedRespondedProbe)).toThrow(/project\/session retry is missing or has multiple terminal states/u); + expect(() => validateOutageLedger(socketNotConnectedPreOutageProbe)).toThrow(/unexpected pre-outage failures/u); + expect(() => validateOutageLedger(socketNotConnectedConsoleWithoutFailure)).toThrow(/console error does not uniquely pair with an outage request failure/u); + expect(() => validateOutageLedger(socketNotConnectedProbeWithoutConsole)).toThrow(/outage request failures lack a unique paired console error/u); expect(() => validateOutageLedger(preStartedOutageStreamTermination)).not.toThrow(); expect(() => validateOutageLedger(knownPreOutageCatalogCancellation)).not.toThrow(); expect(() => validateOutageLedger(knownPreOutageSessionReplayCancellation)).not.toThrow(); expect(() => validateOutageLedger(knownPreOutageSessionReadCancellation)).not.toThrow(); expect(() => validateOutageLedger(knownPreOutageLogsReplayCancellation)).not.toThrow(); + expect(() => validateOutageLedger(knownPreOutageLogsReplayPreHeaderCancellation)).not.toThrow(); + expect(() => validateOutageLedger(logsReplayCancellationWithoutTerminal)).toThrow(/unexpected pre-outage failures/u); + expect(() => validateOutageLedger(logsReplayCancellationAfterFailure)).toThrow(/unexpected pre-outage failures/u); + expect(() => validateOutageLedger(preCloseFreshStreamCancellation)).toThrow(/fresh B MCP stream cancellation is not action-induced/u); + expect(() => validateOutageLedger(postCloseFreshStreamCancellation)).toThrow(/fresh B MCP stream cancellation is not action-induced/u); expect(() => validateOutageLedger(validPostRecovery)).not.toThrow(); expect(() => validateOutageLedger(navigationLiveStreamCancellation)).not.toThrow(); expect(() => validateOutageLedger(navigationRespondedCatalogCancellation)).not.toThrow(); + expect(() => validateOutageLedger(sameMillisecondDepartedRequest)).not.toThrow(); + expect(() => validateOutageLedger(sameMillisecondNextPageRequest)).toThrow(/unknown post-recovery failure/u); + expect(() => validateOutageLedger(lateDeliveredRetry)).not.toThrow(); + expect(() => validateOutageLedger(lateDeliveredFirstRetry)).not.toThrow(); + expect(() => validateOutageLedger(burstRetry)).toThrow(/project\/session retries began too quickly \(attempt 2 arrived 122 ms before/u); + expect(() => validateOutageLedger(underpacedRetries)).toThrow(/project\/session retries began too quickly \(attempt 3 arrived 75 ms before/u); + expect(() => validateOutageLedger(borrowedRetryLateness)).toThrow(/project\/session retries began too quickly \(attempt 3 arrived 125 ms before/u); for (const malformed of malformedLedgers) expect(() => validateOutageLedger(malformed)).toThrow(/Foreground outage ledger rejected/u); for (const malformed of [ resetWithAlteredQuery, resetWithResponse, resetWithUnknownSession, resetWithForeignOrigin, resetWithMismatchedConsoleUrl, diff --git a/packages/workbench/tests/packed-release.e2e.test.ts b/packages/workbench/tests/packed-release.e2e.test.ts index 79a827bb9..fcae978d8 100644 --- a/packages/workbench/tests/packed-release.e2e.test.ts +++ b/packages/workbench/tests/packed-release.e2e.test.ts @@ -399,9 +399,16 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * await expect(appFrame.locator('#view')).toHaveText('packed release dashboard', { timeout: browserTimeout }); phase = 'Logs, Evals, and Comparisons pages'; + // The heading renders before the page's mount replay is answered; leaving + // on the heading alone cancels that replay mid-flight on a loaded server. + // The visit is complete once the replay has responded. + const logsReplayListing = page.waitForResponse((response) => new URL(response.url()).pathname === '/api/logs/replay'); await page.goto(workbenchUrl(origin, 'logs')); phase = 'Logs page heading'; await expect(page.getByRole('heading', { name: 'Logs' })).toBeVisible({ timeout: browserTimeout }); + phase = 'Logs page replay'; + const logsReplayListingResponse = await logsReplayListing; + if (!logsReplayListingResponse.ok()) throw new Error(`The Logs page replay route failed with ${logsReplayListingResponse.status()}: ${await logsReplayListingResponse.text()}`); const initialEvalsRequestIndex = browserRequests.length; await page.goto(workbenchUrl(origin, 'evals')); phase = 'Evals page heading'; @@ -879,6 +886,7 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * await expect(page.locator('.eval-raw-result')).toContainText('The deterministic packed fixture passed.', { timeout: browserTimeout }); await waitForBrowserRequestsAfter(evalsBrowserRequestIndex); phase = 'Evals comparison run availability'; + const comparisonsOpenedIndex = browserRequests.length; await page.getByRole('link', { name: 'Comparisons', exact: true }).click(); await expect(page.getByRole('heading', { name: 'Comparisons' })).toBeVisible({ timeout: browserTimeout }); await expect.poll(async () => page.locator('#comparison-base option').count(), { timeout: browserTimeout }).toBeGreaterThanOrEqual(2); @@ -923,6 +931,19 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * const rebuiltWithRecoveredSession = page.waitForResponse((response) => response.url() === `${origin}/api/project/rebuild` && response.request().method() === 'POST' && response.ok(), ); + // The recovered session hands the Comparisons page new clients, and its + // effect re-lists /api/evals/runs; leaving for Overview before a loaded + // server answers aborts that listing, which the ledger must be able to + // attribute to this departure like every later one. A visit owns the + // requests recorded between its arrival and departure stamps — delivery + // order, which a millisecond cannot establish (see the ledger). + const postRecoveryNavigation: Array> = [Object.freeze({ leftAt: Date.now(), leftIndex: browserRequests.length, openedIndex: comparisonsOpenedIndex, url: `${origin}/api/evals/runs` })]; await page.getByRole('link', { name: 'Overview', exact: true }).click(); await page.getByRole('button', { name: 'Rebuild' }).click(); const rebuiltWithRecoveredSessionResponse = await rebuiltWithRecoveredSession; @@ -967,12 +988,24 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * response.url() === `${origin}/api/mcp/sessions/${encodeURIComponent(browserMcpSessionBId)}` && response.request().method() === 'DELETE' && response.ok(), ); + // The close window opens on a stamp taken before the click — the click + // is issued from here, so nothing it causes can reach the ledger earlier + // — and closes on the DELETE's own completion entry: the page aborts both + // session streams before it issues that DELETE, so the close-induced + // aborts are delivered inside the window however late Playwright hands + // them over, while an abort before the click stays outside it. Completion + // events trail their responses, so the DELETE entry is awaited. const browserMcpSessionBCloseStartedAt = Date.now(); await page.getByRole('button', { name: 'Close MCP session' }).click(); const closedBrowserMcpSessionBResponse = await closedBrowserMcpSessionB; expect(closedBrowserMcpSessionBResponse.request().headers()['x-agent-bundle-session']).toBe(browserGenerationBToken); await expect(page.locator('.mcp-page-phase')).toContainText('Session closed', { timeout: browserTimeout }); - const browserMcpSessionBCloseCompletedAt = Date.now(); + const browserMcpSessionBCloseRequest = browserRequestByPlaywrightRequest.get(closedBrowserMcpSessionBResponse.request()); + if (browserMcpSessionBCloseRequest === undefined) throw new Error('The fresh B browser MCP session close was not recorded in the network ledger.'); + await expect.poll(() => browserMcpSessionBCloseRequest.completedAt, { timeout: browserTimeout }).toBeDefined(); + const browserMcpSessionBCloseCompletedAt = browserMcpSessionBCloseRequest.completedAt; + // Narrowing only: the poll above settled the entry. + if (browserMcpSessionBCloseCompletedAt === undefined) throw new Error('The fresh B browser MCP close window is missing its completed DELETE entry.'); phase = 'desktop navigation floor'; const navigationFloorRequestIndex = browserRequests.length; @@ -981,7 +1014,12 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * { heading: 'MCP playground', label: 'MCP playground' }, { heading: 'Artifacts', label: 'Artifacts' }, { heading: 'Playground', label: 'Playground' }, { heading: 'Logs', label: 'Logs' }, { heading: 'Evals', label: 'Evals' }, { heading: 'Comparisons', label: 'Comparisons' }, ]; + // Every abortable request a route issues on mount, so leaving the route + // before a loaded server answers is claimed by the route's record rather + // than reported as an unknown post-recovery failure. const postRecoveryNavigationUrls = new Map([ + // Skills lists the authored suites for its eval-coverage column. + ['Skills', [`${origin}/api/evals/suites`]], ['Hooks', [`${origin}/api/hooks?epochId=${encodeURIComponent(recoveredEpochId)}`]], ['MCP playground', [`${origin}/api/artifacts/epochs/${encodeURIComponent(recoveredEpochId)}`]], ['Playground', [`${origin}/api/playground/catalog?epochId=${encodeURIComponent(recoveredEpochId)}`]], @@ -990,26 +1028,28 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * ['Comparisons', [`${origin}/api/evals/runs`]], ]); const respondedNavigationStreams = new Set(); - const postRecoveryNavigation: Array> = []; - let activeNavigationRoute: Readonly<{ openedAt: number; urls?: readonly string[] }> | undefined; - const leaveActiveNavigationRoute = (leftAt: number): void => { + let activeNavigationRoute: Readonly<{ openedIndex: number; urls?: readonly string[] }> | undefined; + // A departure is a test action with no wire event of its own, so it is + // stamped twice before the click: the instant, which the abort it + // provokes must not precede, and the ledger length, which orders the + // requests already handed over (the departed page's) against those that + // follow (the next page's) even when both share the instant's millisecond. + const leaveActiveNavigationRoute = (): void => { if (activeNavigationRoute === undefined) return; + const leftAt = Date.now(); + const leftIndex = browserRequests.length; for (const url of activeNavigationRoute.urls ?? []) postRecoveryNavigation.push(Object.freeze({ leftAt, - openedAt: activeNavigationRoute.openedAt, + leftIndex, + openedIndex: activeNavigationRoute.openedIndex, ...(respondedNavigationStreams.has(url) ? { respondedStream: true as const } : {}), url, })); activeNavigationRoute = undefined; }; for (const route of navigationRoutes) { - const openedAt = Date.now(); - leaveActiveNavigationRoute(openedAt); + leaveActiveNavigationRoute(); + const openedIndex = browserRequests.length; const logsStreamResponse = route.label === 'Logs' ? page.waitForResponse((response) => { const url = new URL(response.url()); @@ -1029,15 +1069,15 @@ e2e('runs every Agent API tool from the installed tarball', { timeout: 360_000 * const streamUrl = response.url(); const stream = browserRequestByPlaywrightRequest.get(response.request()); if ( - stream === undefined || stream.at < openedAt || stream.respondedAt === undefined || + stream === undefined || browserRequests.indexOf(stream) < openedIndex || stream.respondedAt === undefined || stream.status !== response.status() ) throw new Error('The Logs navigation stream response was not recorded in the network ledger.'); respondedNavigationStreams.add(streamUrl); routeUrls.push(streamUrl); } - activeNavigationRoute = Object.freeze({ openedAt, urls: Object.freeze(routeUrls) }); + activeNavigationRoute = Object.freeze({ openedIndex, urls: Object.freeze(routeUrls) }); } - leaveActiveNavigationRoute(Date.now()); + leaveActiveNavigationRoute(); await page.getByRole('link', { name: 'Overview', exact: true }).focus(); await page.keyboard.press('Enter'); await expect(page.getByRole('heading', { name: 'Bundle dashboard' })).toBeVisible({ timeout: browserTimeout }); diff --git a/packages/workbench/tests/support/packed-outage-ledger.ts b/packages/workbench/tests/support/packed-outage-ledger.ts index 05fef215f..601707c8f 100644 --- a/packages/workbench/tests/support/packed-outage-ledger.ts +++ b/packages/workbench/tests/support/packed-outage-ledger.ts @@ -22,11 +22,32 @@ export interface OutageLedger { readonly origin: string; readonly outageStartedAt: number; readonly postRecovery?: Readonly<{ + /** + * The B-generation browser MCP session: `openedAt` is the + * `POST /api/mcp/sessions` request instant, and the close window + * `[closeStartedAt, closeCompletedAt]` spans from the stamp the test took + * before clicking Close (the click is issued from the test, so nothing it + * causes can be delivered earlier) to the completion of the session's + * `DELETE` wire entry. The page aborts both of its session streams before + * it issues that `DELETE`, so every close-induced stream abort lands inside + * the window while a pre-click or post-close abort does not. + */ readonly freshMcpSession: Readonly<{ readonly closeCompletedAt: number; readonly closeStartedAt: number; readonly id: string; readonly openedAt: number }>; - /** Exact page-owned requests cancelled when the test deliberately navigated away. */ + /** + * Exact page-owned requests cancelled when the test deliberately navigated + * away. Membership is by delivery order, not by clock: `requests` grows in + * the order Playwright hands events over, and `openedIndex`/`leftIndex` + * are its length when the test stamped the arrival and the departure, so + * a request belongs to the visit when it sits in `[openedIndex, leftIndex)`. + * A millisecond cannot order a request against a departure — a batch of + * events and the stamp that follows it share one — but the array can. The + * abort itself must complete no earlier than `leftAt`: an abort that + * finished before the departure was not the departure's doing. + */ readonly navigation: readonly Readonly<{ readonly leftAt: number; - readonly openedAt: number; + readonly leftIndex: number; + readonly openedIndex: number; readonly respondedStream?: true; readonly url: string; }>[]; @@ -76,8 +97,9 @@ export const postRecoveryCancellationFixture = (): OutageLedger => { ...base, postRecovery: Object.freeze({ freshMcpSession: Object.freeze({ closeCompletedAt: 1_321, closeStartedAt: 1_320, id: freshMcpSessionId, openedAt: 1_310 }), + // The Hooks visit owns exactly the last request of the ledger below. navigation: Object.freeze([ - Object.freeze({ leftAt: 1_340, openedAt: 1_330, url: hooksUrl }), + Object.freeze({ leftAt: 1_340, leftIndex: base.requests.length + 2, openedIndex: base.requests.length + 1, url: hooksUrl }), ]), }), requests: Object.freeze([ @@ -131,16 +153,31 @@ const isPlaygroundSessionReplayPath = (path: string): boolean => { segments[2] === 'sessions' && segments[3]!.length > 0 && segments[4] === 'replay'; }; +const isSuccessStatus = (status: number | undefined): status is number => status !== undefined && status >= 200 && status < 300; + +/** The abort landed before any response headers: Chromium reports neither a status nor a response instant. */ +const responseIsAbsent = (request: NetworkLedgerEntry): boolean => request.respondedAt === undefined && request.status === undefined; + const isPlaygroundSessionReadCancellation = (request: NetworkLedgerEntry): boolean => { const segments = request.path.split('/').filter((segment) => segment.length > 0); - const responseIsAbsent = request.respondedAt === undefined && request.status === undefined; - const responseIsSuccessful = request.respondedAt !== undefined && request.status !== undefined && - request.status >= 200 && request.status < 300; + const responseIsSuccessful = request.respondedAt !== undefined && isSuccessStatus(request.status); return segments.length === 4 && segments[0] === 'api' && segments[1] === 'playground' && segments[2] === 'sessions' && segments[3]!.length > 0 && request.url === `${request.origin}${request.path}` && - request.completedAt !== undefined && request.at <= request.completedAt && (responseIsAbsent || responseIsSuccessful); + request.completedAt !== undefined && request.at <= request.completedAt && (responseIsAbsent(request) || responseIsSuccessful); }; +/** + * The Logs page issues `/api/logs/replay` from its mount effect and aborts it + * from the effect's cleanup, so leaving the page cancels the replay in + * whichever state it is in: after a 2xx arrived (the body read is cut short) + * or before any headers arrived (a loaded server has not answered yet, and + * Chromium reports the abort with no status at all). Both are the same + * deliberate navigation; an abort after a non-2xx answer is still rejected. + */ +const isLogsReplayCancellation = (request: NetworkLedgerEntry): boolean => + request.path === '/api/logs/replay' && request.completedAt !== undefined && request.at <= request.completedAt && + (responseIsAbsent(request) || isSuccessStatus(request.status)); + /** * The playground screen retires a superseded in-flight catalog request when * its effect re-runs (one AbortController per effect), and route changes abort @@ -152,7 +189,7 @@ const isKnownPreOutageClientCancellation = (request: NetworkLedgerEntry): boolea request.path === '/api/playground/catalog' || isPlaygroundSessionReadCancellation(request) || isPlaygroundSessionReplayPath(request.path) || - (request.path === '/api/logs/replay' && request.status !== undefined && request.status >= 200 && request.status < 300) + isLogsReplayCancellation(request) ); export const hasCanonicalAfterCursor = (url: URL): boolean => { @@ -163,8 +200,26 @@ export const hasCanonicalAfterCursor = (url: URL): boolean => { return Number.isSafeInteger(parsed) && parsed >= 0 && String(parsed) === after && url.search === `?after=${after}`; }; -/** A probe against a dying server can hit its half-open socket (RESET) instead of a closed port (REFUSED). */ -const downServerProbeCodes: ReadonlySet = new Set(['net::ERR_CONNECTION_REFUSED', 'net::ERR_CONNECTION_RESET']); +/** + * A probe against a dying server can hit its half-open socket (RESET), or go + * out over a keep-alive connection the server has already closed — Chromium + * reports that as SOCKET_NOT_CONNECTED — instead of a closed port (REFUSED). + * `closeChild` (`packed-release-harness.ts`) stops the server with SIGTERM, so + * the first probe of an outage races the server closing its idle sockets by + * sub-millisecond ordering (CI runs 33933481002 and 33936651225: 9 ms and + * 18 ms in, no response headers, every later probe REFUSED). + */ +const downServerProbeCodes: ReadonlySet = new Set(['net::ERR_CONNECTION_REFUSED', 'net::ERR_CONNECTION_RESET', 'net::ERR_SOCKET_NOT_CONNECTED']); + +/** The wait the Workbench project client observes after every failed session probe (`project-client.ts`). */ +const projectSessionRetryDelayMs = 250; + +/** + * How late Playwright may hand a network event to the ledger on a loaded + * runner before the ledger stops explaining a short retry gap with it: half + * the client's delay, so a probe issued without any delay can never pass. + */ +const maximumDeliveryDelayMs = 125; /** Chromium reports a severed old-stream socket as RESET or, when the reconnect never attached, SOCKET_NOT_CONNECTED. */ const oldStreamSeveranceCodes: ReadonlySet = new Set(['net::ERR_CONNECTION_RESET', 'net::ERR_SOCKET_NOT_CONNECTED']); @@ -206,6 +261,14 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { const postRecovery = ledger.postRecovery; const freshMcpSession = postRecovery.freshMcpSession; const freshMcpStreamPath = `/api/mcp/sessions/${encodeURIComponent(freshMcpSession.id)}/stream`; + // The MCP page keeps two readers on one session: the transport opens + // `stream?after=0` as soon as the POST returns (AgentBundleRemoteTransport + // #start) and the session controller subscribes to `stream?after=N` once + // the trace refresh has settled (McpSessionController #subscribeTrace). + // Closing the session aborts both — the controller's subscription, then + // the transport's stream — before the DELETE goes out, so a close leaves + // one or two same-path aborts, each carrying the 2xx headers it had + // already received, inside the close window. const freshMcpStreamFailures = postRecoveryFailures.filter((request) => request.path === freshMcpStreamPath); assertOutageLedger(freshMcpStreamFailures.length >= 1 && freshMcpStreamFailures.length <= 2, `fresh B MCP stream did not terminate exactly once or twice: ${JSON.stringify(freshMcpStreamFailures)}`); @@ -216,26 +279,27 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { assertOutageLedger( failure.origin === ledger.origin && url.origin === ledger.origin && url.pathname === freshMcpStreamPath && hasCanonicalAfterCursor(url) && failure.method === 'GET' && failure.error === 'net::ERR_ABORTED' && failure.at >= freshMcpSession.openedAt && - failure.respondedAt !== undefined && failure.respondedAt <= ledgerFailureAt(failure) && - failure.status !== undefined && failure.status >= 200 && failure.status < 300 && + failure.respondedAt !== undefined && failure.respondedAt <= ledgerFailureAt(failure) && isSuccessStatus(failure.status) && ledgerFailureAt(failure) >= freshMcpSession.closeStartedAt && ledgerFailureAt(failure) <= freshMcpSession.closeCompletedAt, `fresh B MCP stream cancellation is not action-induced: ${JSON.stringify(failure)}`, ); } - const navigationFailures: NetworkLedgerEntry[] = []; + const navigationFailures = new Set(); for (const navigation of postRecovery.navigation) { - const failures = postRecoveryFailures.filter((request) => - request.url === navigation.url && request.at >= navigation.openedAt && request.at < navigation.leftAt && - ledgerFailureAt(request) >= navigation.leftAt, - ); + // Membership by delivery order (see OutageLedger.postRecovery.navigation): + // the visit owns the requests handed over between its arrival and its + // departure stamps, whatever millisecond they carry. + const failures = postRecoveryFailures.filter((request) => { + const index = ledger.requests.indexOf(request); + return request.url === navigation.url && index >= navigation.openedIndex && index < navigation.leftIndex && + ledgerFailureAt(request) >= navigation.leftAt; + }); assertOutageLedger(failures.length <= 1, `multiple action-induced navigation cancellations: ${JSON.stringify({ failures, navigation })}`); for (const failure of failures) { - const responseIsAbsent = failure.respondedAt === undefined && failure.status === undefined; const responseIsSuccessful = failure.respondedAt !== undefined && failure.respondedAt >= failure.at && - failure.respondedAt <= ledgerFailureAt(failure) && failure.status !== undefined && - failure.status >= 200 && failure.status < 300; - let validResponse = responseIsAbsent || responseIsSuccessful; + failure.respondedAt <= ledgerFailureAt(failure) && isSuccessStatus(failure.status); + let validResponse = responseIsAbsent(failure) || responseIsSuccessful; if (navigation.respondedStream === true) { let url: URL; try { url = new URL(failure.url); } @@ -249,11 +313,16 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { `navigation cancellation did not match its exact pending-or-stream response contract: ${JSON.stringify({ failure, navigation })}`, ); } - navigationFailures.push(...failures); + for (const failure of failures) navigationFailures.add(failure); } - const recognizedPostRecoveryFailures = [...freshMcpStreamFailures, ...navigationFailures]; - assertOutageLedger(recognizedPostRecoveryFailures.length === postRecoveryFailures.length, - `unknown post-recovery failure: ${JSON.stringify(postRecoveryFailures)}`); + // What must hold is that every post-recovery failure is claimed by some + // contract. Report only the unclaimed ones — a dump of every failure reads + // as if the recognized ones were at fault. + const unrecognizedPostRecoveryFailures = postRecoveryFailures.filter((request) => + !freshMcpStreamFailures.includes(request) && !navigationFailures.has(request), + ); + assertOutageLedger(unrecognizedPostRecoveryFailures.length === 0, + `unknown post-recovery failure: ${JSON.stringify(unrecognizedPostRecoveryFailures)}`); const postRecoveryConsoleErrors = ledger.consoleErrors.filter((consoleError) => consoleError.at >= ledger.recoveredAt); assertOutageLedger(postRecoveryConsoleErrors.length === 0, `post-recovery console errors: ${JSON.stringify(postRecoveryConsoleErrors)}`); } @@ -297,7 +366,7 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { const oldSessionDeletes = sameOriginRequests.filter((request) => request.method === 'DELETE' && request.path === oldSessionPath); assertOutageLedger(oldSessionDeletes.length === 1, `expected exactly one old-session DELETE attempt: ${JSON.stringify(oldSessionDeletes)}`); const oldSessionDelete = oldSessionDeletes[0]!; - const deleteSucceeded = oldSessionDelete.status !== undefined && oldSessionDelete.status >= 200 && oldSessionDelete.status < 300; + const deleteSucceeded = isSuccessStatus(oldSessionDelete.status); const deleteRefused = oldSessionDelete.error === 'net::ERR_CONNECTION_REFUSED'; assertOutageLedger((deleteSucceeded ? 1 : 0) + (deleteRefused ? 1 : 0) === 1 && oldSessionDelete.completedAt !== undefined, `old-session DELETE must succeed or fail exactly with ERR_CONNECTION_REFUSED: ${JSON.stringify(oldSessionDelete)}`); @@ -305,9 +374,7 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { const projectSessionAttempts = sameOriginRequests.filter((request) => request.method === 'GET' && request.path === '/api/project/session' && request.at >= ledger.outageStartedAt, ).sort((left, right) => left.at - right.at); - const successfulSessions = projectSessionAttempts.filter((request) => - request.status !== undefined && request.status >= 200 && request.status < 300, - ); + const successfulSessions = projectSessionAttempts.filter((request) => isSuccessStatus(request.status)); assertOutageLedger(successfulSessions.length >= 1, `the browser did not complete a B-generation project session: ${JSON.stringify(projectSessionAttempts)}`); const firstSuccessfulBSession = successfulSessions[0]!; assertOutageLedger(firstSuccessfulBSession.completedAt === ledger.recoveredAt, @@ -320,9 +387,22 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { `project/session retry had a non-connection failure: ${JSON.stringify(retryAttempts)}`); assertOutageLedger(retryAttempts.at(-1) === firstSuccessfulBSession && firstSuccessfulBSession.status === 200, `project/session recovery did not finish with the first successful B session: ${JSON.stringify(retryAttempts)}`); + // `at` is stamped when Playwright delivers the `request` event to Node, not + // when the page issued the probe, and a delivery can only run late — by at + // most `maximumDeliveryDelayMs` here — so a held-back event lengthens its own + // gap and shortens the next by the same amount (a 284 ms / 222 ms pair on a + // loaded host). A gap may therefore fall short of the client's 250 ms only by + // lateness already accumulated: the credit starts at the ceiling (the first + // probe may itself have been delivered late), every gap adds or spends its + // difference from 250 ms, capped at the ceiling, and it may never go + // negative. A burst (one probe issued without the delay) overspends at once; + // an under-paced client cannot borrow from gaps it has not produced yet. + let deliveryLatenessCredit = maximumDeliveryDelayMs; for (const [index, attempt] of retryAttempts.entries()) { - if (index > 0) assertOutageLedger(attempt.at - retryAttempts[index - 1]!.at >= 225, - `project/session retries began too quickly: ${JSON.stringify(retryAttempts)}`); + if (index === 0) continue; + deliveryLatenessCredit = Math.min(maximumDeliveryDelayMs, deliveryLatenessCredit + (attempt.at - retryAttempts[index - 1]!.at) - projectSessionRetryDelayMs); + assertOutageLedger(deliveryLatenessCredit >= 0, + `project/session retries began too quickly (attempt ${String(index + 1)} arrived ${String(-deliveryLatenessCredit)} ms before any delivery lateness could explain): ${JSON.stringify(retryAttempts)}`); } const retryTimeline = retryAttempts.flatMap((request) => [ Object.freeze({ at: request.at, delta: 1 }), @@ -335,7 +415,7 @@ export const validateOutageLedger = (ledger: OutageLedger): void => { maxInFlight = Math.max(maxInFlight, inFlight); } assertOutageLedger(maxInFlight <= 1 && inFlight === 0, `project/session retry concurrency exceeded one: ${JSON.stringify(retryAttempts)}`); - const retryUpperBound = 2 + Math.ceil((ledger.recoveredAt - ledger.outageStartedAt) / 250); + const retryUpperBound = 2 + Math.ceil((ledger.recoveredAt - ledger.outageStartedAt) / projectSessionRetryDelayMs); assertOutageLedger(retryAttempts.length <= retryUpperBound, `project/session retries exceeded the bounded cadence (${String(retryUpperBound)}): ${JSON.stringify(retryAttempts)}`);