Skip to content

test(ci): drive the npm-verify retry loop on a virtual clock - #436

Merged
jpr5 merged 1 commit into
mainfrom
fix/npm-verify-deterministic-timing
Sep 13, 2026
Merged

test(ci): drive the npm-verify retry loop on a virtual clock#436
jpr5 merged 1 commit into
mainfrom
fix/npm-verify-deterministic-timing

Conversation

@jpr5

@jpr5 jpr5 commented Sep 12, 2026

Copy link
Copy Markdown
Contributor

Why

The EXECUTED: the retry window is honoured, not multiplied by a longer deadline negative control in src/__tests__/npm-publish-verify-workflow.test.ts asserted on real elapsed wall clock. It is red on main @ 252a4cc (run 34597377003, legs test (20) and test (26)), which puts a red X on every open PR — including the three external-contributor PRs #433/#434/#435.

Widening the window was already tried (20e0d88) and is not the fix. The step's body computes ELAPSED from date +%s, which is whole-second: if START is sampled just before a second boundary, the loop's own arithmetic crosses a 3s deadline after as little as ~2.0s of real time. That is sub-second phase, not runner load — it fails on an idle laptop.

RED

On origin/main, unloaded, 25 consecutive runs of just that test: 8 failed.

RUN 6: RED  → expected 2469 to be greater than or equal to 2800
RUN 7: RED  → expected 2501 to be greater than or equal to 2800
RUN 8: RED  → expected 2492 to be greater than or equal to 2800
RUN 9: RED  → expected 2475 to be greater than or equal to 2800
RUN 16: RED → expected 2474 to be greater than or equal to 2800
RUN 17: RED → expected 2539 to be greater than or equal to 2800
RUN 21: RED → expected 2567 to be greater than or equal to 2800
RUN 22: RED → expected 2466 to be greater than or equal to 2800

Fix

date and sleep are external commands, so they can be stubbed on PATH exactly like the existing npm stub. The step's run: body is still executed verbatim and unmodified — only its clock is now the test's.

  • sleep N records N and advances a virtual clock file by N; date +%s reads it.
  • Timing becomes an observable: the exact attempt count and the exact backoff schedule the loop issued. No assertion in the file touches wall clock any more (elapsedMs is gone from Observation).
  • The observations now run at the shipped 300s/5s/30s defaults instead of a shrunken 1s window, so what is tested is what CI runs. A five-minute window costs nothing on a virtual clock — the whole file got faster, ~30s → ~8s.
  • The default schedule is asserted exactly: attempts at t+0,5,15,35,65,95,125,155,185,215,245,275,305, sleeps [5,10,20,30,30,30,30,30,30,30,30,30], failing at attempt 13.
  • "Honoured, not multiplied" is now a property that no runner speed can break: a shorter deadline stops the loop sooner, and overshoot past any deadline is < deadline + MAX_DELAY (one backoff step).
  • A body that stopped sleeping would spin against a clock that never advances, so the npm stub jumps the clock after 40 attempts — turning a hang into a legible failure.

GREEN

20 consecutive green runs of the file: 12 standalone, then 8 more concurrently with the full npx vitest run (189 files / 5804 tests, exit 0) hammering the same machine. Zero failures.

Mutation proof — it still bites

Both mutations applied to the real publish-release.yml guard:

Mutation Result
Retry loop deleted (while :; do → single pass, i.e. the pre-fix "ask once" body) RED — 5 of 10 tests fail (expected 1 to be 2, expected 1 to be 3, expected +0 to be 1 ×3)
Deadline's exit 1exit 0 RED — 3 of 10 tests fail (expected +0 to be 1 ×3)

Workflow restored afterwards; this PR changes one file, the test.

Other wall-clock assertions in the file

Yes — three more, all fixed the same way: the never appears FAILS control (elapsedMs >= 4000), the FAILS FAST control (elapsedMs < 10_000), and the loose attempts > N bounds. All are now exact attempt counts and exact sleep schedules.

Gates (raw exit codes)

Gate Exit
prettier --check 0
npx eslint . 0
pnpm typecheck 0
npx vitest run (full) 0
npx commitlint --from origin/main --to HEAD 0
npx actionlint 1 — pre-existing on main, SC2086 in changelog-radar.yml / test-drift.yml; no workflow file is touched by this PR

🤖 Generated with Claude Code

https://claude.ai/code/session_01AvkmhXVLqSSEW6FvPQHSu5

The "retry window is honoured" negative control asserted on real elapsed
wall clock (>= 2800ms for a 3s deadline) and went red on main at 252a4cc,
poisoning every open PR. Widening the window was already tried in 20e0d88
and is not a fix: the body computes ELAPSED from `date +%s`, which is
whole-second, so START landing just before a second boundary makes the
loop exit a full second of real time early. Locally, unloaded, the old
assertion failed 8 times in 25 runs.

Stub `date` and `sleep` on PATH next to the existing `npm` stub, so the
step's own body runs unmodified against a clock the test owns. Timing is
now an observable: the exact attempt count and the exact backoff schedule
the loop issued. Nothing asserts wall clock any more, and the
observations run at the SHIPPED 300s/5s/30s defaults instead of a
shrunken window, so what is tested is what CI runs.

A body that stopped sleeping would spin against a clock that never
advances, so the npm stub jumps the clock after 40 attempts to turn that
hang into a legible failure.

Mutation-checked: deleting the retry loop fails 5 of 10; flipping the
deadline's `exit 1` to `exit 0` fails 3 of 10.
@pkg-pr-new

pkg-pr-new Bot commented Sep 12, 2026

Copy link
Copy Markdown

Open in StackBlitz

npm i https://pkg.pr.new/@copilotkit/aimock@436

commit: c569c9e

@jpr5
jpr5 merged commit fca797f into main Sep 13, 2026
30 checks passed
@jpr5
jpr5 deleted the fix/npm-verify-deterministic-timing branch September 13, 2026 00:02
jpr5 added a commit to Ayush7614/aimock that referenced this pull request Sep 13, 2026
… dimensions

The new 400s caught four real 500s (`input: 123`, `input: {}`, `dimensions: -1`,
`dimensions: 1.5`, plus the moderation/search/rerank `.slice is not a function`
crashes). Those stay. But the guards were drawn tighter than the wire formats
these endpoints serve, turning a set of working 200s into 400s. On a mock, a 400
where the real provider returns 200 surfaces as the consumer's bug.

Narrowed to the shapes the vendored SDK types actually declare invalid:

- `normalizeStringArrayInput` accepts token arrays. `EmbeddingCreateParams.input`
  is `string | Array<string> | Array<number> | Array<Array<number>>`; tiktoken
  chunkers emit the latter two. They are folded into a deterministic string key
  instead of being handed raw to `createHash().update()`.
- `normalizeTextInput` accepts multimodal moderation parts (`ModerationCreateParams
  .input` includes `Array<ModerationMultiModalInput>`) and keeps the previous
  `join(" ")` semantics for every other array element, so no array payload that
  returned 200 starts failing. Only non-string, non-array scalars are rejected —
  exactly the values that used to crash `matchesPattern()`.
- `MAX_EMBEDDING_DIMENSIONS` is no longer an OpenAI model width. `/v1/embeddings`
  also serves Azure and every OpenAI-compatible server routed via COMPAT_SUFFIXES,
  where 4096-dimension models are ordinary. It is now the ECMAScript array-length
  bound (2^32 - 1), which is where `new Array(n)` actually throws RangeError, and
  its literal value is pinned by a test rather than only referenced.
- The `dimensions` check moves back to the deterministic-fallback branch, the only
  path that reads it, so fixture-replay, chaos, strict and record/proxy requests
  are no longer gated on it. `dimensions: null` means unset again.
- The empty-`input`-array rejection is dropped; `input: []` returned 200 before.
- `/search` echoes the raw query back, matching on the normalized string only.
- New 400 envelopes carry `param`, matching the file's existing `code` convention.

Also drops the `npm-publish-verify-workflow.test.ts` hunk, which was a weaker
retry of the flake already fixed in CopilotKit#436 (fca797f deleted `elapsedMs` outright),
and the empty CI-retrigger commit.
jpr5 added a commit to Ayush7614/aimock that referenced this pull request Sep 13, 2026
…de dimensions

The new 400s catch real 500s and those stay. But three guards were drawn tighter
than the wire formats these endpoints serve, turning working 200s into 400s — on
a mock, a 400 where the provider returns 200 surfaces as the consumer's bug.

- normalizeStringArrayInput now accepts number[] and number[][]. Per
  EmbeddingCreateParams.input, `input` is
  `string | Array<string> | Array<number> | Array<Array<number>>`; the token
  forms are what tiktoken chunkers emit. They are folded to a string key rather
  than handed raw to createHash().update().
- normalizeTextInput now accepts any array, joining as the previous
  `Array.isArray(raw) ? raw.join(" ") : raw` did, and reads `.text` out of
  ModerationCreateParams' multimodal parts. Only non-string, non-array values —
  the ones that actually crashed matchesPattern() — still 400.
- MAX_EMBEDDING_DIMENSIONS is no longer an OpenAI model width. /v1/embeddings
  also serves Azure and every OpenAI-compatible server routed through
  COMPAT_SUFFIXES, where 4096-dimension models are ordinary. It is now the
  ECMAScript array-length bound (2**32 - 1), where `new Array(n)` actually
  throws RangeError, and a test pins the literal so it cannot drift.
- The dimensions check moves back onto the deterministic-fallback branch, the
  only path that reads it, so fixture-replay, chaos, strict and record/proxy
  requests are no longer gated on it. `dimensions: null` means unset again.

Also drops the npm-publish-verify-workflow.test.ts hunk — a weaker retry of the
flake already fixed by CopilotKit#436, which deleted elapsedMs outright — and the empty
CI-retrigger commit.
jpr5 added a commit to Ayush7614/aimock that referenced this pull request Sep 13, 2026
…de dimensions

The new 400s catch real 500s and those stay. But several guards were drawn
tighter than the wire formats these endpoints serve, turning working 200s into
400s — on a mock, a 400 where the provider returns 200 surfaces as the
consumer's bug, not ours.

Correctness:

- normalizeEmbeddingInput (renamed from normalizeStringArrayInput, which no
  longer described it) accepts number[] and number[][]. Per
  EmbeddingCreateParams.input, `input` is
  `string | Array<string> | Array<number> | Array<Array<number>>`; the token
  forms are what tiktoken chunkers emit. They are folded to a string key rather
  than handed raw to createHash().update().
- normalizeTextInput accepts any array, joining as the previous
  `Array.isArray(raw) ? raw.join(" ") : raw` did, and reads `.text` out of
  ModerationCreateParams' multimodal parts. Only non-string, non-array values —
  the ones that actually crashed matchesPattern() — still 400.
- MAX_EMBEDDING_DIMENSIONS is no longer an OpenAI model width. /v1/embeddings
  also serves Azure and every OpenAI-compatible server routed through
  COMPAT_SUFFIXES, where 4096-dimension models are ordinary. It is now the
  ECMAScript array-length bound (2**32 - 1), where `new Array(n)` actually
  throws RangeError, and a test pins the literal so it cannot drift.
- The dimensions check moves onto the deterministic-fallback branch, the only
  path that reads it, so fixture-replay, chaos, strict and record/proxy requests
  are no longer gated on it. `dimensions: null` means unset again.
- The `input: []` rejection is dropped. It returned 200 with `data: []` before
  and crashed nothing, so there was no defect behind it.
- The new 400 bodies carry `param` and `code`. The OpenAI SDK's APIError reads
  both straight off the error object, so omitting them hands consumers
  `undefined` where the real API gives a value.
- /search echoes the query it was given again, matching on the normalized string
  only; an array payload was being echoed back as a joined string.
- EmbeddingRequest.input / dimensions and the search/rerank body types are
  `unknown`: they arrive as arbitrary JSON and are validated at runtime, so the
  declared types must not claim a shape the parser cannot guarantee.

Also drops the npm-publish-verify-workflow.test.ts hunk — a weaker retry of the
flake already fixed by CopilotKit#436, which deleted elapsedMs outright — and the empty
CI-retrigger commit.
jpr5 added a commit that referenced this pull request Sep 13, 2026
…te externally (#437)

## The failure

`main` @ `079f37e` failed the `test (24)` leg of **Unit Tests** ([run
34731065578](https://github.com/CopilotKit/aimock/actions/runs/34731065578)):

```
FAIL src/__tests__/publish-pin-workflow.test.ts
 > the PyPI publish path runs no Python bytes it has not pinned
 > EXECUTED against real pip > SUBSTITUTED backend bytes are REFUSED by the repo's own pin
Error: Test timed out in 5000ms.        (file: 21075ms)
```

Not a correctness failure. The test shells out to **real pip** —
deliberately, that is the guard — and inherited vitest's 5000ms default.
It passes on a fast machine and fails on a slow one.

## Audit

Every `src/__tests__/*workflow*.test.ts` and sibling that spawns a
process was measured. Three already state a budget (`fix-drift-workflow`
30s, `unreleased-check-workflow` 30s, `npm-publish-verify-workflow`
60s). Two did not:

| file | slowest test, measured | new budget |
|---|---|---|
| `publish-pin-workflow.test.ts` | 172ms / 183ms warm local pip;
**21075ms** for the file on the CI runner | `60_000` |
| `test-drift-workflow.test.ts` | **3039ms** idle 18-core; **5490ms →
timed out** under concurrent load | `30_000` |

`drift-sync-core.test.ts` also shells out to real `git`, but its slowest
test is 116ms — 43x of headroom under the default. Left alone.
`fix-drift.test.ts` mocks `child_process`. `adoption-wall.test.ts` is
out of scope.

## RED

`test-drift-workflow` at the inherited default, with two full suites
running concurrently:

```
× EXECUTED POSITIVE CONTROL: base exits 0 and 2 stay non-fatal 5490ms
 Test Files  1 failed | 1 passed (2)
      Tests  1 failed | 32 passed (33)
```

`publish-pin-workflow`'s RED is the CI run above — local pip is warm
here and never approaches 5s.

## GREEN

Both files, 5 consecutive runs:

```
run 1 exit=0    Tests  33 passed (33)
run 2 exit=0    Tests  33 passed (33)
run 3 exit=0    Tests  33 passed (33)
run 4 exit=0    Tests  33 passed (33)
run 5 exit=0    Tests  33 passed (33)
```

And once under the exact condition that produced RED — concurrent with
two full suites:

```
CONCURRENT EXIT=0
 Test Files  2 passed (2)
      Tests  33 passed (33)
slowest under load: 4751ms, 4379ms, 3898ms
```

4751ms against a 5000ms budget is the flake, stated plainly.

## The budgets still bite

A raised-so-far-it-can-never-fire timeout is a removed guard. Both were
confirmed against an injected hang (`sleep` in front of the external
call, reverted after):

```
publish-pin  → Test timed out in 60000ms.   Tests  2 failed | 7 passed (9)
test-drift   → Test timed out in 30000ms.   Tests  1 failed | 1 passed | 22 skipped (24)
```

## Deliberately not done

- **No global `testTimeout`** — that would stop genuinely hung tests
from failing everywhere.
- **No stubbing.** These are marked `EXECUTED against real pip` because
running the repo's own pin file against the real resolver *is* the
assertion. What they exercise is unchanged.
- **`npm-publish-verify-workflow.test.ts` untouched** — already fixed in
#436 on a stubbed clock.

## Gates (raw exit codes)

| gate | exit |
|---|---|
| `prettier --check` | 0 |
| `npx eslint .` | 0 |
| `pnpm typecheck` | 0 |
| `npx vitest run` (full) | 0 — 191 passed / 1 skipped, 5864 tests |
| `npx commitlint --from origin/main --to HEAD` | 0 |

🤖 Generated with [Claude Code](https://claude.com/claude-code)

https://claude.ai/code/session_01AvkmhXVLqSSEW6FvPQHSu5
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant