[e2e] Rebuild the event-log corruption repro around step-count divergence - #3147
Conversation
…ence The existing `event-log-race-repro` job produced ~0.1% `CORRUPTED_EVENT_LOG` (2 / 2000 runs), all from the `hook-sleep` scenario, because its scenarios supplied only part of the recipe: one wake source per run, short event logs, and — critically — branches that emit the same number of steps whichever way they resolve. A stale write in that shape is a benign retry, not a divergence. The two new storm workflows race a settle path that emits one step against a recovery path that emits two, then fan out a reconcile batch whose width is derived from how many branches took the recovery path. Because correlation IDs are positional ordinals of one seeded sequence, a replay that disagrees about the winner renames every entity after it. - `step-storm` races an in-run step completion against a per-branch watchdog, under continuous out-of-band pressure from a never-read poke hook. - `hook-storm` races an out-of-band hook delivery against the watchdog — the shape seen corrupting production runs. - `hook-sleep` is retained at low attempt counts as a calibration control. The harness also now classifies failures from the top-level `errorCode` rather than `error.code`, which is rehydrated into an `Error` carrying only `name`/`message`; every real corruption was previously reported as `other`.
🦋 Changeset detectedLatest commit: c0163e9 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 |
VaguelySerious
added
the
event-log-race-repro
📊 Workflow Benchmarkscommit Backend:
ℹ️ Metric definitions & methodologyBest/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 · STSO (1-20) 20/30/60 · STSO (101-120) 30/45/90 · STSO (1001-1020) 40/60/120 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 |
🧪 E2E Test Results✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 📋 Other
✅ vercel-multi-region
|
Event Log Race Repro928 of 1400 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
Showing 20 of 928 non-completed runs. |
|
No backport to This rewrites the opt-in, label-triggered To override, re-run the Backport to stable workflow manually via |
…ry-2 * origin/main: (292 commits) feat(core): seal forwarded stream writes to the owner's public key (#3098) feat(core): seal hook payloads to the target run's public key (#3096) [e2e] Rebuild the event-log corruption repro around step-count divergence (#3147) feat: decrypt sealed payloads in the dashboard and CLI (#3146) Prewarm only appended replay payloads (#3131) feat: publish each run's X25519 public key on the run entity (#3095) feat(core): route sealed envelopes through the serialization layer (#3094) docs: redirect retired migration-guides URLs to comparisons (#3127) feat(core): add `encp` sealed-box encryption primitive (#3093) chore(core): clarify runtime comments (#3111) Remove obsolete world factory aliases (#3112) feat(core): deterministic sandbox hardening (#3045) Remove retired v1 step route plumbing (#3061) [core] Don't count racing invocations' duplicate step_started events toward the maxRetries ceiling (#3069) [world-testing] Isolate each spawned test server's data directory (#3055) fix: upgrade postcss to >=8.5.18 to address GHSA-r28c-9q8g-f849 (#3102) [next] Respect .gitignore in dev watcher to avoid EMFILE on large monorepos (#3085) [ci] Backport only stability fixes to `stable`, default to claude-opus-5 (#3092) perf(core): immediate leading-edge dispatch for idle streams (flush window default 0) (#3088) Optimize `processImportSpecifier` by computing `shouldFollowImportsFromFile` once per file (#3052) ... # Conflicts: # docs/components/geistdocs/desktop-menu.tsx # docs/components/geistdocs/mobile-menu.tsx # docs/content/docs/v5/cookbook/advanced/child-workflows.mdx # docs/content/docs/v5/cookbook/advanced/upgrading-workflows.mdx # docs/content/docs/v5/cookbook/agent-patterns/agent-cancellation.mdx # docs/content/docs/v5/cookbook/agent-patterns/durable-agent.mdx # docs/content/docs/v5/cookbook/agent-patterns/human-in-the-loop.mdx # docs/content/docs/v5/cookbook/common-patterns/batching.mdx # docs/content/docs/v5/cookbook/common-patterns/idempotency.mdx # docs/content/docs/v5/cookbook/common-patterns/rate-limiting.mdx # docs/content/docs/v5/cookbook/common-patterns/saga.mdx # docs/content/docs/v5/cookbook/common-patterns/scheduling.mdx # docs/content/docs/v5/cookbook/common-patterns/sequential-and-parallel.mdx # docs/content/docs/v5/cookbook/common-patterns/timeouts.mdx # docs/content/docs/v5/cookbook/common-patterns/webhooks.mdx # docs/content/docs/v5/cookbook/common-patterns/workflow-composition.mdx # docs/content/docs/v5/cookbook/index.mdx # docs/content/docs/v5/cookbook/integrations/ai-sdk.mdx # docs/content/docs/v5/cookbook/integrations/chat-sdk.mdx # docs/content/docs/v5/cookbook/integrations/sandbox.mdx # docs/next.config.ts # docs/proxy.ts # docs/scripts/lint.ts # pnpm-lock.yaml # pnpm-workspace.yaml
1 participant
Why
The
event-log-race-reprojob exists to give us a measurableCORRUPTED_EVENT_LOGrate to test event-guard changes against. Its last full run produced 2 corruptions / 2000 runs (0.1%), all in thehook-sleepscenario (2/1498);step-fanoutwas 0/250 and bothstep-sleep-race-*were 0/125. That rate is too low to tell a fix from noise, while real user workloads hit it repeatedly.A corrupted event log needs three things to line up. The old scenarios supplied at most two:
sleep()s do not help — the suspension handler schedules only the soonest pending wait as a single delayed re-invocation, so N parallel sleeps produce one wake, not N.Item 3 is the amplifier. Correlation IDs are positional ordinals of one seeded sequence, so a replay that emits a different number of steps renames every entity after that point, turning one missing event into an unrecoverable divergence. The corrupted production runs we traced diverged at ordinals 1337 and 901, deep into long logs.
What
Two new storm workflows (
workbench/nextjs-turbopack/workflows/103_event_log_corruption_repro.ts) supply all three by construction. Each round fans outwidthbranches; every branch races a settle path that emits one step against a recovery path that emits two, and then the round fans out a reconcile batch whose width is derived from how many branches took the recovery path.step-stormraces an in-run step completion against a per-branch watchdog timer. The step body also issuessetAttributes, which is a genuinely out-of-band write, and the driver resumes a hook the workflow creates but never reads on a continuous cadence, so every replay is racing a stream ofhook_receivedevents written with no snapshot behind them.hook-stormraces an out-of-band hook delivery against the watchdog, with the round's deliveries staggered so they straddle the deadline. This is the shape seen corrupting production runs: a task waiting on a callback with a timeout.hook-sleepis retained at low attempt counts (200) as a calibration control, since its historical ~0.1% rate is our only baseline.Defaults: 600 step-storm + 600 hook-storm + 200 control at concurrency 40, 6 rounds x 8 branches, watchdog 2500 ms against a 2200 ms +/- 250 ms step delay so the jitter decides each winner. Every knob is a
workflow_dispatchinput.Two other changes matter for reading the results:
errorCode.erroris rehydrated into anErrorcarrying onlyname/message, soerror.codewas alwaysundefinedand every real failure was bucketed asother. The previous artifact'sother: 2and this branch'sCORRUPTED_EVENT_LOG: 2would be the same outcome reported differently — worth remembering when diffing against the old sticky comment.validateStormReturn) catches silent corruption: a run that diverged but still reachedcompletedwill normally disagree with itself about its own straggler count or reconcile width. That reports asBAD_STORM_LEDGER.Result
First full run on this branch (plain
mainSDK, no guard), run 30316814473:CORRUPTED_EVENT_LOG0
USER_ERROR(the poke-hook risk below did not materialise), 0RUNTIME_ERROR, 0BAD_STORM_LEDGER, 0 infra. Against the previous harness's 2/2000 (0.1%), that is a ~650x increase, and the retainedhook-sleepcontrol stayed at 0/200 in the same run — so the gain comes from the step-count-divergent shape, not from load.The
Event Log Race Reprocheck failing is the corruption gate firing as designed; every other check on this PR passes, includingE2E Required Check.The 22 stuck runs are all
hook-storm, all stillrunningat the 240 s timeout, spread evenly across attempts and not correlated with failed hook resumes (some have 8/8 resumes delivered). That is a separate signal from divergence and worth a look on its own.Acceptance bar
Label a PR
event-log-race-reproand the job runs. Met: 906 corruptions in one run, with step-storm alone at 90.7%. The knobs are still there if a future backend change suppresses the rate and it needs re-tuning:width,watchdog_msvsstep_delay_msseparation,rounds, then attempt counts.Known risk
A step-storm run accumulates roughly 40 unread
hook_receivedevents on the poke hook. If the backend capped pending hook events this would surface asUSER_ERRORrather than a corruption. The first full run reported 0USER_ERROR, so it does not.