Uh oh!
There was an error while loading. Please reload this page.
[core] [test-only] Poll for the deferred check instead of sleeping past it - #3507
Conversation
`Unit Tests (windows-latest)` had two independent failures. #3503 fixed the world-local one. This is the other: `events-consumer.test.ts`, rotating between lines 1005 and 1123 across main runs 31626621981 and 31631614229. Eleven call sites slept `MIN_DEFERRED_CHECK_DELAY_MS * 4` and then asserted an outcome the deferred unconsumed-event check produces. That check is not on a fixed schedule. It waits for delivery to go idle, which is its own poll loop, and only then arms a `getDeferredCheckDelayMs()` timer, so the sleep is a lower bound on when the timer becomes eligible rather than a guarantee it has run. The helper's own comment already said assertions that a check DID fire should poll instead; every one of the eleven ignored it. Replace the sleep with `afterDeferredCheck`, which polls the assertion block. The positive assertions gate the poll and the negatives alongside them are evaluated once the check is known to have fired, which is what they mean. Reproduced without a Windows runner by raising the test's stubbed delay 20x, which makes the fixed sleep too short by construction: the old file fails at exactly 1005 and 1123, the two lines CI reports, and the new file passes 45/45 at the same delay.
🦋 Changeset detectedLatest commit: f446a2a The changes in this PR will be included in the next version bump. This PR includes changesets to release 0 packagesWhen changesets are added to this PR, you'll see the packages that this PR includes changesets for and the associated semver types Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
🧪 E2E Test Results✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ vercel-multi-region
|
📊 Workflow Benchmarkscommit Backend:
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 165564ms → this run 167484ms (Δ +1920ms, +1%) ℹ️ Metric definitions & methodologyThe collapsed STSO distribution section above buckets every step gap of the sequential-steps run (not a sampled window), split by whether the step ending the gap ran inline — in the same warm process as the step before it, so the gap is pure framework overhead — or after a queue-hop — the first step of a fresh process, which pays queue dispatch, client reinit and event-log replay. Bars overlay the two runs: Best/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · SL: stream latency (in-deployment write → read propagation, readAt - writtenAt) · SO: stream overhead (end-to-end write+consume time beyond the modelled generation window) Scenarios — step: one trivial no-op step, no stream; no hooks, so the run stays in turbo mode (in-process fast path) · stream: one streaming step; no hooks, so the run stays in turbo mode (in-process fast path) · hook + stream: registers a hook before one step, which exits turbo mode (dispatch path) · 1020 steps: 1020 trivial sequential steps; STSO is measured between consecutive steps in the given step ranges, and WO is the whole-run overhead outside step bodies · stream latency: parallel reader/writer steps on a dedicated stream; SL is the in-deployment write->read propagation (readAt - writtenAt) · stream overhead (text): writer streams 300 variable-length text token deltas paced at 100/s for 3s (a haiku-size LLM's token throughput) while a parallel reader drains the whole stream; SO is the end-to-end write+consume time beyond the 3s generation window (overhead/backpressure) · stream overhead (structured): same workload as stream overhead (text), but each delta is an AI-SDK-style structured object ({ type: 'text-delta', id, text }) instead of a raw string, so the SO gap vs the text scenario is the added serialization cost 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 · SL 50/60/125 · SO 250/500/1000 All metrics are measured from deployment-side timestamps only. Runs are triggered by an in-deployment route that stamps the anchor ( Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 6 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
Uh oh!
There was an error while loading. Please reload this page.
No backport to This is a test-only flaky-test fix, which would normally qualify, but the tests it repairs do not exist on To override, re-run the Backport to stable workflow manually via |
Unit Tests (windows-latest)was red onmainwith two independent failures.#3503 fixed the world-local one. This is the other, and it is why that lane
stayed red after #3503 landed:
Main runs 31626621981 and 31631614229, rotating between lines 1005 and 1123.
The defect
Eleven call sites slept
MIN_DEFERRED_CHECK_DELAY_MS * 4and then asserted anoutcome the deferred unconsumed-event check produces. That check has no fixed
schedule: it first waits for delivery to go idle, which is its own poll loop,
and only after that resolves does it arm a
getDeferredCheckDelayMs()timer.The sleep bounds when the timer becomes eligible, not when it has run, and on
a loaded runner with a coarse timer it is not close.
The helper's own doc comment already said so:
All eleven call sites ignored it.
The fix
afterDeferredCheck(assertions)polls the whole assertion block instead. Thepositive assertions gate the poll, and the negatives alongside them are then
evaluated at the moment the check is known to have fired, which is what they
were meant to assert. Where a site already had a trailing
vi.waitFor, that isleft outside the block.
Evidence
Reproduced without a Windows runner. The test stubs
WORKFLOW_DEFERRED_CHECK_DELAY_MStoMIN_DEFERRED_CHECK_DELAY_MS; raisingthat stub 20x makes the fixed sleep too short by construction:
Those are exactly the two lines CI reports. At the normal stub both pass, so the
old file is not wrong on a fast machine, only unbounded on a slow one.
Test-only, so the changeset is empty.