[core] Add the wake-loop scenario to the event log race repro - #4017
Conversation
One sequential loop racing a reusable hook read against a heartbeat sleep, with the concurrency supplied by the driver's resumes (single wakes, bursts, and wakes aimed at the heartbeat deadline) rather than by fan-out. It is the shape of a production run that failed CORRUPTED_EVENT_LOG on an unconsumable wait_created after replays of one immutable prefix diverged non-deterministically: a replay that observes a hook payload ahead of an earlier wait_completed runs a wake cycle where the log recorded a heartbeat, and draws the heartbeat's ordinal for a step. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
🦋 Changeset detectedLatest commit: 9386ce1 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 |
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 147324ms → this run 128659ms (Δ -18665ms, -13%) 📈 CRTT drill-down vs main (RTT distributions & profiles)RTT over stream progress (avg per tenth of stream, bars scaled min→max): RTT by chunk size (avg per log size bin, ~160B → ~12KB serialized, bars scaled min→max): Delivery jitter over stream progress (avg positive CDV per tenth of stream, bars scaled min→max): ℹ️ Metric definitions & methodologyStreams: first-chunk RTT (the stream-open path, before any buffering/backpressure), CRTT percentiles, and worst delivery stall (CDV max). Cells are medians across iterations; per-run values in the artifacts. No 🔴/🟢 marks until targets attach. The collapsed STSO distribution section above buckets every step gap, split inline (same warm process — pure framework overhead) vs queue-hop (fresh process — dispatch, reinit, replay). The collapsed CRTT drill-down: per-variant RTT histograms (fixed log bins, 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) · Fan-out TTFS: fan-out time to first step (in-deployment start() → first of the parallel step bodies to complete) · Fan-out TTLS: fan-out time to last step (in-deployment start() → last of the parallel step bodies to complete, i.e. when the Promise.all resolves) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · CRTT: chunk round-trip time (per-chunk write → read latency, one clock domain: deployment → stream backend → same deployment) · CDV: chunk delay variation / delivery jitter (inter-arrival gap minus inter-write gap per seq-adjacent pair; skew-free; the row is each run's MAX positive value, so one stall moves it) 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 · Promise.all(100 steps): 100 trivial no-op steps started together in a single Promise.all; Fan-out TTFS is the first of them to complete and Fan-out TTLS the last, both from the in-deployment clientStart, so their gap is the spread the runtime adds across the fan-out · paced control (100/s, 60B): the control: 300 tiny (~60B) deltas metronome-paced at 100/s — zero workload structure, so it reads the transport floor and flush cadence, and disambiguates transport-wide vs workload-specific when a replay row moves · size sweep (100/s, 160B-12KB): same pacing as the control with deltas padded in rotation across seven log-spaced sizes (~160B–12KB) — rotation decouples size from stream position, so it isolates whether chunk size causes latency · replay gateway-gpt-5.4-nano-2000t (1x): raw provider SSE cadence captured at the AI gateway boundary (gpt-5.4-nano, the most popular gateway model; per-token deltas p50 208B = the modal production chunk size), replayed exactly as measured — the typical customer's workload; its CDV is the typical customer's real delivery jitter · replay eve-gpt-5.6-sol-2000t (1x): a captured eve turn (gpt-5.6-sol, the most-used demanding eve model; ~2000 output tokens = production p50 turn length) replayed exactly as measured — eve's envelope protocol re-ships the cumulative message so sizes ramp 142B→13KB; the demanding outlier tenant's reality · replay eve-gpt-5.6-sol-2000t (2x): the same eve capture at 2x — the headroom/stress row; real fast-tier models emit the same chunk sizes at proportionally higher rate, so time compression is a faithful speed model · first chunk (pooled): every run's seq-0 RTT pooled across all stream scenarios — the first chunk precedes any workload differentiation, so pooling samples one shared stream-open path with exact percentiles Replay cadences (semantic sha256) — eve-gpt-5.6-sol-2000t 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 All timestamps are deployment-side; runs are triggered in-deployment, so the CI runner and api.vercel.com sit outside every measured window. TTFS = Cold starts stay in the numbers (real bursty-workload latency, inflates P75+); Best is the warm floor. |
🧪 E2E Test Results✅ All tests passed
|
| Passed | Failed | Skipped | Total | |
|---|---|---|---|---|
| ✅ ▲ Vercel Production | 3636 | 0 | 684 | 4320 |
| ✅ 💻 Local Development | 3922 | 0 | 558 | 4480 |
| ✅ 📦 Local Production | 3922 | 0 | 558 | 4480 |
| ✅ 🐘 Local Postgres | 3922 | 0 | 558 | 4480 |
| ✅ 🪟 Windows | 320 | 0 | 0 | 320 |
| ✅ 🌐 Cross-language Conformance | 68 | 0 | 73 | 141 |
| ✅ vercel-http-transport | 817 | 0 | 143 | 960 |
| ✅ vercel-multi-region | 27 | 0 | 0 | 27 |
| ✅ vercel-ws-transport | 553 | 0 | 87 | 640 |
| Total | 17187 | 0 | 2661 | 19848 |
Details by Category
✅ ▲ Vercel Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-node | 132 | 0 | 28 |
| ✅ astro-quickjs | 132 | 0 | 28 |
| ✅ example-node | 132 | 0 | 28 |
| ✅ example-quickjs | 132 | 0 | 28 |
| ✅ express-node | 132 | 0 | 28 |
| ✅ express-quickjs | 132 | 0 | 28 |
| ✅ fastify-node | 132 | 0 | 28 |
| ✅ fastify-quickjs | 132 | 0 | 28 |
| ✅ hono-node | 132 | 0 | 28 |
| ✅ hono-quickjs | 132 | 0 | 28 |
| ✅ nest-node | 132 | 0 | 28 |
| ✅ nest-quickjs | 132 | 0 | 28 |
| ✅ nextjs-turbopack-node | 157 | 0 | 3 |
| ✅ nextjs-turbopack-quickjs | 157 | 0 | 3 |
| ✅ nextjs-webpack-node | 157 | 0 | 3 |
| ✅ nextjs-webpack-quickjs | 157 | 0 | 3 |
| ✅ nitro-node | 132 | 0 | 28 |
| ✅ nitro-quickjs | 132 | 0 | 28 |
| ✅ nuxt-node | 132 | 0 | 28 |
| ✅ nuxt-quickjs | 132 | 0 | 28 |
| ✅ python-node | 66 | 0 | 94 |
| ✅ sveltekit-node | 151 | 0 | 9 |
| ✅ sveltekit-quickjs | 151 | 0 | 9 |
| ✅ tanstack-start-node | 132 | 0 | 28 |
| ✅ tanstack-start-quickjs | 132 | 0 | 28 |
| ✅ vite-node | 132 | 0 | 28 |
| ✅ vite-quickjs | 132 | 0 | 28 |
✅ 💻 Local Development
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 📦 Local Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🐘 Local Postgres
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🪟 Windows
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-quickjs | 160 | 0 | 0 |
✅ 🌐 Cross-language Conformance
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ python | 68 | 0 | 73 |
✅ vercel-http-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ hono | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ nitro | 132 | 0 | 28 |
| ✅ vite | 132 | 0 | 28 |
✅ vercel-multi-region
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack | 27 | 0 | 0 |
✅ vercel-ws-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ vite | 132 | 0 | 28 |
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Sim WorldSimulated world deterministic testing for races. Traces 🟠 world-sim scenario book — 1 fail of 41 total
Full trace: |
About these numbersSizes are gzip; parentheses show the change against
|
Event Log Race Repro
Run History
Config
|
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
A/B: this branch (main) vs the same scenario on
|
| Lane | main (run) | beta.46 (run, branch peter/repro-wake-loop-beta46) |
|---|---|---|
| vercel | 47 completed, 0 corrupt, 1 stuck (slow tail: still writing steps 3s before the 240s cancel; p50 119s, p90 166s at c12) | 41 completed, 6 CORRUPTED_EVENT_LOG, 1 infra |
| world-local | 48 completed | 38 completed, 9 CORRUPTED_EVENT_LOG, 1 stuck |
| world-postgres | 48 completed, 0 divergence WARNs in the app log | 48 completed, 397 divergence WARNs in the app log (every episode recovered within the 3-retry budget) |
So the scenario reproduces the class on the release the incident happened on, and is clean on main across 48+48+48 runs and 6+26+26 more at the default scale (three lanes, PR runs). On beta.46 the corrupted Vercel-lane logs split the same way the analysis predicted: 3 of 6 hold a step bound to the ordinal a sibling writer gave a wait (a flipped replay got to commit), 3 of 6 are self-consistent logs where the flipped replays only diverged, which is the incident's shape.
Two harness notes from the soak:
- The app log on world-postgres shows the divergence rate even when every run completes. The harness's outcome-only view is blind to recovered episodes; counting the
Workflow replay divergedWARNs per lane would make the local lanes a rate signal. Follow-up. - At
concurrency=12the wake-loop's slow tail brushesrunTimeoutMson the Vercel lane. The default scale (c8, 6 attempts) ran 95-140s.
🤖 Generated with Claude Code
|
No backport to This commit adds a brand-new To override, re-run the Backport to stable workflow manually via |
Bisect: the fix is #3879 (
|
| beta.46 + | vercel | world-local | world-postgres |
|---|---|---|---|
| #3879 only (run) | 48 completed, 0 corrupt | 48 completed, 0 divergence WARNs | 48 completed, 0 divergence WARNs |
| #3841 only (run) | 44 completed, 4 corrupt | 40 completed, 4 corrupt, 4 stuck, 187 WARNs | 43 completed, 5 corrupt, 941 WARNs |
Locally (world-postgres, 16 runs at c12 with 40 worker slots and 8 busy-loop processes to approximate a 4-core runner; the laptop is otherwise too fast to hit the window): beta.46 baseline 3 corrupt / 37 WARNs, +#3841 0 corrupt / 6 WARNs, +#3879 0 corrupt / 0 WARNs.
Mechanism, consistent with #3879's description and with the flip this scenario was built around: a buffered hook payload registers an unarmed delivery barrier; the idle safety net may retire it while the payload and its claim() closure stay alive in a retained VM. Before #3879, a later iterator.next() that claimed it called arm() on the retired entry, which changed nothing in the registry, so the runtime saw no committed delivery: isDeliveryIdle could report idle and the pass could suspend while the claim was still resolving, and later deliveries (a wait_completed appended on resume) had nothing at that index to order behind. The parked body then took the hook branch out of log order. In this shape that means a wake cycle where the log recorded a heartbeat, and the next drain draws the ordinal the log holds for the heartbeat's wait_created, which is exactly Replay could not consume event: eventType=wait_created. #3879 reinstalls an armed entry on a late claim, so the claim is visible to both the idle check and the ordering gates.
Branches for reruns: peter/repro-wake-loop-beta46, peter/bisect-b46-3879, peter/bisect-b46-3841.
🤖 Generated with Claude Code
…c-workflow-source * origin/main: (22 commits) feat(streams): add writer session seam (#3832) docs: document WORKFLOW_NODE_HTTP in the v4 World docs (#4050) [world-vercel] Honor WORKFLOW_NODE_HTTP on the queue transport (#4044) feat(streams): add WebSocket capability gate (#3764) fix(world-local): retry JSON reads on Windows (#4051) [core] Add the wake-loop scenario to the event log race repro (#4017) [ci] Cap concurrent Vercel E2E action repo-wide (10 by default) (#4039) Add `Run#getWritable()` for appending to another run's stream (#3972) feat(streams): add WebSocket v1 client protocol contract (#3763) [swc-playground] Update to Next.js v16.3.4 (#4018) [core] Add a retention option to start() (#3787) fix(swc-plugin): register class expressions via an IIFE instead of by name (#3971) [docs] Fix prose typos across v4/v5 docs and the SWC plugin README (#3948) Validate pending changesets in CI so a bad one fails the PR, not the Release job (#3964) Version Packages (beta) (#3919) Classify Workflow stream failures (#3850) Drop the ignored @workflow/world-sim package from the hook_conflict delta changeset (#3963) Add attribute inspection to the CLI (#3950) [core] Settle a hook's awaiter in-process instead of re-invoking, on creation and on conflict (#3938) Use the storage APIs for run detail views (#3944) ...
Scenario
wake-loop: one sequential loop that races a reusable hook read (iterator.next()carried across heartbeat wins) against a heartbeatsleep, with a four-step cycle (verify,drain,verify,sync) per fresh wake or heartbeat, averifybefore every heartbeat is re-armed, stale wakes that emit no step, and occasional back-to-back cycles decided by the drain step's result. Nothing in the workflow fans out; every bit of concurrency comes from the driver, which sends single wakes at a short cadence, bursts of near-simultaneous wakes, and wakes aimed at the heartbeat deadline so ahook_receivedcommits right next to await_completed.This is the shape of a production run on 5.0.0-beta.46 that failed
CORRUPTED_EVENT_LOGwithReplay could not consume event: eventType=wait_created. Its persisted log is self-consistent (a faithful offline replay of all 633 slots is clean, and no correlation ordinal is bound to two entities), yet from the moment onewait_completedlanded, replays of the same immutable prefix stalled at the samewait_createdintermittently: 16 stalled passes against dozens of clean ones over three minutes, each queuing a recovery replay that usually succeeded, until four consecutive stalls exhausted the budget. The only replay that reproduces the exact message offline is one that observes a hook payload ahead of an earlierwait_completed: it runs a wake cycle where the log recorded a heartbeat, and its nextdraindraws the ordinal the log holds for the heartbeat'swait_created.Knobs (
EVENT_LOG_RACE_REPRO_WAKE_LOOP_*): attempts, fresh wakes per run, heartbeat, drain duration and spread, step payload size (so replays pay real hydration), continue-every, fresh/burst/idle ratios, burst size, gap range, max cycles. Defaults live in the harness only, as for the other scenarios; three of them are exposed asworkflow_dispatchinputs (GitHub caps a workflow at 25). The result JSON carriespressure.wakeLoop(fresh/stale/bursts/idles sent; cycles/heartbeats/stale consumed reported by the run) and the return-value ledger is cross-checked for internal consistency.Results
The scenario reproduces the class on the release the incident happened on and is clean on main. Same dispatch (48 wake-loop runs, concurrency 12) on this branch and on the scenario cherry-picked onto
workflow@5.0.0-beta.46(peter/repro-wake-loop-beta46):runTimeoutMsCORRUPTED_EVENT_LOGCORRUPTED_EVENT_LOG, 1 stuckOf the 6 corrupted Vercel-lane logs on beta.46, 3 hold a step bound to the ordinal a sibling gave a
wait(a flipped replay committed) and 3 are self-consistent logs where the flipped replays only diverged, the incident's shape. Details in the comment below. Locally on world-postgres (this branch) 38 runs were clean as well.🤖 Generated with Claude Code