Files
PaperClipAI/tests/runner-e2e/response-timing.test.ts
T
DottaandPaperclip 53732c811b 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 <noreply@paperclip.ing>
2026-10-21 08:31:22 -05:00

120 lines
5.5 KiB
TypeScript

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<typeof absent>(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<typeof absent>(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 } },
});
});