[core] Diagnose residual slot-mode CORRUPTED_EVENT_LOG: draws are not stable under log extension - #3543
[core] Diagnose residual slot-mode CORRUPTED_EVENT_LOG: draws are not stable under log extension#3543VaguelySerious wants to merge 1 commit 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>
🦋 Changeset detectedLatest commit: 3e060e3 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 194368ms → this run 152318ms (Δ -42050ms, -22%) ℹ️ 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) · 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) · 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 · 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 · 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 — 3 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
|
(AI) Local postgres soak addendum: 120 step-storm attempts with the DIAG probes reproduced the same class in 29/120 runs. Each affected run diverges repeatedly at one fixed low slot (58–84, the round-0/1 boundary) while the log keeps growing (e.g. Two operational notes from the soak:
|
Draft / diagnostics — not for merge as-is. This PR carries the offline reproduction and instrumentation for the residual
CORRUPTED_EVENT_LOGfailures on spec-6 (slot-identity) runs, most recentlywrun_41KZYJ92TP0GYBNDKW3FJBWQ3Y(step-storm repro on the #3519 preview, 1/14).What the data shows
Reconstructed from the run's full event log (staging o11y) plus per-invocation runtime logs:
…QMWZeagerly at slot 630,…QMX0lazily at slot 631), and both executed (duplicate step execution). A third trajectory (the failing replayer) assigned…QMWZto a releaseStep, which is the decrypted divergence:step event …QMWZ belongs to "finalizeStep", but the current step consumer is "releaseStep".eventCount: 610in its logs) and continued correctly. Nothing it did was wrong given what it loaded.Offline reproduction (in this PR)
storm-log-replay.test.tsrebuilds the run's exact log shape (slot order, entity kinds, step names, ULID ranks remapped onto the test harness's deterministic sequence) and replays it through a faithful port ofstepStormReproWorkflow:storm-log-sweep.test.ts(opt-in viaSTORM_LOG_SWEEP=1) sweeps prefix lengths:The flip event (slot 612) is an ordinary finalize
step_completed. Note also that at len 610 the settled branch's finalize draw (its waking event is at slot 577) lands after draws woken at slots 588–602.Diagnosis
Replay is deterministic for a byte-identical log, but draw order is not stable under log extension: a branch's post-
Promise.racecontinuation draws its next correlation id at a point in the microtask schedule that depends on how much log is loaded, not at its waking event's log position. Two honest replayers holding different-length (both dense, both valid) snapshots therefore bind the same ordinal to different steps; each commits creates from its own trajectory; the log ends up carrying mutually inconsistent bindings, and every replayer that loads past the conflicting create fails deterministically → 4 recovery replays →CORRUPTED_EVENT_LOG.This is the property the delivery-barrier work (
step-delivery-ordering.test.ts,step-delivery-hop-count.test.ts) pins for adjacent-event shapes; the storm shape (8-widePromise.race+finally+ interleaved recover chains) escapes it.race-padded-draw-ordering.test.ts(also in this PR) shows the minimal 2-branch race shape is correctly ordered cold+warm, so the escape needs the wider interleaving.Also included:
runtime.tsDIAG probes (error-level array-order check before each pass, per-suspension draw-binding log, array-order dump on divergence) so the preview repro lane produces the same forensics without ClickHouse spelunking. The array-order probe has stayed silent locally — the events array is not the problem.Fix directions (follow-up, not in this PR)
*_createdtolerance to become sound).🤖 Generated with Claude Code