test(core): repro — step vs wait/hook delivery ordering diverges across replays (CORRUPTED_EVENT_LOG) - #3137
test(core): repro — step vs wait/hook delivery ordering diverges across replays (CORRUPTED_EVENT_LOG)#3137pranaygp wants to merge 5 commits into
Conversation
…divergence (corrupted event log) Adds packages/core/src/step-delivery-ordering.test.ts, reproducing the production CORRUPTED_EVENT_LOG failures on o2flow runs wrun_41KYJENABV0GSF5YTE9EETV5DD and wrun_41KYJEE01S0GPC9RWT5MEKVCX8 (@workflow/core@5.0.0-beta.36). Step results are not part of the `pendingDeliveryBarriers` system in private.ts, which pins branch-deciding delivery order to event-log position for the kinds 'hook' and 'wait' only. A `step_completed` resolution's microtask-hop count instead depends on whether the invocation's shared ReplayPayloadCache already memoized its result, so a `step_completed` adjacent in the log to a `wait_completed` or a buffered `hook_received` is delivered after it on the first replay of a queue delivery (cold cache, the ordering the log records) and before it on every later replay of that same delivery (warm cache). The two workflow branches then swap the deterministic ULIDs they draw for their next step calls, and replay diverges permanently at the same event. The two "later replay" tests are expected to FAIL on main -- that failure is the reproduction. The companion fix on branch pgp/fix-step-delivery-ordering adds 'step' to the delivery-barrier system and makes them pass. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Signed-off-by: Pranay Prakash <pranay.gp@gmail.com>
🦋 Changeset detectedLatest commit: 86377f2 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:
📜 Previous results (1)913dd3cMon, 27 Jul 2026 21:03:17 GMT · run logs
ℹ️ 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
|
There was a problem hiding this comment.
Pull request overview
Adds a deterministic, core-only repro test suite for a production replay-divergence incident where step_completed delivery ordering can flip relative to wait_completed / buffered hook_received across replays when a ReplayPayloadCache is shared, leading to ReplayDivergenceError and eventual CorruptedEventLogError.
Changes:
- Introduces
step-delivery-ordering.test.ts, a harness-driven synthetic event-log repro covering step-vs-wait and step-vs-hook ordering across cold vs warm payload-cache replays. - Adds an empty changeset entry to satisfy the repo’s “changeset required” process without bumping packages.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| packages/core/src/step-delivery-ordering.test.ts | New repro tests demonstrating replay ordering divergence when step result hydration cost changes across replays sharing a payload cache. |
| .changeset/nasty-hounds-retire.md | Empty changeset marker (no package bumps). |
Comments suppressed due to low confidence (1)
packages/core/src/step-delivery-ordering.test.ts:513
- This test is also described as failing on
main(repro). If this PR is intended to merge on its own, keeping it asit(...)will hold CI red; considerit.failsfor the repro case, and switch back toitin the companion fix PR (or merge the fix and tests together).
it('delivers the hook payload before the step result on a later replay sharing the payload cache', async () => {
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| .map((item) => (item.type === 'step' ? item.stepName : '')); | ||
| } | ||
|
|
||
| it('delivers the wait before the step result on the first replay, matching the log', async () => { |
There was a problem hiding this comment.
| it('delivers the wait before the step result on the first replay, matching the log', async () => { | |
| it.fails('delivers the wait before the step result on the first replay, matching the log', async () => { |
| expect(ctx.eventsConsumer.eventIndex).toBe(events.length); | ||
| }); | ||
|
|
||
| it('delivers the wait before the step result on a later replay sharing the payload cache', async () => { |
There was a problem hiding this comment.
| it('delivers the wait before the step result on a later replay sharing the payload cache', async () => { | |
| it.fails('delivers the wait before the step result on a later replay sharing the payload cache', async () => { |
My original explanation was wrong. It claimed `for await` reproduces because the async iterator has not subscribed when the events consumer drains the log on `process.nextTick`, so the payload buffers and is delivered later through `claim()`. Measured instead by probing the two delivery branches in `workflow/hook.ts`: every hook case — `for await` on both the cold and the warm replay, and the direct `await hook` control — takes the `promises.length > 0` immediate path. `payloadsQueue.push` never fires, so the buffered `claim()` path is not involved in any of them. Entering `for await` calls `next()`, which reaches `yield await this` and registers the awaiter before the drain. What actually differs is the number of microtask hops between the payload resolving and the branch calling `afterHook()`: the async generator has to resume at `yield await this`, settle the promise returned by `next()`, and only then run the loop body, whereas `await hook` resumes the continuation directly. So the hook flavour is the same latency race as the wait flavour, and the consumer shape only sets how much of a head start the step result needs. The observable behavior is unchanged: `for await` reproduces, direct `await hook` does not, so the repro must use `for await` or it reports a false green. Only the attribution was wrong. Adopts the corrected wording from #3139 verbatim, so this file is once again identical to that branch's copy apart from the two `it.fails` markers. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Signed-off-by: Pranay Prakash <pranay.gp@gmail.com>
|
@VaguelySerious thanks for the review and for the Three of the five tests pass on
The first two assert that the cold-cache replay reproduces the ordering the live invocation actually committed to the log. That's the half of the behavior that is correct today, and it's what makes the warm-replay divergence meaningful rather than just "a test that fails." The third is the control for the direct- With all five marked, run 30303532379 reported One correction that's probably of interest to you specifically, as the author of |
…scope limit Two inline comments still described the hook payload as "buffered" after e2cbc8a corrected the top docstring. Probing both delivery branches of workflow/hook.ts shows every hook case in this file taking the promises.length > 0 immediate path, so payloadsQueue.push never fires and no payload is buffered. The direct-await control also gave the wrong reason for staying green: its hook hydration slot being queued on the serial promiseQueue ahead of the step_completed slot is equally true of the reproducing for-await case, so it cannot be what separates them. The difference is consumer hop count. Also records what these five cases cannot detect. Every consumer here reaches its next useStep in the fewest possible microtask hops, so they pass for a fix that merely delays step resolution by a hop or two without ordering deliveries at all -- a revision of the companion fix did exactly that, and diverged again under a consumer padded with one extra await. Padded consumers are covered by step-delivery-hop-count.test.ts on the fix branch. Comments only; no assertions, test bodies, or expected-failure markers changed. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Signed-off-by: Pranay Prakash <pranay.gp@gmail.com>
The two
it.failstests are the reproduction.Two of the five tests in the new file assert the correct behavior and fail on
main. Following @VaguelySerious's review suggestion (applied in913dd3c85), those two are markedit.fails, so CI here is green and the markers themselves assert the bug still exists: if the ordering flip stopped happening, they would error withExpect test to fail.The other three tests are plain
it(...)and pass onmainby design — the two cold-replay cases assert the first replay reproduces the ordering the log recorded, and the direct-await hookcase is a shortest-consumer control that has to stay green. The suggestion was initially applied to all five, which made those three error withExpect test to fail— CI red for the wrong reason, and the two genuine divergences no longer visible in the output (run 30303532379:3 failed | 1542 passed | 5 expected fail, the three named failures being exactly these controls, on both ubuntu-latest and Windows). Narrowed inc2427bb7eto the two cases that actually diverge — the two Copilot's review comment named.The companion fix is #3139, which carries this same test file with plain
it(...)on all five and ships them passing. The two copies ofstep-delivery-ordering.test.tsare identical apart from those two markers (sed 's/it\.fails(/it(/g'on this filecmps clean against #3139's), so you can still confirm the tests were not bent to fit the fix. #3139 additionally carries a second test file that this PR does not have — see What these tests do not cover.Merge plan — two viable dispositions; the choice is the maintainers':
it(...)on all five, and this one closes as the demonstration artifact. Nothing here reachesmain.it.failsmarkers are for: the two markers land onmainas executable documentation that the bug is real and still unfixed, then fix(core): order step-result deliveries against wait/hook deliveries by event-log position #3139 rebases and flips them to plainit(...)as part of the fix, bringing its hop-count file with it (see below — that file is the part that actually pins the guarantee). This has the property thatmainwould carry a test which fails loudly the moment the ordering changes without the marker being removed.Either way the test content is identical; only the two markers differ.
#3139 brings step results into the delivery-barrier system. Adding a
'step'kind and ordering theresolve()calls turns out not to be sufficient — and the five tests in this PR cannot tell you that, which is its main limitation (What these tests do not cover). Three things were needed:claim(), i.e. whenever the workflow next reads the hook — and reaching that read commonly requires the step result itself (await stepX()before the read). Gating there would stall the run until the barrier's idle safety net fired, which then releases everything at once and regresses four existinghook-sleep-interactioncases. Barrier entries therefore carry anarmedflag, and step deliveries skip earlier deliveries that cannot resolve on their own; seeDEFER_BEHINDandresolvesOnItsOwninprivate.tson that branch. Waits and hooks deliberately keep gating on unclaimed payloads — for them, waiting for the claim is the guarantee — so the asymmetry is load-bearing and those four tests are its regression guard.resolve()ran — it does not mean the woken branch has reached its nextuseStep(...), so the earlier branch's whole microtask chain needs to drain first.The production incident
Two o2flow runs on
@workflow/core@5.0.0-beta.36—wrun_41KYJENABV0GSF5YTE9EETV5DDandwrun_41KYJEE01S0GPC9RWT5MEKVCX8— failed with:The same divergence recurred at the same
eventIdacross all three divergence-recovery replays and then escalated to a terminalCorruptedEventLogError. The relevant slice of run 1's log is:Mechanism
Every
useStep(...)invocation draws the next deterministic ULID as its correlation id (packages/core/src/step.ts,step_${ctx.generateUlid()}). So which branch's continuation runs first decides which correlation id each step call gets. Replay matches events to consumers by exact correlation id and rejects astep_createdwhose recordedstepNamediffers from the consumer's (step.ts, theeventStepName !== stepNamecheck).The runtime already has a delivery-barrier system that pins branch-deciding delivery order to event-log position —
pendingDeliveryBarriers/awaitEarlierDeliveries/registerDeliveryBarrierinpackages/core/src/private.ts. ItsDeliveryKindis'hook' | 'wait'. Step results are not in it.wait_completedresolves through a detached chain with a fixed, small microtask-hop count (packages/core/src/workflow/sleep.ts, thewait_completedbranch). Astep_completedinstead resolves inside a serialctx.promiseQueueslot that first hydrates its payload viaReplayPayloadCache.getStepResult(...)(step.ts, thestep_completedbranch). That hop count is not fixed: the first hydration pays async decrypt/deserialize, while a later replay hits theprimitiveStepResultsmemo for small primitive results and resolves in one or two hops (packages/core/src/replay-payload-cache.ts).The cache is shared across replays:
runtime.tscreates oneReplayPayloadCacheper queue delivery, outside thewhile (true)main replay loop, so every inline replay in that delivery reuses it.Net effect: when a
step_completedsits adjacent in the log to await_completed(or ahook_received) and both consumers are live, the first replay of a delivery (cold cache) delivers the wait/hook first — the ordering the live invocation committed to the log — and every later replay in that same delivery (warm cache) delivers the step result first. The two branch continuations then swap the ULIDs they draw for their next step calls, and replay diverges permanently at the same event.The tests
packages/core/src/step-delivery-ordering.test.ts(harness adapted fromhook-sleep-interaction.test.ts, with one addition: aReplayPayloadCachecan be passed intosetupWorkflowContextso two sequential replays share one cache, like production).Each scenario runs the same workflow body twice against the same synthetic log — one branch awaiting
stepA()thenafterStep(), the other awaiting a sleep/hook thenafterSleep()/afterHook()— and asserts both replays agree with the log and suspend.mainReplayDivergenceErrorfor await) — first replayfor await) — later replay sharing the cacheReplayDivergenceErrorawait hookdirectly (control)The table above describes the underlying behavior. With the two markers in place the run reports
3 passed | 2 expected fail (5); with them removed (as on #3139 before the fix) the two diverging cases surface the production error verbatim:Same shape as production, down to the sentence. Six consecutive runs produced identical results, so the repro is deterministic, not a timing flake.
src/hook-sleep-interaction.test.ts— the harness this borrows from — still passes (34 passed, 2 pre-existingit.fails). Fullpackages/coresuite on this branch:1545 passed | 5 expected fail (1550), the 5 being 3 pre-existing plus these 2.Independent confirmations that this is not a local quirk:
Two notes on how the hook cases behave, since they are not symmetric. An earlier revision of this description got the reason wrong — it claimed
for awaitreproduces because the payload is buffered and delivered throughclaim(). That is not what happens. Probing both delivery branches inworkflow/hook.tsshows every hook case here —for awaiton both replays, and the directawait hookcontrol — taking thepromises.length > 0immediate path;payloadsQueue.pushnever fires, so the bufferedclaim()path is not involved at all. Enteringfor awaitcallsnext(), which reachesyield await thisand registers the awaiter before the events consumer drains the log onprocess.nextTick.What actually differs is the number of microtask hops between the payload resolving and the branch calling
afterHook(), i.e. drawing the next ULID:for awaitcase reproduces because resolution has to resume the async generator atyield await this, settle the promise returned bynext(), and only then run the loop body. Those extra hops are enough for a memo-warmstep_completed— which on an unfixed runtime resolves inside its own queue slot with no detached chain — to drawCORR_IDS[2]first.await hookcase does not reproduce, and is the control: resolution resumes the branch's continuation directly, so it reachesafterHook()in the first microtask and stays ahead of the step result even on a warm cache. The fix must not regress this — fix(core): order step-result deliveries against wait/hook deliveries by event-log position #3139 touches that same path (the barrier is registered already-armedthere), and this control stays green on it.So the hook flavour is not about payload buffering; it is the same latency race as the wait flavour, and the consumer shape only sets how much of a head start the step result needs. The practical consequence is unchanged: a repro written with
await hookreports a false green, so it must usefor await.What these tests do not cover
Every branch in this file reaches its next
useStep(...)in the fewest possible microtask hops after being resumed. That keeps the repro small, but it also means these five cases cannot distinguish:This is not hypothetical: a revision of #3139 provided (b) and passed all five. Instrumenting
awaitEarlierDeliveriesshowed the step reportingdefers=0in the hook case — the hook's hydration slot runs first on the serial queue and its detached resolve deregisters the barrier before the step's slot starts, so the barrier ordered nothing at all, and the hook test passed purely on the one extra microtask hop that moving the step's resolve into a detached.thenhappens to add. The wait case did genuinely defer (defers=1), but with about one hop of margin. Padding the consumer with a single extraawaitre-diverges the hook case; two re-diverges the wait case.Padded consumers are covered by a second file on the fix branch,
packages/core/src/step-delivery-hop-count.test.ts, which runs both flavours at 0/1/2/4/8/16 extra hops:mainThat file is deliberately not in this PR; this one stays single-file. But if the maintainers take disposition (b) above and merge this PR first, whoever flips the markers should pick the hop-count file up along with the fix, because without it a future refactor could regress to (b) with this entire suite still green.
Padding a consumer is a legitimate shape rather than a contrived one, incidentally. In a live run the two events arrive in separate deliveries, so the first branch runs to completion long before the second event exists; only a replay hands both to one drain window and makes the two branches race in userland at all.
Is this Vercel-world-specific? No.
The repro drives
createUseStep,createSleep,createCreateHook,EventsConsumer, andReplayPayloadCachedirectly, with a hand-built event log and no World implementation at all. Every piece of machinery that decides delivery order lives inpackages/coreand is shared by all worlds; worlds only supply event I/O. I did look at building a second repro on top of@workflow/world-localand drivingworkflowEntrypoint(the pattern insrc/runtime/wait-completion-replay.test.ts) and skipped it deliberately: it would add a world, step registration, and forced multi-iteration replay plumbing without testing a single additional line of the code path that causes the bug, and the divergence-recovery machinery would sit between the fault and the assertion.Changeset is intentionally empty — this PR is test-only.
🤖 Generated with Claude Code