diff --git a/packages/core/e2e/e2e.test.ts b/packages/core/e2e/e2e.test.ts index 52867c4e4b..43a74e608f 100644 --- a/packages/core/e2e/e2e.test.ts +++ b/packages/core/e2e/e2e.test.ts @@ -16,11 +16,12 @@ import { afterAll, assert, beforeAll, - beforeEach, describe, expect, - test, + type TestContext, + type test as vitestTest, } from 'vitest'; +import { createTaskCollector, getCurrentSuite } from 'vitest/suite'; import { getTrustedSourcesHeaders } from '../../../scripts/trusted-sources-headers.mjs'; import type { Run } from '../src/runtime'; import { @@ -32,11 +33,14 @@ import { resumeHook, } from '../src/runtime'; import { + announceTestStart, assertUnsupportedTestsExist, cliCancel, cliHealthJson, cliInspectJson, cliInspectJsonUntil, + createPerTestState, + dumpTrackedRunDiagnostics, fetchManifest, getCollectedRunIds, getWorkflowMetadata, @@ -45,10 +49,14 @@ import { hasWorkflowSourceMaps, isJsApp, isLocalDeployment, + noteTestSettled, + noteTestStarted, requireFixture, - setupRunTracking, + requireSupported, + runInTestState, setupWorld, startTracked, + summarizeLoad, trackRun, warmDeployment, writeDiagnosticsSidecar, @@ -61,7 +69,12 @@ if (!deploymentUrl) { } const DISTRIBUTED_CLOCK_TOLERANCE_MS = 1_000; -const RACE_WINNER_MAX_DURATION_MS = 5_000; +// The race winner takes 1s; the loser would take 10s. The bound only has to +// sit clearly below the loser to catch badly delayed or sequential +// completion — under the concurrent suite, queue latency pushed the winner's +// observed duration to ~6.5s on loaded local-dev lanes, so 5s was tight +// enough to flake without being any better at catching the regression. +const RACE_WINNER_MAX_DURATION_MS = 8_000; const EVENT_POLL_PAGE_SIZE = 100; function expectElapsedAtLeast( @@ -144,6 +157,87 @@ const e2e = (fn: string) => { * Every test not marked here is in scope for cross-language conformance, and is * gated only by `e2e-conformance.json`. No-op for the JS workbench apps. */ +/** + * Every test in this suite runs through this handler wrapper, which owns the + * per-test harness plumbing the sequential suites do in a `beforeEach` + * (announce heartbeat, conformance gates, failure diagnostics). + * + * The suite runs concurrently, and vitest's `getCurrentTest()` is a plain + * module variable that is wrong after any `await`, so nothing per-test can + * live in module globals. The wrapper binds a per-test state (name, tracked + * runs, the test's own `skip`) via AsyncLocalStorage *around the handler + * call itself* — a direct call stack, so the store provably reaches the test + * body — and `trackRun`/`recordInfraEvent`/`requireFixture` read it + * ambiently with no call-site changes. (A `test.extend` auto fixture cannot + * do this: vitest resolves fixtures in a separate async context, so a store + * bound around `use()` never reaches the test body.) Failure diagnostics + * dump from the bound state, so a failing test reports its own runs, not a + * concurrent sibling's. + */ +const wrapE2EHandler = + (handler: (ctx: TestContext) => unknown) => (ctx: TestContext) => { + const state = createPerTestState(ctx.task.name, ctx.skip); + announceTestStart(ctx.task.name); + ctx.onTestFailed( + (result) => dumpTrackedRunDiagnostics(state, result.errors?.[0]?.message), + 30_000 // Allow 30s for diagnostics fetching (default hookTimeout is 10s) + ); + return runInTestState(state, async () => { + // Second conformance gate — inside the bound state so the skip + // targets this test. + requireSupported(ctx.task.name); + // Timed for the per-lane load summary (see summarizeLoad): under + // concurrency the interesting number is not pass/fail but how far + // per-test latency moved and whether CLI children dominate it. + const startedAt = Date.now(); + noteTestStarted(); + try { + return await handler(ctx); + } finally { + noteTestSettled(ctx.task.name, Date.now() - startedAt); + } + }); + }; + +/** + * Drop-in `test` that wraps every handler with {@link wrapE2EHandler} and + * then hands the call to the enclosing suite's own collector — exactly what + * vitest's top-level `test` does (`getCurrentSuite().test.fn.call(this, …)`). + * + * Delegating rather than calling `getCurrentSuite().task()` directly is + * load-bearing: the suite collector is where suite options are merged into + * each test (`Object.assign({}, suiteOptions, options)`), which is how + * `describe.concurrent` reaches its tests. Calling `task()` directly skips + * that merge, and the suite silently runs sequentially — caught in CI as + * lanes matching the serial baseline minute-for-minute. + * + * Built on `createTaskCollector`, so the whole chainable surface (`.skip`, + * `.only`, `.each`, `.runIf`, `.sequential`, …) keeps working. + */ +const test = createTaskCollector(function ( + this: Record, + name: string, + optionsOrFn?: unknown, + optionsOrTest?: unknown +) { + let options: unknown = {}; + let handler: (ctx: TestContext) => unknown = () => {}; + if (typeof optionsOrTest === 'object' && optionsOrTest !== null) { + options = optionsOrTest; + handler = optionsOrFn as typeof handler; + } else if (typeof optionsOrTest === 'number') { + options = { timeout: optionsOrTest }; + handler = optionsOrFn as typeof handler; + } else if (typeof optionsOrFn === 'object' && optionsOrFn !== null) { + options = optionsOrFn; + handler = optionsOrTest as typeof handler; + } else if (typeof optionsOrFn === 'function') { + handler = optionsOrFn as typeof handler; + } + + getCurrentSuite().test.fn.call(this, name, options, wrapE2EHandler(handler)); +}) as typeof vitestTest; + const testJsOnly = isJsApp() ? test : test.skip; const describeJsOnly = isJsApp() ? describe : describe.skip; @@ -321,9 +415,13 @@ async function startWorkflowViaHttp( return run; } -// NOTE: Temporarily disabling concurrent tests to avoid flakiness. -// TODO: Re-enable concurrent tests after conf when we have more time to investigate. -describe('e2e', () => { +// Concurrent: ~128 serial tests were the dominant wall-clock cost per matrix +// entry (~22 of 24 minutes on the Vercel lanes). The known blockers are +// fixed: per-test attribution is concurrency-safe (see the e2eTracking +// fixture), abort-fetch tests are hermetic, the fibonacci tree fits the +// scheduler, and source-map assertions are positive-only. A test that +// genuinely cannot share a deployment can opt out with `test.sequential`. +describe.concurrent('e2e', () => { // Configure the World for the test runner process so that start() and // run.returnValue can communicate with the same backend as the workbench app. // Also warm the target before the first test starts a run: a fresh Vercel @@ -346,13 +444,11 @@ describe('e2e', () => { ); }, 150_000); - // Enable automatic run diagnostics on test failure - beforeEach((ctx) => { - setupRunTracking(ctx.task.name); - }); - // Write E2E metadata and diagnostics files afterAll(() => { + // First, so the numbers reach the log even if a later assertion in this + // hook throws. + process.stdout.write(summarizeLoad()); writeE2EMetadata(); writeDiagnosticsSidecar(); writeInfraSidecar(); diff --git a/packages/core/e2e/utils.test.ts b/packages/core/e2e/utils.test.ts index b985ae5c8a..9315f0b14c 100644 --- a/packages/core/e2e/utils.test.ts +++ b/packages/core/e2e/utils.test.ts @@ -1,7 +1,11 @@ import { afterEach, describe, expect, test, vi } from 'vitest'; import { + createPerTestState, + getCollectedRunIds, getRecordedInfraEvents, hasStepSourceMaps, + runInTestState, + trackRun, waitForRunPickup, warmDeployment, } from './utils'; @@ -214,3 +218,31 @@ describe('warmDeployment', () => { ).toBe(startProbe.mock.calls.length); }); }); + +describe('per-test state isolation', () => { + test('interleaved contexts attribute runs to their own test', async () => { + const before = getCollectedRunIds().length; + const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms)); + const fakeRun = (id: string) => ({ runId: id }) as never; + + // Two "tests" interleaving on the event loop, as under + // describe.concurrent: each tracks a run after yielding, so a + // module-global current-test-name would attribute both to whichever + // context touched it last. + await Promise.all([ + runInTestState(createPerTestState('test-a'), async () => { + await sleep(20); + trackRun(fakeRun('wrun_a')); + }), + runInTestState(createPerTestState('test-b'), async () => { + await sleep(10); + trackRun(fakeRun('wrun_b')); + }), + ]); + + const entries = getCollectedRunIds().slice(before); + expect( + Object.fromEntries(entries.map((e) => [e.runId, e.testName])) + ).toEqual({ wrun_a: 'test-a', wrun_b: 'test-b' }); + }); +}); diff --git a/packages/core/e2e/utils.ts b/packages/core/e2e/utils.ts index 7c0779ab0a..689b5bf208 100644 --- a/packages/core/e2e/utils.ts +++ b/packages/core/e2e/utils.ts @@ -1,3 +1,4 @@ +import { AsyncLocalStorage } from 'node:async_hooks'; import { spawn } from 'node:child_process'; import fs from 'node:fs'; import path, { dirname } from 'node:path'; @@ -268,7 +269,7 @@ export function hasFixture(fixtureName: string): boolean { */ export function requireFixture(fixtureName: string): void { if (hasFixture(fixtureName)) return; - getCurrentTest()?.context.skip( + currentSkip()?.( `"${fixtureName}" is not listed in ${CONFORMANCE_CONFIG_FILENAME}` ); } @@ -290,7 +291,7 @@ export function requireSupported(testName: string): void { seenTestNames.add(testName); const reason = getConformanceConfig()?.unsupported?.[testName]; if (!reason) return; - getCurrentTest()?.context.skip( + currentSkip()?.( `${CONFORMANCE_CONFIG_FILENAME} declares this unsupported: ${reason}` ); } @@ -412,6 +413,76 @@ function getCliArgs(): string { return `--backend vercel --verbose`; } +// --------------------------------------------------------------------------- +// Load observability +// +// The concurrent suite's cost is not obvious from pass/fail: tests can pass +// while per-test latency inflates several-fold, and the inflation can come +// from the deployment (queueing) or from the runner (every CLI assertion +// spawns a full `node` child, and a CI runner has few cores). The counters +// here make each lane report which one it was — peak test and CLI +// concurrency, CLI child count, and CLI wall time as a share of total test +// wall time — so a tuning decision has numbers behind it instead of a guess. +// --------------------------------------------------------------------------- + +const loadStats = { + cliCalls: 0, + cliMs: 0, + cliInFlight: 0, + cliPeakInFlight: 0, + testsInFlight: 0, + testsPeakInFlight: 0, + testMs: 0, + durations: [] as { name: string; ms: number }[], +}; + +/** Called by the suite's handler wrapper when a test body starts. */ +export function noteTestStarted() { + loadStats.testsInFlight++; + loadStats.testsPeakInFlight = Math.max( + loadStats.testsPeakInFlight, + loadStats.testsInFlight + ); +} + +/** Called by the suite's handler wrapper when a test body settles. */ +export function noteTestSettled(name: string, ms: number) { + loadStats.testsInFlight--; + loadStats.testMs += ms; + loadStats.durations.push({ name, ms }); +} + +/** + * One-line-per-fact load summary for the job log. Logged from `afterAll`. + */ +export function summarizeLoad(): string { + const { durations } = loadStats; + if (durations.length === 0) return ''; + const slowest = [...durations].sort((a, b) => b.ms - a.ms).slice(0, 10); + const sum = durations.reduce((acc, d) => acc + d.ms, 0); + const cliShare = + loadStats.testMs > 0 + ? Math.round((loadStats.cliMs / loadStats.testMs) * 100) + : 0; + const lines = [ + '', + '━━━ e2e load summary ━━━', + `tests: ${durations.length} · peak concurrent: ${loadStats.testsPeakInFlight}`, + `test wall time (summed): ${Math.round(sum / 1000)}s · median ${Math.round( + [...durations].sort((a, b) => a.ms - b.ms)[ + Math.floor(durations.length / 2) + ].ms + )}ms`, + `cli children: ${loadStats.cliCalls} · peak concurrent: ${loadStats.cliPeakInFlight} · ` + + `wall time ${Math.round(loadStats.cliMs / 1000)}s (${cliShare}% of summed test time)`, + 'slowest tests:', + ...slowest.map((d) => ` ${Math.round(d.ms / 1000)}s ${d.name}`), + '━━━━━━━━━━━━━━━━━━━━━━', + '', + ]; + return lines.join('\n'); +} + const awaitCommand = async ( command: string, args: string[], @@ -422,6 +493,18 @@ const awaitCommand = async ( console.log(`[Debug]: Executing ${command} ${args.join(' ')}`); console.log(`[Debug]: in CWD: ${cwd}`); + loadStats.cliCalls++; + loadStats.cliInFlight++; + loadStats.cliPeakInFlight = Math.max( + loadStats.cliPeakInFlight, + loadStats.cliInFlight + ); + const cliStartedAt = Date.now(); + const noteCliSettled = () => { + loadStats.cliInFlight--; + loadStats.cliMs += Date.now() - cliStartedAt; + }; + return await new Promise<{ stdout: string; stderr: string }>( (resolve, reject) => { const child = spawn(command, args, { @@ -458,8 +541,12 @@ const awaitCommand = async ( }); } - child.on('error', (err) => reject(err)); + child.on('error', (err) => { + noteCliSettled(); + reject(err); + }); child.on('close', (code, signal) => { + noteCliSettled(); if (code !== 0) { const exitReason = signal ? `killed by signal ${signal}` @@ -758,8 +845,56 @@ interface TrackedRun { workflowFn?: string; } -// Per-test tracked runs — reset between tests via setupRunTracking() -let trackedRuns: TrackedRun[] = []; +/** + * Per-test harness state: the name used to attribute runs and infra events, + * and the runs whose diagnostics dump if the test fails. + * + * Concurrent suites bind one of these per test via {@link runInTestState} + * (AsyncLocalStorage), so tests interleaving on the event loop cannot + * clobber each other's attribution — `getCurrentTest()` is a plain module + * variable in vitest and is wrong after any `await` under concurrency. + * Sequential suites (dev.test.ts, e2e-agent.test.ts, e2e-region.test.ts) + * keep the classic path: {@link setupRunTracking} resets a module-level + * fallback that is safe when only one test runs at a time. + */ +interface PerTestState { + testName: string; + trackedRuns: TrackedRun[]; + /** + * The test's own `ctx.skip`, captured where the context is unambiguous + * (the fixture), so conformance gates called mid-test-body can skip the + * right test — `getCurrentTest()?.context.skip` would target whichever + * test most recently started. + */ + skip?: (note?: string) => void; +} + +const testStateStorage = new AsyncLocalStorage(); +let fallbackTestState: PerTestState = { + testName: 'unknown', + trackedRuns: [], +}; +const currentTestState = (): PerTestState => + testStateStorage.getStore() ?? fallbackTestState; + +export function createPerTestState( + testName: string, + skip?: (note?: string) => void +): PerTestState { + return { testName, trackedRuns: [], skip }; +} + +/** ALS-bound skip when available, vitest's global otherwise. */ +const currentSkip = (): ((note?: string) => void) | undefined => + testStateStorage.getStore()?.skip ?? getCurrentTest()?.context.skip; + +/** Run `fn` with `state` bound as the ambient per-test state. */ +export function runInTestState( + state: PerTestState, + fn: () => Promise +): Promise { + return testStateStorage.run(state, fn); +} // Global list of run IDs collected for metadata (observability links) const globalCollectedRunIds: { @@ -790,8 +925,9 @@ export function trackRun( workflowFn?: string; } ): Run { - const testName = options?.testName ?? currentTestName; - trackedRuns.push({ + const state = currentTestState(); + const testName = options?.testName ?? state.testName; + state.trackedRuns.push({ run, workflowFile: options?.workflowFile, workflowFn: options?.workflowFn, @@ -865,7 +1001,7 @@ export function recordInfraEvent( ) { infraEvents.push({ ...event, - testName: event.testName ?? currentTestName, + testName: event.testName ?? currentTestState().testName, timestamp: new Date().toISOString(), }); } @@ -1223,43 +1359,55 @@ function emitGitHubAnnotation( * beforeEach((ctx) => { setupRunTracking(ctx.task.name); }); */ export function setupRunTracking(testName: string) { - currentTestName = testName; - trackedRuns = []; + fallbackTestState = createPerTestState(testName); // Second conformance gate. Sited here because every test in the suite calls // setupRunTracking from `beforeEach`, which makes this the one place that // sees a test's name without the test having to declare anything. requireSupported(testName); - // Heartbeat: announce the test the moment it starts, written straight to - // stdout to bypass vitest's per-file console buffering. Without this, a - // test that stalls (e.g. polling a run that never progresses) produces no - // output until its timeout, making CI look like a silent hang — the - // reporter only prints a test's result line once it completes. Emitting the - // name on start makes the stalling test immediately identifiable. - process.stdout.write(`\n[e2e] ▶ start: ${testName}\n`); + announceTestStart(testName); + const state = fallbackTestState; onTestFailed( - async (result) => { - const errorMessage = result.errors?.[0]?.message || 'Test failed'; - - for (const tracked of trackedRuns) { - try { - const diagnostics = await getRunDiagnostics(tracked); - console.error(diagnostics); - emitGitHubAnnotation(testName, tracked, errorMessage); - } catch { - console.error( - `[diagnostics] Failed to fetch diagnostics for run ${tracked.run.runId}` - ); - } - } - }, + (result) => dumpTrackedRunDiagnostics(state, result.errors?.[0]?.message), 30_000 // Allow 30s for diagnostics fetching (default hookTimeout is 10s) ); } -// Current test name for auto-tracking -let currentTestName = 'unknown'; +/** + * Heartbeat: announce the test the moment it starts, written straight to + * stdout to bypass vitest's per-file console buffering. Without this, a + * test that stalls (e.g. polling a run that never progresses) produces no + * output until its timeout, making CI look like a silent hang — the + * reporter only prints a test's result line once it completes. Emitting the + * name on start makes the stalling test immediately identifiable. + */ +export function announceTestStart(testName: string) { + process.stdout.write(`\n[e2e] ▶ start: ${testName}\n`); +} + +/** + * Dump diagnostics for every run tracked by `state`. Shared by the + * sequential path (setupRunTracking's onTestFailed) and the concurrent + * fixture, which passes the state it bound for its own test — the one + * thing vitest's globals cannot provide under concurrency. + */ +export async function dumpTrackedRunDiagnostics( + state: PerTestState, + errorMessage = 'Test failed' +) { + for (const tracked of state.trackedRuns) { + try { + const diagnostics = await getRunDiagnostics(tracked); + console.error(diagnostics); + emitGitHubAnnotation(state.testName, tracked, errorMessage); + } catch { + console.error( + `[diagnostics] Failed to fetch diagnostics for run ${tracked.run.runId}` + ); + } + } +} /** * Write diagnostics sidecar file with per-test run info for the aggregation script. diff --git a/vitest.config.ts b/vitest.config.ts index ad59d47870..78cac94104 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -12,6 +12,15 @@ export default defineConfig({ // the signal (event-log-race-repro, benchmarks) pin `retry: 0` locally. // Local runs keep retry at 0 so races reproduce while debugging. retry: process.env.CI ? 1 : 0, + // How many concurrent tests vitest runs from a `describe.concurrent` + // suite (vitest's own default is 5). Only the e2e conformance suite is + // concurrent, so this is effectively its dial. Tunable because the right + // value is a property of the runner and the deployment rather than of + // the tests: every CLI assertion spawns a `node` child, and a CI runner + // has few cores, so too high a value inflates per-test latency until + // tests exceed budgets written for an unloaded suite. Each lane logs + // what it observed (see `summarizeLoad` in the e2e utils). + maxConcurrency: Number(process.env.WORKFLOW_E2E_MAX_CONCURRENCY ?? 5), // Positional file arguments are regex filters, not paths, so // `vitest run packages/core/e2e/x.test.ts` also matches // `.claude/worktrees//packages/core/e2e/x.test.ts` when agent