[core] Pin draw order to event-log order: retire delivery barriers through one ordered dispenser - #3554
[core] Pin draw order to event-log order: retire delivery barriers through one ordered dispenser#3554VaguelySerious wants to merge 9 commits into
Conversation
…e replay of the corrupted storm log + draw-order probes Offline replay tests built from the actual corrupted event log of wrun_41KZYJ92TP0GYBNDKW3FJBWQ3Y (step-storm repro, preview, spec 6): - storm-log-replay.test.ts: a faithful replay of the full 655-event log reproduces the production divergence verbatim; a faithful replay of the corrupting writer's exact 610-event prefix reproduces the writer's committed binding, proving the writer was prefix-determined and the binding conflict is created by log growth, not by a misbehaving writer. - storm-log-sweep.test.ts (STORM_LOG_SWEEP=1): sweeps prefix lengths and finds the flip at slot 612 - a branch's post-Promise.race draw is not pinned to its waking event's log position, so the ordinal it draws depends on how much log is loaded. - race-padded-draw-ordering.test.ts: the minimal 2-branch race shape stays correctly ordered cold+warm (regression coverage for the barrier fix). - runtime.ts DIAG probes (array order before each pass, draw bindings per suspension, array-order dump on divergence) for the preview repro lane. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…anch keeps tests+fixture only) Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…g draw order to log order The delivery-barrier registry orders branch-deciding resolutions by event-log position, but its safety net was one independent idle poll per barrier. When chains park behind an unclaimed buffered hook payload (a fire-and-forget createHook), the net firing order decides delivery order — and per-barrier polls fire in whatever order their re-arm cycles land, decaying to timing noise. A branch's next useStep ULID then depends on how much log the replay loaded: two invocations of one run holding different-length (both valid) prefixes bind the same correlation ordinal to different steps, both commit creates, and every later replayer fails deterministically with CORRUPTED_EVENT_LOG (and one logical step executes under two ids). Replace the per-barrier nets with one per-context dispenser that, at delivery idle, retires only the LOWEST-index entry, then yields so the released chain re-blocks idle before the next retirement. Every barrier gate points from a higher index to a strictly lower one, so the lowest undelivered entry at idle is the head of every parked chain; releasing head-first is the only order that cannot invert the log. Regression coverage replays the actual corrupted production log (wrun_41KZYJ92TP0GYBNDKW3FJBWQ3Y, step-storm repro): a faithful replay of the corrupting writer's exact 610-event prefix must reproduce the binding that writer committed, and pending-step bindings must be identical across prefix lengths 610..630 — before this fix, extending the log from 611 to 612 slots rebound rank 198 from finalizeStep to releaseStep. The full-log replay still (rightly) diverges: that log holds two creates for one logical step, which no single deterministic trajectory can satisfy; the fix makes such logs unproducible, not readable. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
🦋 Changeset detectedLatest commit: 2b84280 The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 packages
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 |
VaguelySerious
added
the
event-log-race-repro
🧪 E2E Test Results✅ All tests passed 🛠 Infra Events (absorbed by the harness)Platform anomalies the e2e harness detected and worked around (e.g. a run the queue never picked up, replaced by a fresh run). Clustered timestamps indicate a backend blip; a steady drip indicates a platform issue worth escalating.
E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 🌐 Cross-language Conformance
✅ vercel-multi-region
|
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 408504ms → this run 302796ms (Δ -105708ms, -26%) 1020 steps (queue-hop) Cumulative STSO time: 2497ms over 1 samples No 📈 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): 📜 Previous results (3)56b179fFri, 14 Aug 2026 21:00:43 GMT · run logs
90d0fdcFri, 14 Aug 2026 18:50:27 GMT · run logs
8325da5Fri, 14 Aug 2026 18:15:16 GMT · run logs
ℹ️ Metric definitions & methodologyStreams: writer/reader sustained rates (steady window, 10% trimmed each side), 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. |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 3 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
![vercel[bot]](https://avatars.githubusercontent.com/in/8329?s=60&v=4){kind=small}
Event Log Race Repro (world-local)6 of 14 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
|
…stry The dispenser changed a race the old per-barrier nets won by accident: all nets fired in the same idle window as the suspension check, so a suspension practically never preempted undelivered parked chains. With one dispenser, end-of-log suspension could fire between retirements, ending the pass with consumed-but-undelivered branch-deciding events — the run then schedules none of their follow-up work and sits dormant (CI repro lanes: step-storm 6/6 stuck on world-local and world-postgres, while hook-storm — whose hooks are all claimed, so no unarmed barriers — completed 6/6). Make it structural instead of a race: isDeliveryIdle (suspension + the events consumer's unconsumed-event check) now also requires the barrier registry to be EMPTY, while the dispenser keeps the weaker gate (no hydration in flight, no committed delivery mid-deferral) so it can do the draining that idle waits for. Registry size strictly decreases per retirement, so idle is always reached. The dispenser also re-arms on a rejected promiseQueue rather than dying with the registry non-empty, which would now wedge the run. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
(AI) Second regression found via the report-only CI repro lanes and fixed: with the dispenser, end-of-log suspension could fire between retirements (the old per-barrier nets all fired in the same idle window, so this race was previously won by accident), ending a pass with consumed-but-undelivered branch-deciding events — runs went dormant (step-storm 6/6 stuck on both local lanes, while hook-storm, which has no unclaimed payloads, completed 6/6). Now structural rather than a race: |
…sses The copied harness stubbed the events consumer's idle gate as () => true, letting the unconsumed-event check observe 'idle' while the barrier dispenser was still draining — a timing hole production wiring does not have (workflow.ts binds the real predicate). macOS scheduling never hit it; the Windows unit lane did, failing the extension-stability test with a non-suspension outcome. Also surface the actual error when a prefix replay fails to suspend, so a lane failure names the cause. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…f + direct unit coverage Self-review findings on #3554: - The rejected-promiseQueue re-arm added for dispenser survival would have degenerated into a busy loop on an abandoned context (a rejected queue settles immediately, forever). Back off through a plain 50ms timer on that path instead; the normal cadence is unchanged. - The dispenser's guarantees were only covered end-to-end (storm lanes) or via the production-log fixture. Add direct unit coverage: suspension-not-before-parked-deliveries, log-order wakes across several parked segments, and registry drain on a rejected queue. The last one fails on main (per-barrier polls die silently there); the first two pin properties the old code held only by scheduling accident at small scale. Also verified during review: the QuickJS engine replaces this replay path entirely (own implementation), so it is affected by neither the bug fix nor the regressions it guards against. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
(AI) Self-review pass over the final diff, findings and dispositions: Fixed in this push (56b179f):
Audited, no change needed:
|
1 participant
Fixes the residual slot-mode
CORRUPTED_EVENT_LOGclass diagnosed in #3543 (most recentlywrun_41KZYJ92TP0GYBNDKW3FJBWQ3Y, the step-storm repro on preview).Root cause
The delivery-barrier registry orders branch-deciding resolutions (step results, wait completions, hook payloads) by event-log position — but its safety net was one independent idle-gated poll per barrier. When chains park behind an unclaimed buffered hook payload (a fire-and-forget
createHookthe workflow never reads — the storm workflows have exactly one, and production dagRunner-style workflows do too), the order those nets fire in is the delivery order for everything parked. Per-barrier polls re-arm through apromiseQueuethat grows between checks, so with several parked segments the release order decays to timing noise.The consequence: a branch's next
useStep()correlation ULID depends on which barriers were in the registry, i.e. on how much log the replay had loaded. Replay stays deterministic per byte-identical input — every recovery replay fails identically — while two honest invocations holding different-length (both dense, both valid) prefixes bind the same ordinal to different steps. Both commitstep_createds; the log ends up carrying bindings no single trajectory can satisfy; every later replayer deterministically diverges, and one logical step executes under two ids (observed at slots 630/631 of the production run).Receipts in #3543: a faithful replay of the corrupting writer's exact 610-event prefix reproduces the writer's committed binding (the writer did nothing wrong), and extending that log by one ordinary
step_completed(slot 612) rebound rank 198 from finalizeStep to releaseStep.The fix, in three parts (one per commit of substance)
ensureBarrierSafetyNet): safety-net retirements go through one per-context dispenser that only ever retires the lowest-index entry. Every barrier gate points from a higher index to a strictly lower one, so at delivery idle the lowest undelivered entry is the head of every parked chain; head-first is the only release order that cannot invert the log. One dormant-when-empty poller also replaces one live poll per abandoned barrier.Replay could not consume event).isDeliveryIdle— which gates end-of-log suspension and the unconsumed-event check — now additionally requires the barrier registry to be empty, while the dispenser runs on the weaker gate (no hydration in flight, no committed delivery mid-deferral) so it can do the draining idle waits for. Registry size strictly decreases per retirement, so idle is always reached. Previously the suspension merely happened to lose the timer race against the old nets; with one dispenser it started winning, ending passes with undelivered branch-deciding events and leaving runs dormant (repro lanes: step-storm 6/6 stuck while hook-storm — no unclaimed payloads — completed 6/6). Now it is structural.Verification
Offline regression tests replay the actual corrupted production log (fixture from staging o11y, ULID ranks remapped onto the harness's deterministic sequence):
mainat 611→612.storm-log-sweep.test.ts(STORM_LOG_SWEEP=1) prints the full per-length table; every length agrees on this branch.Repro lanes (label
event-log-race-repro), per head:Local 120-attempt/24-concurrency soaks saturate the single-process harness into all-stuck on every head including main (documented in the repro script's notes), so only their divergence counts carry signal: main 83+ divergence warnings across 29 runs; dispenser-v1 5236; with sweep 5.
Full core suite: 2122 passed / 3 expected-fail.
Compatibility note
Logs already written by mutually inconsistent trajectories remain unreadable — they were unreadable before, deterministically. For healthy logs the dispenser only changes behavior in the parked regime, where the previous order was timing noise rather than anything a writer could depend on. Runs on Vercel keep replaying on the deployment that created them (skew protection), so mid-flight runs do not switch schedulers.
🤖 Generated with Claude Code