From 53732c811bb69655eb43d3d12f2063ae4ca5ad67 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Wed, 21 Oct 2026 08:31:22 -0500 Subject: [PATCH] fix(evals): classify latency from observation bounds (#16829) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - Product E2E probes measure when acknowledgements and replies become visible. > - A poll gives a time interval for an event. > - The first positive poll can occur after a target that the event could still meet. > - This pull request compares the full interval with a strict or inclusive target. > - Reports retain the raw observations and the original verdict when the timing verdict changes. ## Linked Issues or Issue Description **What happened?** A historical acknowledgement was absent at 1901 ms and first present at 2427 ms. A report marked the 2000 ms target as failed. The interval crosses that target, so the available evidence cannot give a pass or fail verdict. **Expected behavior** Return pass when the full interval meets the target. Return fail when the full interval rules out the target. Return inconclusive for overlap, invalid evidence, or insufficient evidence. Respect strict and inclusive targets and open and closed endpoints. **Steps to reproduce** Run the deterministic timing tests. Use the acknowledgement interval `(1901, 2427] ms` with `<= 2000 ms`. Compare the late reply interval `(52965, 53334] ms` with `<= 30000 ms`. The first is inconclusive. The second fails. **Paperclip version or commit** The source includes master at `14afc12124017d4ec30d0f4bfd6892f8ce475d21`. Related PR: [#13710](https://github.com/paperclipai/paperclip/pull/13710) changed chat latency and session reuse. This change corrects probe evidence and report verdicts. ## What Changed - Add a shared interval classifier with explicit endpoint and target operators. - Start observation before dispatch. Use a monotonic clock. Bound asynchronous reads by request start and completion. - Measure the first visible response separately from message creation and final settlement. Share browser reads with an optional acknowledgement probe. - Keep raw bounds, clock resolution, message metadata, failed reads, and original verdicts in retained report evidence. - Add deterministic coverage for threshold equality, missing data, edited messages, asynchronous reads, teardown, report correction, and a finite-domain oracle. - Bound observer shutdown to one second across pending and final reads. Retain timeout counts. Ignore late completions and start no more reads after shutdown. - Document the timing contract in the existing Product E2E guide. - Keep current startup reuse evidence after the master merge. Update four stale test expectations for qualified Copilot admission. Keep the explicit suite and provider restrictions. ## Verification - Current head: `c42e87e6d3b4b347e7cb176f56819c1d0abe106d`. - Passed: `pnpm test:e2e:runner:unit` (3,287 Vitest tests and 128 native completion tests; two explicit skips). - Passed: `pnpm test:e2e:runner:typecheck`, `pnpm -r typecheck`, `pnpm build`, `pnpm check:token-gates`, and `git diff origin/master --check`. - Passed: [exact-head CI](https://github.com/paperclipai/paperclip/actions/runs/39607140418), including both required checks (`ci / verify` and `ci / e2e`), all general and serialized test jobs, all eight browser shards, build, canary dry run, and the clean public npm-install smoke. - Greptile reviewed the complete current diff and returned [5/5 with no actionable issues](https://github.com/paperclipai/paperclip/pull/16829#issuecomment-6266704814). All review threads are resolved. - The redundant local `pnpm test:run` was stopped after the exact-head CI test jobs passed. It did not produce a complete local verdict; the full repository test evidence is the CI run above. - The [earlier broad run](https://github.com/paperclipai/paperclip/actions/runs/39249282597) failed on the old head. Its full test command timed out after 15 minutes. Five E2E support failures came from ambient `NODE_PATH` and a missing historical Git object. Current master supplies the closed-environment launcher and retained source fixture. The full support suite passes with these fixes. - After the current master merge, four stale Copilot assertions and the nested unit launcher failed. Copilot is now qualified. Those assertions now require no qualification override and retain the rejected suite/provider cases. The full documented unit command passes. - The first local typecheck after the merge used stale generated package declarations and failed. The typechecks pass after `pnpm build`. - These checks use synthetic timing evidence. They make no live provider calls and claim no new live latency measurement. ## Risks - The browser diagnostic depends on the existing message and receipt DOM markers. Controlled tests cover visibility, receipt separation, concurrent reads, and teardown. - Corrected timing verdicts can become inconclusive. The report keeps the original verdict and does not change the overall workflow grade. - This change adds no database migration or product surface. ## Model Used - OpenAI GPT-6 Codex. Model family: GPT-6. This session does not expose a more specific model ID or context window size. The agent used reasoning, shell tools, code inspection, and deterministic tests. The earlier implementation session did not retain its exact model ID. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Paperclip --- doc/evals.md | 5 + tests/runner-e2e/README.md | 41 ++++++ tests/runner-e2e/catalog.ts | 3 +- tests/runner-e2e/dashboard.ts | 9 +- tests/runner-e2e/extended-harnesses.test.ts | 13 +- tests/runner-e2e/history.ts | 6 + tests/runner-e2e/installed-cli.test.ts | 4 +- tests/runner-e2e/latency-timing.test.ts | 122 ++++++++++++++++++ tests/runner-e2e/latency-timing.ts | 130 ++++++++++++++++++++ tests/runner-e2e/report.test.ts | 36 ++++++ tests/runner-e2e/response-timing.test.ts | 119 ++++++++++++++++++ tests/runner-e2e/response-timing.ts | 102 +++++++++++++++ tests/runner-e2e/result-validation.ts | 21 ++++ tests/runner-e2e/runner.spec.ts | 10 ++ tests/runner-e2e/types.ts | 1 + tests/runner-e2e/user-actions.ts | 4 +- 16 files changed, 613 insertions(+), 13 deletions(-) create mode 100644 tests/runner-e2e/latency-timing.test.ts create mode 100644 tests/runner-e2e/latency-timing.ts create mode 100644 tests/runner-e2e/response-timing.test.ts create mode 100644 tests/runner-e2e/response-timing.ts diff --git a/doc/evals.md b/doc/evals.md index cb6ea498144..0c49d0d7284 100644 --- a/doc/evals.md +++ b/doc/evals.md @@ -263,6 +263,11 @@ analytical label. ## Evidence, provenance, and history +Polling latency is an interval rather than an exact first-detection time. The +[Product E2E timing contract](../tests/runner-e2e/README.md#latency-observation-bounds) +keeps last-absent/first-present bounds, resolution, strict or inclusive targets, +and pass/fail/inconclusive timing verdicts alongside the unchanged workflow grade. + Retained result snapshots and dated measurement reports belong in `paperclip-evals`; application tests, Product E2E fixtures/graders, and executable scenario inventories remain in this repository. Keep a compact results index diff --git a/tests/runner-e2e/README.md b/tests/runner-e2e/README.md index f17b530e77b..1ba9e2a9273 100644 --- a/tests/runner-e2e/README.md +++ b/tests/runner-e2e/README.md @@ -1,5 +1,46 @@ # Paid runner full-stack E2E +## Latency observation bounds + +The explicit `codie-latency-diagnostic` arms its observation recorder before +dispatching task creation and measures elapsed time with `performance.now()`. +The first browser read starts before dispatch; subsequent reads run every 100 ms +without overlapping. The observer stops and drains before fixture teardown, +with one one-second deadline for its pending and final reads. On expiry, it +records `observationTimeouts` and a failed observation for each waiting probe, +starts no more reads, and ignores late completions. Fixture cleanup owns the +browser operation that can still be running after that deadline. +It retains `latencyProbes` in the existing result JSON and dashboard, separately +for the first visible substantive response and final task/run settlement, with +an inclusive 30-second target. Platform-generated receipts do not count as the +substantive response. Browser polls bound persistent visible output; this does +not measure Slack delivery or qualify transient output between observations. +These timing verdicts are diagnostic dimensions and do not replace the existing +workflow matchers or rewrite the original attempt grade. + +`latency-timing.ts` is shared by response and acknowledgement timing evidence. +The browser adapter samples both from one snapshot when an acknowledgement +target is explicitly configured; the Daytona diagnostic does not enable that +feature or infer a missing Slack acknowledgement from its browser observations. +An absent observation and a present observation give `(lastAbsent, firstPresent]`; +an asynchronous absent read uses its start time, while a present read uses its +completion time. Each bound is widened by the declared clock resolution. +Targets specify `<` or `<=`; open and closed endpoints determine equality. +Pass requires the entire interval to satisfy the target, fail requires the +entire interval to violate it, and all other cases are inconclusive. Missing +observations remain null; unknown resolution and invalid/empty intervals cannot +produce a conclusive verdict. Failed reads are not absent observations. + +The historical acknowledgement `(1901, 2427] ms` is inconclusive against +`<= 2000 ms`; the reply `(52965, 53334] ms` fails `<= 30000 ms`. These are +deterministic calibration examples, not fresh live measurements. Provider +message creation/edit timestamps remain separate metadata; an edit can expose +new response text on an older message. Neither those timestamps nor final run +settlement substitutes for first visible response. The legacy warm-turn +`responseLatencyMs` field continues to mean final settlement and is labelled +accordingly. Report regeneration recomputes interval verdicts, retains changed +`recordedVerdict` values and all bounds, and leaves the original files intact. + ## Live provider connection journeys See [PROVIDER-CONNECTIONS.md](PROVIDER-CONNECTIONS.md) for the explicit-only diff --git a/tests/runner-e2e/catalog.ts b/tests/runner-e2e/catalog.ts index f4bd0d09d46..75995939899 100644 --- a/tests/runner-e2e/catalog.ts +++ b/tests/runner-e2e/catalog.ts @@ -1154,7 +1154,8 @@ export const runnerSuites: readonly RunnerSuiteFixture[] = [ tasks: runnerTasks.filter(task => task.id === "message-marker") .map(task => ({ ...task, automaticRetryPolicy: "single_attempt" as const })), expectedMatrixSize: 1, - definitionMetadata: { diagnostic: true, modelSource: "observed-staging-run", providerAuth: "api_key", stagingAuth: "subscription", companyData: "fresh-fixture", slackDelivery: false, maximumAutomaticRetries: 0 }, + definitionMetadata: { diagnostic: true, modelSource: "observed-staging-run", providerAuth: "api_key", stagingAuth: "subscription", companyData: "fresh-fixture", slackDelivery: false, maximumAutomaticRetries: 0, + timing: { version: 1, clock: "monotonic", responseTargetMs: 30_000, event: "first_visible_response", settlementSeparate: true } }, }, { id: TASK_WORKSPACES_SUITE, label: "Task workspaces without projects", manualOnly: true, diff --git a/tests/runner-e2e/dashboard.ts b/tests/runner-e2e/dashboard.ts index c9fe698d04d..2875917c056 100644 --- a/tests/runner-e2e/dashboard.ts +++ b/tests/runner-e2e/dashboard.ts @@ -2,6 +2,7 @@ import { html, durationLabel, tokenLabel, llmCostLabel, usdLabel } from "./repor import { renderReportShell, reportNavigationStyles, reportShellScript } from "./report-navigation.js"; import { reportBrowserScript } from "./report-browser.js"; import { isIncompleteFirstTaskResult, renderCaseOutcome } from "./case-outcome.js"; +import { latencyIntervalLabel } from "./latency-timing.js"; import { campaignSuiteSummaryStyles, renderCampaignSuiteSummary, renderSuiteCaseIndex } from "./campaign-summary.js"; import { journeyCapabilities, journeyFeatureIds } from "./journey-features.js"; import { journeyFeatureStyles, renderJourneyFeatureCoverage, renderJourneyFeatureOptions } from "./feature-coverage.js"; @@ -217,6 +218,11 @@ function renderCase( `, ) .join(""); + const latencyRows = (entry?.result.latencyProbes ?? []).map(probe => ` + ${html(probe.event)}${html(probe.verdict)} + ${html(latencyIntervalLabel(probe))}${html(`${probe.target.operator} ${probe.target.ms} ms`)} + ${html(probe.resolutionMs === null ? "unknown" : `${probe.resolutionMs} ms`)} + `).join(""); const startupReuseRows = (entry?.result.startupReuse ?? (entry?.result.runIds ?? []).map(runId => ({ runId, ...summarizeStartupReuse([]), }))).map(reuse => ` @@ -310,7 +316,8 @@ function renderCase( : "" }

${html(detail)}

- ${turnTimingRows ? `
${turnTimingRows}
TurnRunLeaseSchedulerRun durationResponse
` : ""} + ${turnTimingRows ? `
${turnTimingRows}
TurnRunLeaseSchedulerRun durationFinal settlement (legacy response field)
` : ""} + ${latencyRows ? `
${latencyRows}
EventTiming verdictPossible latencyTargetResolution
` : ""} ${startupReuseRows ? `
${startupReuseRows}
Startup reuse evidence
RunWarmthEnvironment/leaseWorkspaceRunnerProvider processProvider sessionProvider launches
` : ""} ${matcherRows ? `
${matcherRows}
ResultMatcherExpectationDetail
` : `

No matcher result was recorded.

`} ${entry ? `
Usage and billing metadata
${html(JSON.stringify({ billing, rawUsage: entry.result.usage ?? null }, null, 2))}
` : ""} diff --git a/tests/runner-e2e/extended-harnesses.test.ts b/tests/runner-e2e/extended-harnesses.test.ts index f0bbe7114ea..0912bcf6b4a 100644 --- a/tests/runner-e2e/extended-harnesses.test.ts +++ b/tests/runner-e2e/extended-harnesses.test.ts @@ -51,8 +51,8 @@ describe("extended ACP harness qualification", () => { const server = buildPaperclipServerEnvironment(env); for (const name of Object.keys(ambient).filter(name => name !== "PAPERCLIP_RUNNER_ACPX_QUALIFICATION")) expect(server[name]).toBeUndefined(); expect(buildRunnerE2EProcessEnvironment(ambient, []).PAPERCLIP_RUNNER_ACPX_QUALIFICATION).toBeUndefined(); - const pending = selected.find(value => value.profile.qualificationCandidate === "copilot")!; - expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...pending, suite: { ...pending.suite, manualOnly: false } }])).toThrow("explicit"); + const copilot = selected.find(value => value.profile.qualificationCandidate === "copilot")!; + expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...copilot, suite: { ...copilot.suite, manualOnly: false } }])).toThrow("explicit"); }); it("adds six explicit local/Daytona warm cells without admitting them implicitly", () => { const warm = runnerMatrix.filter(cell => cell.suite.id === "rich-acp-warm-continuity"); @@ -64,8 +64,7 @@ describe("extended ACP harness qualification", () => { const config = cell.profile.buildAgent({ executionId: "warm", environmentId: "env", environmentFixtureId: cell.environment.id, workspacePath: "/tmp/workspace", secretRefs: { [cell.profile.credential]: { type: "secret_ref", secretId: "11111111-1111-4111-8111-111111111111", version: "latest" } } }).adapterConfig; expect(config).toMatchObject({ lifecycleMode: "warm", idleTimeoutMs: 300_000, timeoutSec: 120 }); const admission = buildRunnerE2EProcessEnvironment({}, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION; - if (cell.profile.qualificationCandidate !== "copilot") expect(admission).toBeUndefined(); - else expect(JSON.parse(admission!)).toEqual([{ agent: "copilot", model: cell.profile.model }]); + expect(admission).toBeUndefined(); expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...cell, suite: { ...cell.suite, manualOnly: false } }])).toThrow("explicit"); } expect(selectRunnerExecutions(parseRunnerSelectors(["--all"])).some(cell => cell.suite.id === "rich-acp-warm-continuity")).toBe(false); @@ -94,8 +93,7 @@ describe("extended ACP harness qualification", () => { expect(new Set(cells.map(cell => cell.environment.id))).toEqual(new Set(["local", "daytona"])); for (const cell of cells) { const admission = buildRunnerE2EProcessEnvironment({}, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION; - if (cell.profile.qualificationCandidate !== "copilot") expect(admission).toBeUndefined(); - else expect(JSON.parse(admission!)).toEqual([{ agent: "copilot", model: cell.profile.model }]); + expect(admission).toBeUndefined(); expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...cell, profile: { ...cell.profile, qualificationCandidate: cell.profile.qualificationCandidate === "pi" ? "cursor" : "pi" } }])).toThrow("explicit"); } } @@ -109,8 +107,7 @@ describe("extended ACP harness qualification", () => { for (const cell of cells) { expect(cell.suite.manualOnly).toBe(true); const admission = buildRunnerE2EProcessEnvironment({ PAPERCLIP_RUNNER_ACPX_QUALIFICATION: "ambient" }, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION; - if (cell.profile.qualificationCandidate !== "copilot") expect(admission).toBeUndefined(); - else expect(JSON.parse(admission!)).toEqual([{ agent: "copilot", model: cell.profile.model }]); + expect(admission).toBeUndefined(); expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...cell, suite: { ...cell.suite, manualOnly: false } }])).toThrow("explicit"); expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...cell, profile: { ...cell.profile, qualificationCandidate: "pi" } }])).toThrow("explicit"); expect(() => buildRunnerE2EProcessEnvironment({}, [{ ...cell, suite: { ...cell.suite, id: "unrelated-manual-suite" } }])).toThrow("explicit"); diff --git a/tests/runner-e2e/history.ts b/tests/runner-e2e/history.ts index 203535ffffc..90476f4ee8e 100644 --- a/tests/runner-e2e/history.ts +++ b/tests/runner-e2e/history.ts @@ -1,4 +1,5 @@ import { isIncompleteFirstTaskResult } from "./case-outcome.js"; +import { classifyLatency } from "./latency-timing.js"; import { summarizeStartupReuse } from "../../packages/adapter-utils/src/startup-reuse.js"; import { validateRetainedRunnerResult } from "./result-validation.js"; import { @@ -29,6 +30,11 @@ export function canonicalExecutionId(id: string) { export function upgradeRunnerResult(result: RunnerE2EResult): RunnerE2EResult { validateRetainedRunnerResult(result); + if (result.latencyProbes) result = { ...result, latencyProbes: result.latencyProbes.map(probe => { + const corrected = classifyLatency(probe, probe.target); + return probe.verdict === corrected.verdict ? corrected + : { ...corrected, recordedVerdict: probe.recordedVerdict ?? probe.verdict }; + }) }; result = { ...result, startupReuse: result.startupReuse ?? (result.runIds ?? []).map(runId => ({ runId, ...summarizeStartupReuse([]), })) }; diff --git a/tests/runner-e2e/installed-cli.test.ts b/tests/runner-e2e/installed-cli.test.ts index 5929e409ee6..b1ab4577a87 100644 --- a/tests/runner-e2e/installed-cli.test.ts +++ b/tests/runner-e2e/installed-cli.test.ts @@ -60,11 +60,11 @@ it("admits only the 20 agreed Copilot cells through normal installed resolution expect(() => assertInstalledCliSelection(env, [{ ...cell, id: `${cell.id}-unreviewed` }])).toThrow("explicit supported"); } }); -it("qualified providers drop ambient admission while pending Copilot retains its exact gate", () => { +it("qualified providers drop ambient admission without granting custom model overrides", () => { for (const cell of cells) expect(buildRunnerE2EProcessEnvironment({ PAPERCLIP_RUNNER_ACPX_QUALIFICATION: "ambient" }, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION).toBeUndefined(); for (const agent of ["copilot"]) { const cell = runnerMatrix.find(e => e.profile.qualificationCandidate === agent)!; - expect(JSON.parse(buildRunnerE2EProcessEnvironment({ PAPERCLIP_RUNNER_ACPX_QUALIFICATION: "ambient" }, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION!)).toEqual([{ agent, model: cell.profile.model }]); + expect(buildRunnerE2EProcessEnvironment({ PAPERCLIP_RUNNER_ACPX_QUALIFICATION: "ambient" }, [cell]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION).toBeUndefined(); } const changed = { ...cells[0]!, profile: { ...cells[0]!.profile, model: "custom/explicit-model" } }; expect(buildRunnerE2EProcessEnvironment({}, [changed]).PAPERCLIP_RUNNER_ACPX_QUALIFICATION).toBeUndefined(); diff --git a/tests/runner-e2e/latency-timing.test.ts b/tests/runner-e2e/latency-timing.test.ts new file mode 100644 index 00000000000..d0e8e08e3e7 --- /dev/null +++ b/tests/runner-e2e/latency-timing.test.ts @@ -0,0 +1,122 @@ +import { describe, expect, it } from "vitest"; +import { armLatencyProbe, classifyLatency, observationTiming } from "./latency-timing.js"; + +const target = { operator: "<=" as const, ms: 2_000 }; +const observed = (lastAbsentMs: number | null, firstPresentMs: number | null, resolutionMs: number | null = 0) => + observationTiming({ event: "acknowledgement", lastAbsentMs, firstPresentMs, resolutionMs }); + +describe("interval latency classification", () => { + it("retains the historical acknowledgement bounds as inconclusive", () => { + expect(classifyLatency(observed(1_901, 2_427), target)).toMatchObject({ + verdict: "inconclusive", lastAbsentMs: 1_901, firstPresentMs: 2_427, + interval: { lower: { ms: 1_901, inclusive: false }, upper: { ms: 2_427, inclusive: true } }, + }); + expect(classifyLatency({ ...observed(52_965, 53_334), event: "first_visible_response" }, { operator: "<=", ms: 30_000 }).verdict).toBe("fail"); + }); + + it.each(["<", "<="] as const)("classifies every endpoint equality for %s", operator => { + // The same number is not sufficient: endpoint inclusion determines equality. + for (const lowerInclusive of [false, true]) for (const upperInclusive of [false, true]) { + const verdict = (lower: number, upper: number) => classifyLatency({ + ...observed(null, null), interval: { + lower: { ms: lower, inclusive: lowerInclusive }, upper: { ms: upper, inclusive: upperInclusive }, + }, + }, { operator, ms: 2_000 }).verdict; + expect(verdict(1_000, 2_000)).toBe(operator === "<=" || !upperInclusive ? "pass" : "inconclusive"); + expect(verdict(2_000, 3_000)).toBe(operator === "<" || !lowerInclusive ? "fail" : "inconclusive"); + expect(verdict(1_999, 2_001)).toBe("inconclusive"); + expect(verdict(2_000, 2_000)).toBe(lowerInclusive && upperInclusive ? (operator === "<=" ? "pass" : "fail") : "inconclusive"); + } + }); + + it.each([ + [null, null, "inconclusive"], [null, 1_999, "pass"], [null, 2_001, "inconclusive"], + [1_999, null, "inconclusive"], [2_000, null, "fail"], [2_001, null, "fail"], + ] as const)("handles missing observations (%s, %s)", (lower, upper, verdict) => { + const result = classifyLatency(observed(lower, upper), target); + expect(result.verdict).toBe(verdict); + expect(result.lastAbsentMs).toBe(lower); + expect(result.firstPresentMs).toBe(upper); + }); + + it.each([ + [-1, 1_000], [NaN, 1_000], [1_000, Infinity], [2_001, 2_000], [2_000, 2_000], + ])("does not turn invalid observations %s, %s into exact latency", (lower, upper) => { + expect(classifyLatency(observed(lower!, upper!), target)).toMatchObject({ verdict: "inconclusive", reason: "invalid_evidence" }); + }); + + it("keeps unknown resolution and widens rounded measurements before grading", () => { + expect(classifyLatency(observed(1_900, 2_000, null), target).verdict).toBe("inconclusive"); + expect(classifyLatency(observed(1_900, 2_000, 1), target)).toMatchObject({ + verdict: "inconclusive", resolutionMs: 1, firstPresentMs: 2_000, + interval: { lower: { ms: 1_899 }, upper: { ms: 2_001 } }, + }); + expect(classifyLatency(observed(0, 1, 1), { operator: "<=", ms: 0 }).verdict).toBe("inconclusive"); + for (const resolution of [-1, NaN, Infinity]) expect(classifyLatency(observed(1, 2, resolution), target).reason).toBe("invalid_evidence"); + for (const ms of [-1, NaN, Infinity]) expect(classifyLatency(observed(1, 2), { ...target, ms }).reason).toBe("invalid_evidence"); + }); + + it("matches an independent finite-domain oracle on strict and inclusive targets", () => { + for (const operator of ["<", "<="] as const) for (const lowerInclusive of [false, true]) for (const upperInclusive of [false, true]) { + for (let lower = 0; lower <= 4; lower++) for (let upper = lower; upper <= 4; upper++) { + const values = Array.from({ length: 9 }, (_, n) => n / 2) + .filter(n => (n > lower || (lowerInclusive && n === lower)) && (n < upper || (upperInclusive && n === upper))); + const passes = values.map(n => operator === "<" ? n < 2 : n <= 2); + const expected = !values.length ? "inconclusive" : passes.every(Boolean) ? "pass" : passes.every(p => !p) ? "fail" : "inconclusive"; + const interval = { lower: { ms: lower, inclusive: lowerInclusive }, upper: { ms: upper, inclusive: upperInclusive } }; + expect(classifyLatency({ ...observed(null, null), interval }, { operator, ms: 2 }).verdict).toBe(expected); + } + } + }); +}); + +describe("monotonic observation probes", () => { + it("measures an edited message's first matching visibility independently of creation and settlement", async () => { + let clock = 10_000; + const now = () => clock; + const reply = armLatencyProbe({ event: "first_visible_response", target, resolutionMs: 0, now }); + const settled = armLatencyProbe({ event: "final_settlement", target, resolutionMs: 0, now }); + // The observer is armed before dispatch; the response can arrive before send returns. + const send = async () => { + clock += 1_901; + await reply.sample(async () => ({ present: false })); + clock = 12_427; + await reply.sample(async () => ({ present: true, messageTimestamps: { createdAt: "2026-01-01T00:00:00Z", editedAt: "2026-01-01T00:00:10Z" } })); + }; + await send(); + clock = 63_334; + await reply.sample(async () => ({ present: false })); + await settled.sample(async () => ({ present: true })); + expect(reply.result()).toMatchObject({ event: "first_visible_response", verdict: "inconclusive", lastAbsentMs: 1_901, firstPresentMs: 2_427, + messageTimestamps: { createdAt: "2026-01-01T00:00:00Z", editedAt: "2026-01-01T00:00:10Z" } }); + expect(settled.result()).toMatchObject({ event: "final_settlement", lastAbsentMs: null, firstPresentMs: 53_334 }); + }); + + it("uses poll start for absence and poll completion for presence", async () => { + let clock = 0; + const probe = armLatencyProbe({ event: "acknowledgement", target, resolutionMs: 0, now: () => clock }); + clock = 1_901; + await probe.sample(async () => { clock = 2_100; return { present: false }; }); + clock = 2_200; + await probe.sample(async () => { clock = 2_427; return { present: true }; }); + expect(probe.result()).toMatchObject({ verdict: "inconclusive", lastAbsentMs: 1_901, firstPresentMs: 2_427 }); + }); + + it("does not count failed reads as absence or use wall-clock message metadata", async () => { + let clock = 0; + const probe = armLatencyProbe({ event: "acknowledgement", target, resolutionMs: 0, now: () => clock }); + clock = 3_000; + await expect(probe.sample(async () => { throw new Error("unavailable"); })).rejects.toThrow("unavailable"); + expect(probe.result()).toMatchObject({ verdict: "inconclusive", lastAbsentMs: null, firstPresentMs: null }); + await probe.sample(async () => ({ present: true, messageTimestamps: { createdAt: "invalid", editedAt: "2099-01-01" } })); + expect(probe.result()).toMatchObject({ verdict: "inconclusive", firstPresentMs: 3_000 }); + }); + + it("rejects a backwards clock instead of clamping latency to zero", async () => { + let clock = 100; + const probe = armLatencyProbe({ event: "acknowledgement", target, resolutionMs: 0, now: () => clock }); + clock = 99; + await probe.sample(async () => ({ present: true })); + expect(probe.result()).toMatchObject({ verdict: "inconclusive", reason: "invalid_evidence" }); + }); +}); diff --git a/tests/runner-e2e/latency-timing.ts b/tests/runner-e2e/latency-timing.ts new file mode 100644 index 00000000000..9b659894983 --- /dev/null +++ b/tests/runner-e2e/latency-timing.ts @@ -0,0 +1,130 @@ +/** Probe timing is an interval, never the timestamp of the poll that found it. */ +export type LatencyEvent = "acknowledgement" | "first_visible_response" | "message_creation" | "final_settlement"; +export type LatencyVerdict = "pass" | "fail" | "inconclusive"; +export interface TimingBound { ms: number; inclusive: boolean } +export interface LatencyTarget { operator: "<" | "<="; ms: number } +export interface LatencyEvidence { + event: LatencyEvent; + interval: { lower: TimingBound | null; upper: TimingBound | null }; + lastAbsentMs: number | null; + firstPresentMs: number | null; + /** Conservative uncertainty on each elapsed observation; null means unknown. */ + resolutionMs: number | null; + invalid?: boolean; + observationFailures?: number; + /** Reads abandoned when the browser observer's shutdown deadline expires. */ + observationTimeouts?: number; + /** Provider wall-clock metadata is retained separately and never measures visibility. */ + messageTimestamps?: { createdAt?: string; editedAt?: string }; +} +export interface LatencyResult extends LatencyEvidence { + target: LatencyTarget; + verdict: LatencyVerdict; + /** Original retained verdict, if report regeneration corrects the timing grade. */ + recordedVerdict?: LatencyVerdict; + reason: "within_target" | "outside_target" | "threshold_overlap" | "missing_observations" | "invalid_evidence" | "unknown_resolution"; +} + +const nonnegative = (value: unknown): value is number => + typeof value === "number" && Number.isFinite(value) && value >= 0; + +export function classifyLatency(evidence: LatencyEvidence, target: LatencyTarget): LatencyResult { + const { lower, upper } = evidence.interval ?? {}; + const result = (verdict: LatencyVerdict, reason: LatencyResult["reason"]): LatencyResult => + ({ ...evidence, target, verdict, reason }); + const validBound = (bound: TimingBound | null) => bound === null + || (bound && nonnegative(bound.ms) && typeof bound.inclusive === "boolean"); + if (evidence.invalid || !nonnegative(target.ms) || !["<", "<="].includes(target.operator) + || !validBound(lower) || !validBound(upper) + || (evidence.lastAbsentMs !== null && !nonnegative(evidence.lastAbsentMs)) + || (evidence.firstPresentMs !== null && !nonnegative(evidence.firstPresentMs)) + || (evidence.lastAbsentMs !== null && evidence.firstPresentMs !== null && evidence.lastAbsentMs > evidence.firstPresentMs) + || (lower && upper && (lower.ms > upper.ms || (lower.ms === upper.ms && !(lower.inclusive && upper.inclusive)))) + || (evidence.resolutionMs !== null && !nonnegative(evidence.resolutionMs))) { + return result("inconclusive", "invalid_evidence"); + } + if (evidence.resolutionMs === null) return result("inconclusive", "unknown_resolution"); + if (!lower && !upper) return result("inconclusive", "missing_observations"); + if (upper && (upper.ms < target.ms || (upper.ms === target.ms && (target.operator === "<=" || !upper.inclusive)))) { + return result("pass", "within_target"); + } + if (lower && (lower.ms > target.ms || (lower.ms === target.ms && (target.operator === "<" || !lower.inclusive)))) { + return result("fail", "outside_target"); + } + return result("inconclusive", "threshold_overlap"); +} + +export function observationTiming(input: Omit): LatencyEvidence { + const uncertainty = input.resolutionMs ?? 0; + return { + ...input, + interval: { + lower: input.lastAbsentMs === null ? null : { ms: Math.max(0, input.lastAbsentMs - uncertainty), inclusive: input.lastAbsentMs - uncertainty < 0 }, + upper: input.firstPresentMs === null ? null : { ms: input.firstPresentMs + uncertainty, inclusive: true }, + }, + }; +} + +/** Arm immediately before dispatch. Inject a monotonic clock for deterministic tests. + * The predicate must describe a persistent event (or a latched event observer). + * A missing/failed read is not an absent observation. */ +export function armLatencyProbe(input: { + event: LatencyEvent; + target: LatencyTarget; + resolutionMs: number; + now?: () => number; +}) { + const now = input.now ?? (() => performance.now()); + const start = now(); + let lastClock = start; + let invalid = !Number.isFinite(start); + let lastAbsentMs: number | null = null; + let firstPresentMs: number | null = null; + let observationFailures = 0; + let messageTimestamps: LatencyEvidence["messageTimestamps"]; + const elapsed = () => { + const current = now(); + if (!Number.isFinite(current) || current < lastClock) invalid = true; + lastClock = current; + return current - start; + }; + type Observation = { present: boolean; messageTimestamps?: LatencyEvidence["messageTimestamps"] }; + const beginObservation = () => { + const before = elapsed(); + let completed = false; + return (observation: Observation) => { + if (completed) throw new Error("Observation already completed"); + completed = true; + const after = elapsed(); + if (typeof observation.present !== "boolean" || after < before) invalid = true; + // Concurrent or late reads cannot replace the first positive observation. + if (firstPresentMs !== null) return; + if (observation.present) { + firstPresentMs = after; + messageTimestamps = observation.messageTimestamps; + } else { + lastAbsentMs = Math.max(lastAbsentMs ?? 0, before); + } + }; + }; + return { + beginObservation, + async sample(load: () => Promise) { + if (firstPresentMs !== null) return; + const complete = beginObservation(); + try { complete(await load()); } + catch (error) { observationFailures++; throw error; } + }, + result(): LatencyResult { + return classifyLatency(observationTiming({ event: input.event, lastAbsentMs, firstPresentMs, + resolutionMs: input.resolutionMs, ...(invalid ? { invalid: true } : {}), + ...(observationFailures ? { observationFailures } : {}), + ...(messageTimestamps ? { messageTimestamps } : {}) }), input.target); + }, + }; +} + +export function latencyIntervalLabel(evidence: LatencyEvidence): string { + const { lower, upper } = evidence.interval; + return `${lower?.inclusive ? "[" : "("}${lower?.ms ?? "unknown"}, ${upper?.ms ?? "unknown"}${upper?.inclusive ? "]" : ")"} ms`; +} diff --git a/tests/runner-e2e/report.test.ts b/tests/runner-e2e/report.test.ts index ff0ed5ff807..2677ec7d3b6 100644 --- a/tests/runner-e2e/report.test.ts +++ b/tests/runner-e2e/report.test.ts @@ -6,6 +6,7 @@ import path from "node:path"; import { afterEach, describe, expect, it } from "vitest"; import { STARTUP_REUSE_LAYERS, STARTUP_REUSE_SCHEMA, summarizeStartupReuse } from "../../packages/adapter-utils/src/startup-reuse.js"; import type { RunnerE2EResult } from "./types.js"; +import { classifyLatency, observationTiming } from "./latency-timing.js"; const execFileAsync = promisify(execFile); const repositoryRoot = path.resolve(import.meta.dirname, "../.."); @@ -19,6 +20,41 @@ afterEach(async () => { }); describe("runner E2E report aggregation", () => { + it("corrects overconfident timing verdicts without changing retained bounds or original files", async () => { + const root = await mkdtemp(path.join(os.tmpdir(), "runner-latency-report-")); + cleanupDirectories.push(root); + const executionId = "core-compatibility.runner-codex.local.message-marker"; + const directory = path.join(root, "attempt-1"); + await mkdir(directory); + const acknowledgement = classifyLatency(observationTiming({ event: "acknowledgement", lastAbsentMs: 1_901, firstPresentMs: 2_427, resolutionMs: 0 }), { operator: "<=", ms: 2_000 }); + const response = classifyLatency(observationTiming({ event: "first_visible_response", lastAbsentMs: 52_965, firstPresentMs: 53_334, resolutionMs: 0 }), { operator: "<=", ms: 30_000 }); + const result: RunnerE2EResult = { + schema: "paperclip.runner-e2e.result/v2", executionId, suiteId: "core-compatibility", attempt: 1, status: "passed", + profileId: "runner-codex", environmentId: "local", caseId: "message-marker", provider: "codex", model: "fixture-model", runtimeMode: "native", + startedAt: "2026-10-18T00:00:00Z", finishedAt: "2026-10-18T00:01:00Z", durationMs: 60_000, cleanup: "passed", + // An old report called the crossing interval a failure (or a pass). + latencyProbes: [{ ...acknowledgement, verdict: "fail", reason: "outside_target", observationTimeouts: 1 }, { ...acknowledgement, verdict: "pass", reason: "within_target" }, response], + }; + const raw = JSON.stringify(result); + await writeFile(path.join(directory, "result.json"), raw); + await writeFile(path.join(directory, "final-state.png"), "fixture-png"); + await writeFile(path.join(directory, "evidence-manifest.json"), JSON.stringify({ files: ["final-state.png"], leaks: [], missing: [] })); + const output = path.join(root, "merged"); + await execFileAsync(process.execPath, [path.join(repositoryRoot, "cli/node_modules/tsx/dist/cli.mjs"), path.join(repositoryRoot, "tests/runner-e2e/report.ts")], { + cwd: repositoryRoot, env: { ...process.env, PAPERCLIP_RUNNER_E2E_REPORT_ROOT: root, PAPERCLIP_RUNNER_E2E_REPORT_OUT: output, PAPERCLIP_RUNNER_E2E_EXPECTED_IDS: JSON.stringify([executionId]) }, + }); + const normalized = JSON.parse(await readFile(path.join(output, "normalized-results.json"), "utf8")); + expect(normalized.results[0].latencyProbes).toEqual([ + { ...acknowledgement, recordedVerdict: "fail", observationTimeouts: 1 }, { ...acknowledgement, recordedVerdict: "pass" }, response, + ]); + expect(normalized.passed).toBe(1); + expect(await readFile(path.join(directory, "result.json"), "utf8")).toBe(raw); + const dashboard = await readFile(path.join(output, "index.html"), "utf8"); + expect(dashboard).toContain("inconclusive"); + expect(dashboard).toContain("(1901, 2427] ms"); + expect(dashboard).toContain("(52965, 53334] ms"); + expect(dashboard).toContain("first_visible_response"); + }); it("retains full reuse and a workspace-only invalidation in the generated report", async () => { const root = await mkdtemp(path.join(os.tmpdir(), "runner-reuse-report-")); cleanupDirectories.push(root); diff --git a/tests/runner-e2e/response-timing.test.ts b/tests/runner-e2e/response-timing.test.ts new file mode 100644 index 00000000000..062250c47ab --- /dev/null +++ b/tests/runner-e2e/response-timing.test.ts @@ -0,0 +1,119 @@ +import type { Page } from "@playwright/test"; +import { afterEach, expect, it, vi } from "vitest"; +import { armResponseTiming } from "./response-timing.js"; + +afterEach(() => { vi.unstubAllGlobals(); vi.useRealTimers(); }); + +it("starts observation before dispatch and drains without overlapping reads on teardown", async () => { + vi.useFakeTimers(); + const absent = { response: false, acknowledgement: false }; + let complete: (value: typeof absent) => void = () => {}; + const read = vi.fn().mockImplementationOnce(() => new Promise(resolve => { complete = resolve; })) + .mockResolvedValue(absent); + const locator = { getByTestId: () => locator, evaluateAll: read }; + const timing = armResponseTiming({ page: locator as unknown as Page }); + expect(read).toHaveBeenCalledTimes(1); // No dispatch or awaited acknowledgement yet. + await vi.advanceTimersByTimeAsync(1_000); + expect(read).toHaveBeenCalledTimes(1); + let stopped = false; + const stopping = timing.stop().then(() => { stopped = true; }); + await vi.advanceTimersByTimeAsync(500); + expect(stopped).toBe(false); + expect(read).toHaveBeenCalledTimes(1); + complete(absent); + await stopping; + expect(stopped).toBe(true); + // One final read after draining the in-flight request, then no more ticks. + expect(read).toHaveBeenCalledTimes(2); + await vi.advanceTimersByTimeAsync(1_000); + expect(read).toHaveBeenCalledTimes(2); +}); + +it.each(["pending", "final"])("bounds shutdown when the %s read never returns and ignores late completions", async phase => { + vi.useFakeTimers(); + const absent = { response: false, acknowledgement: false }; + let complete!: (value: typeof absent) => void; + const stuck = () => new Promise(resolve => { complete = resolve; }); + const read = phase === "pending" ? vi.fn(stuck) : vi.fn().mockResolvedValueOnce(absent).mockImplementation(stuck); + const locator = { getByTestId: () => locator, evaluateAll: read }; + const timing = armResponseTiming({ page: locator as unknown as Page, acknowledgementTarget: { operator: "<=", ms: 2_000 } }); + await vi.advanceTimersByTimeAsync(0); + const stopping = timing.stop(); + await vi.advanceTimersByTimeAsync(1_000); + await stopping; + const evidence = timing.results(); + for (const probe of evidence.filter(probe => probe.event !== "final_settlement")) { + expect(probe).toMatchObject({ verdict: "inconclusive", firstPresentMs: null, observationFailures: 1, observationTimeouts: 1 }); + expect(probe.lastAbsentMs).toBe(phase === "pending" ? null : 0); + } + expect(read).toHaveBeenCalledTimes(phase === "pending" ? 1 : 2); + complete({ response: true, acknowledgement: true }); + await vi.advanceTimersByTimeAsync(1_000); + await timing.stop(); + await timing.observeResponse(locator as unknown as Page); + expect(timing.results()).toEqual(evidence); + expect(read).toHaveBeenCalledTimes(phase === "pending" ? 1 : 2); + expect(vi.getTimerCount()).toBe(0); +}); + +it("observes edited visible text separately from a platform acknowledgement and final settlement", async () => { + let clock = 0; + let receipt = true; + let text = "Platform receipt"; + let visible = true; + vi.stubGlobal("getComputedStyle", () => ({ display: "block", visibility: visible ? "visible" : "hidden" })); + const element = { + closest: () => ({ querySelector: () => receipt ? {} : null }), + get textContent() { return text; }, + getClientRects: () => visible ? [{}] : [], + }; + const locator = { + getByTestId: () => locator, + evaluateAll: async (read: (elements: Element[]) => unknown) => read([element as unknown as Element]), + }; + const page = locator as unknown as Page; + const timing = armResponseTiming({ now: () => clock }); + clock = 1_900; + const firstSettlement = timing.beginSettlement(); + await timing.observeResponse(page); + firstSettlement({ present: false }); + // The same message now has substantive content; creation time does not + // change. Hidden content is still not a visible response. + receipt = false; + text = "The answer"; + visible = false; + clock = 29_900; + await timing.observeResponse(page); + visible = true; + clock = 30_100; + await timing.observeResponse(page); + clock = 52_965; + const lastAbsent = timing.beginSettlement(); + clock = 53_000; + lastAbsent({ present: false }); + const present = timing.beginSettlement(); + clock = 53_334; + present({ present: true }); + expect(timing.results()).toMatchObject([ + { event: "first_visible_response", verdict: "inconclusive", lastAbsentMs: 29_900, firstPresentMs: 30_100, resolutionMs: 1 }, + { event: "final_settlement", verdict: "fail", lastAbsentMs: 52_965, firstPresentMs: 53_334 }, + ]); +}); + +it("uses the same observation bounds for an explicitly expected acknowledgement", async () => { + let clock = 0; + let acknowledgement = false; + const read = vi.fn(async () => ({ response: false, acknowledgement })); + const locator = { getByTestId: () => locator, evaluateAll: read }; + const timing = armResponseTiming({ now: () => clock, acknowledgementTarget: { operator: "<=", ms: 2_000 } }); + clock = 1_901; + await timing.observeResponse(locator as unknown as Page); + clock = 2_427; + acknowledgement = true; + await timing.observeResponse(locator as unknown as Page); + expect(read).toHaveBeenCalledTimes(2); // One snapshot per poll shared by both events. + expect(timing.results().find(probe => probe.event === "acknowledgement")).toMatchObject({ + verdict: "inconclusive", lastAbsentMs: 1_901, firstPresentMs: 2_427, + interval: { lower: { ms: 1_900, inclusive: false }, upper: { ms: 2_428, inclusive: true } }, + }); +}); diff --git a/tests/runner-e2e/response-timing.ts b/tests/runner-e2e/response-timing.ts new file mode 100644 index 00000000000..f5689e7b45e --- /dev/null +++ b/tests/runner-e2e/response-timing.ts @@ -0,0 +1,102 @@ +import type { Page } from "@playwright/test"; +import { armLatencyProbe, type LatencyTarget } from "./latency-timing.js"; + +/** Browser observations, independent of provider creation/edit timestamps and run settlement. + * Used only by the explicit latency diagnostic; these are not Slack delivery probes. */ +export function armResponseTiming(input: { now?: () => number; page?: Page; acknowledgementTarget?: LatencyTarget } = {}) { + const common = { now: input.now, resolutionMs: 1 }; + const response = armLatencyProbe({ ...common, event: "first_visible_response", target: { operator: "<=", ms: 30_000 } }); + const settlement = armLatencyProbe({ ...common, event: "final_settlement", target: { operator: "<=", ms: 30_000 } }); + // Only measure acknowledgement when the caller expects that feature. The + // Daytona response diagnostic does not enable receipts or measure Slack. + const acknowledgement = input.acknowledgementTarget + ? armLatencyProbe({ ...common, event: "acknowledgement", target: input.acknowledgementTarget }) : undefined; + const shutdown = new AbortController(); + const timeouts = new Map, number>(); + let stopped = false; + const observeResponse = async (page: Page) => { + if (stopped || shutdown.signal.aborted) return; + const observing = [response, ...(acknowledgement ? [acknowledgement] : [])] + .filter(probe => probe.result().firstPresentMs === null); + if (!observing.length) return; + const read = () => page.getByTestId("task-chat-thread") + .getByTestId("task-chat-agent-bubble").evaluateAll(elements => { + const visible = { response: false, acknowledgement: false }; + for (const element of elements) { + // Receipt details live beside the bubble inside its thread anchor. + // A platform receipt is not the agent's first substantive response. + const anchor = element.closest("[data-thread-anchor]"); + const receipt = anchor?.querySelector('[aria-label="Message details"]'); + const style = getComputedStyle(element); + if (element.textContent?.trim() && element.getClientRects().length > 0 + && style.visibility !== "hidden" && style.display !== "none") { + if (receipt) visible.acknowledgement = true; + else visible.response = true; + } + } + return visible; + }); + let resolve!: (value: Awaited>) => void; + let reject!: (error: unknown) => void; + const snapshot = new Promise>>((yes, no) => { resolve = yes; reject = no; }); + // Both lower observations must precede the shared read, including the + // second probe. Starting that probe after read() could overstate absence. + const samples = Promise.all([ + response.sample(async () => ({ present: (await snapshot).response })), + acknowledgement?.sample(async () => ({ present: (await snapshot).acknowledgement })), + ]); + const abandon = () => { + for (const probe of observing) timeouts.set(probe, (timeouts.get(probe) ?? 0) + 1); + // Reject the shared snapshot so a late browser completion cannot alter + // evidence after cleanup resumes. The browser operation itself may still + // be running; do not start another read after this deadline. + reject(new Error("Latency observer shutdown deadline exceeded")); + }; + shutdown.signal.addEventListener("abort", abandon, { once: true }); + try { + try { read().then(resolve, reject); } catch (error) { reject(error); } + await samples; + } finally { + shutdown.signal.removeEventListener("abort", abandon); + } + }; + let pending: Promise | undefined; + let timer: ReturnType | undefined; + let stopping: Promise | undefined; + if (input.page) { + const page = input.page; + const tick = () => { + if (pending) return; + // A failed browser read is counted by the probe, never recorded as absence. + pending = observeResponse(page).catch(() => {}).finally(() => { + pending = undefined; + if (response.result().firstPresentMs !== null + && (!acknowledgement || acknowledgement.result().firstPresentMs !== null)) clearInterval(timer); + }); + }; + tick(); // The first read starts before dispatch, not after its acknowledgement. + timer = setInterval(tick, 100); + } + return { + beginSettlement: () => settlement.beginObservation(), + observeResponse, + stop() { + return stopping ??= (async () => { + clearInterval(timer); + // One deadline covers both draining and the final observation. Abort + // only our snapshot wait, leaving page teardown to the fixture owner. + const deadline = setTimeout(() => shutdown.abort(), 1_000); + try { + await pending; + if (input.page) await observeResponse(input.page).catch(() => {}); + } finally { + stopped = true; + clearTimeout(deadline); + } + })(); + }, + results: () => [response, settlement, ...(acknowledgement ? [acknowledgement] : [])].map(probe => ({ + ...probe.result(), ...(timeouts.has(probe) ? { observationTimeouts: timeouts.get(probe)! } : {}), + })), + }; +} diff --git a/tests/runner-e2e/result-validation.ts b/tests/runner-e2e/result-validation.ts index 577b5ea059c..bea69688fd2 100644 --- a/tests/runner-e2e/result-validation.ts +++ b/tests/runner-e2e/result-validation.ts @@ -57,6 +57,26 @@ const date: Rule = (value, at) => { string(value, at); if (!Number.isFinite(Date.parse(value as string))) invalid(at); }; +const finite: Rule = (value, at) => { + if (typeof value !== "number" || !Number.isFinite(value)) invalid(at); +}; +// Finite invalid bounds remain inspectable evidence with an inconclusive verdict. +const timingBound = nullable(shape({ ms: finite, inclusive: boolean })); +const latencyProbe: Rule = (value, at) => { + shape({ + event: oneOf("acknowledgement", "first_visible_response", "message_creation", "final_settlement"), + interval: shape({ lower: timingBound, upper: timingBound }), + lastAbsentMs: nullable(finite), firstPresentMs: nullable(finite), resolutionMs: nullable(finite), + invalid: optional(boolean), + observationFailures: optional(integer), + observationTimeouts: optional(integer), + messageTimestamps: optional(shape({ createdAt: optional(string), editedAt: optional(string) })), + target: shape({ operator: oneOf("<", "<="), ms: finite }), + verdict: oneOf("pass", "fail", "inconclusive"), + recordedVerdict: optional(oneOf("pass", "fail", "inconclusive")), + reason: oneOf("within_target", "outside_target", "threshold_overlap", "missing_observations", "invalid_evidence", "unknown_resolution"), + })(value, at); +}; const url: Rule = (value, at) => { string(value, at); try { @@ -195,6 +215,7 @@ const fields = { issueId: optional(string), issueIdentifier: optional(nullable(string)), runIds: optional(array(string)), + latencyProbes: optional(array(latencyProbe)), startupReuse: optional(array(shape({ runId: string, warmth: oneOf("cold", "warm", "partial_reuse", "unknown"), diff --git a/tests/runner-e2e/runner.spec.ts b/tests/runner-e2e/runner.spec.ts index 355a29abc45..04dfd9f18e6 100644 --- a/tests/runner-e2e/runner.spec.ts +++ b/tests/runner-e2e/runner.spec.ts @@ -40,6 +40,7 @@ import { runRepositorySkillsFlow } from "./repository-skills.js"; import { captureStockHarness, gradeStockHarness, gradeStockHire } from "./stock-harness.js"; import { verifyStockHarnessPreflight, STOCK_PREFLIGHT_ENV } from "./stock-harness-admission.js"; import { createTaskThroughUi, submitTaskReply } from "./user-actions.js"; +import { armResponseTiming } from "./response-timing.js"; import { projectFirstTaskResult, runFirstTaskFlow, setupFirstTaskFixtures } from "./first-task-flow.js"; import { runChatFlow } from "./chat-flow.js"; @@ -647,6 +648,7 @@ for (const execution of executions) { }; let firstTaskEvidence: RunnerE2EResult["firstTask"]; let turnTimings: NonNullable | undefined; + let responseTiming: ReturnType | undefined; let startupReuse: RunnerE2EResult["startupReuse"]; const turnSubmissionTimesMs: number[] = []; const screenshots: NonNullable = []; @@ -1238,6 +1240,8 @@ for (const execution of executions) { workMode: execution.task.workMode, projectName: fixtures.project?.name, requireExplicitTitle: execution.suite.id === "task-titles" && Boolean(title), + beforeDispatch: execution.suite.id === "codie-latency-diagnostic" + ? () => { responseTiming = armResponseTiming({ page }); } : undefined, }); turnSubmissionTimesMs.push(createdTask.submittedAtMs); @@ -1290,6 +1294,7 @@ for (const execution of executions) { ); const loadTaskState = async () => { + const observeSettlement = responseTiming?.beginSettlement(); const [currentIssue, runs, comments, interactions] = await Promise.all([ api.get(`/api/issues/${issue!.id}`), api.get( @@ -1302,6 +1307,9 @@ for (const execution of executions) { ), api.get(`/api/issues/${issue!.id}/interactions`), ]); + observeSettlement?.({ present: currentIssue.status === execution.task.expectedTerminalState.issue + && matchingRuns(runs, currentIssue).length >= minimumRunCount(execution.task) + && matchingRuns(runs, currentIssue).every(run => TERMINAL_RUN_STATUSES.has(run.status)) }); return { currentIssue, taskRuns: matchingRuns(runs, currentIssue), @@ -3018,6 +3026,7 @@ for (const execution of executions) { } } } finally { + await responseTiming?.stop(); await reviewProvider?.close(); try { await writeSanitizedJson( @@ -3182,6 +3191,7 @@ for (const execution of executions) { issueIdentifier: issue?.identifier ?? null, runIds: selectedRuns.map((run) => run.id), ...(turnTimings ? { turnTimings } : {}), + ...(responseTiming ? { latencyProbes: responseTiming.results() } : {}), ...(startupReuse ? { startupReuse } : {}), startedAt, finishedAt: new Date(finishedAtMs).toISOString(), diff --git a/tests/runner-e2e/types.ts b/tests/runner-e2e/types.ts index f5338c138f2..cd4c657aeac 100644 --- a/tests/runner-e2e/types.ts +++ b/tests/runner-e2e/types.ts @@ -312,6 +312,7 @@ export interface RunnerE2EResult { issueId?: string; issueIdentifier?: string | null; runIds?: string[]; + latencyProbes?: import("./latency-timing.js").LatencyResult[]; startupReuse?: Array<{ runId: string } & import("../../packages/adapter-utils/src/startup-reuse.js").StartupReuseSummary>; turnTimings?: Array<{ turn: number; diff --git a/tests/runner-e2e/user-actions.ts b/tests/runner-e2e/user-actions.ts index bba252f098d..7ba0d18ecff 100644 --- a/tests/runner-e2e/user-actions.ts +++ b/tests/runner-e2e/user-actions.ts @@ -28,6 +28,7 @@ export async function createTaskThroughUi(input: { projectName?: string; requireExplicitTitle?: boolean; attachments?: readonly string[]; + beforeDispatch?: () => void; }) { // Search's public creation action exposes the explicit title field. Strict // native-operation fixtures use it so automatic task naming is not an extra @@ -92,7 +93,6 @@ export async function createTaskThroughUi(input: { await projectSearch.fill(input.projectName); await input.page.getByText(input.projectName, { exact: true }).last().click(); } - const submittedAtMs = Date.now(); if (input.attachments?.length) { const chooser = input.page.waitForEvent("filechooser"); const upload = dialog.getByRole("button", { name: "Upload", exact: true }); @@ -106,6 +106,8 @@ export async function createTaskThroughUi(input: { } // The prompt-only composer generates a provisional title which the provider // can rename immediately. Bind the fixture to the actual creation response. + input.beforeDispatch?.(); + const submittedAtMs = Date.now(); const [response] = await Promise.all([ input.page.waitForResponse(response => response.request().method() === "POST" && /^\/api\/companies\/[^/]+\/issues$/.test(new URL(response.url()).pathname)),