[world-local] Fix CORRUPTED_EVENT_LOG from hook-resume staging slot holes - #3492
Conversation
`hook_received` is the only event that does not publish straight into `events/`: it stages under `.locks` first so a terminal transition can reap it before it becomes reader-visible. That staging path was keyed by the event id alone, and a collision on it bumped the writer to the next slot. Under slot ids a staging collision is not evidence the position is taken. The allocator probes `events/` only, so bumping moves the writer past a position nothing will ever fill, and `scanRunEventIds` is max-based so no later writer backfills it. The runtime reads the missing position as a durable hole and fails the run with CORRUPTED_EVENT_LOG. Two triggers: an attempt killed between staging and promoting leaves its staged file behind (cleanup lives in a `finally` the kill skips, and the only other reaper runs on a terminal transition), and two live writers drawing the same candidate where the stager is later rejected. Staging now carries a nonce, so it is private to one attempt and the slot is arbitrated only where it is actually taken, at the promote. Second fix: when a pinned resume loses the publish, the event at the pinned position is that same resume written by the other taker, which is the convergence the pin exists to force. Return that committed event instead of an EntityConflictError the caller cannot act on. Also re-purposes scripts/event-log-race-repro-local.sh to drive either world with `--world postgres|local`.
🦋 Changeset detectedLatest commit: c6bf782 The changes in this PR will be included in the next version bump. This PR includes changesets to release 18 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 |
🧪 E2E Test Results❌ Some tests failed ❌ Failed E2E Tests▲ Vercel Production (1 failed)nextjs-turbopack-node (1 failed):
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 204038ms → this run 174609ms (Δ -29429ms, -14%) 📜 Previous results (1)0161a14Wed, 12 Aug 2026 17:06:24 GMT · run logs
ℹ️ 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) · 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 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 — 6 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
CI status
It is red on main with the identical signature on the last four runs (31530061366, 31533009514, 31604115603, 31616799260) and passed on 08-10 (31446555530, 31431114276). A marginal budget rather than a code regression. Whole-file duration on the Windows runner, same 245 tests either side of the boundary:
8% apart. An added fs op per write would show a much bigger jump than that. Locally Not fixing it here: this PR does not touch
Repro script, postgres laneChecked that the |
pranaygp
left a comment
pranaygp
left a comment
There was a problem hiding this comment.
Reviewed with a focus on the testing story and on whether this closes all the slot-hole paths. The staging-nonce fix is correct and the crash-window regression guard is real — I verified 545/545 on the branch, tsc --noEmit clean, and that tests 1 and 2 fail deterministically with the fix reverted.
Three findings, detailed inline:
- A duplicate-resume window survives the fix (
events-storage.ts): when the pinned adopter of a resume claim wins the promotelink(2), the unpinned claim owner bumps and publishes a secondhook_receivedfor the sameresumeId. Reproduced deterministically; repro in the inline comment. Not aCORRUPTED_EVENT_LOG(the log stays dense) — it's a violation of the dedup contracthook-resume-dedup.test.tsasserts, and it pre-exists this PR in a sibling interleaving. - Test 3 is not a regression guard: it passes with the fix reverted (5/5 runs). Tests 1 and 2 do fail without the fix, so the PR description's claim is accurate for those two only.
- Minor: a
nextjsapp-name glob in the repro script doesn't matchsetupWorld's substring check, which could split-brain the data dir for future app names.
Also audited world-postgres for the analogous hole since it arbitrates slots differently: it doesn't have one. nextSlotId computes the position inside the INSERT itself (storage.ts:167) — nothing reserves a slot ahead of the write, so a rejected or crashed hook_received rolls back its transaction and leaves the numbering untouched; the terminal-race guard is a FOR UPDATE on the run row in the same transaction (storage.ts:1944). It also has no lazy resume-dedup path at all (no resumeId column, per the deliberate omission in drizzle/schema.ts:145), so the duplicate-resume window doesn't apply there either.
| // read. Answer it the same way rather than reporting a conflict | ||
| // the caller cannot act on: the resume IS committed, exactly once, | ||
| // and the dedup contract is that both writers return that event. | ||
| if (eventIdPinned && data.eventType === 'hook_received') { |
There was a problem hiding this comment.
This convergence covers the pinned loser, but the symmetric case is still open and produces a duplicate hook_received for one resumeId.
On a slot run the claim owner is unpinned (eventIdPinned = !isSlotEventId(eventId) up at the claim write), while a racing taker that adopts the claim is pinned. Both stage nonced files and race the promote at the claimed position S. If the adopter wins the link, the owner's promote returns 'exists', bumpEventSlot is allowed to move it (it isn't pinned), and the owner publishes a second hook_received for the same resume at S+1. Both callers return success; the log stays dense, so no CORRUPTED_EVENT_LOG — but replay now delivers one resume twice, which is exactly what the "collapses the two writers of ONE resume onto a single event" contract in hook-resume-dedup.test.ts forbids. (The claim rewrite after the owner's publish points redeliveries at the second event, so later converges mask it — but both events stay in the log and both replay.)
I reproduced this deterministically on this branch by parking the first promoteExclusive caller (the owner — it has a head start, since the adopter does a full findCommittedResumeEvent scan first) until the second caller has linked:
repro test (drop into src/storage/, uses a partial vi.mock of ../fs.js)
const gate = { armed: false, released: false, firstRelease: null as (() => void) | null };
vi.mock('../fs.js', async (importOriginal) => {
const actual = (await importOriginal()) as Record<string, any>;
return {
...actual,
promoteExclusive: async (stagedPath: string, filePath: string) => {
if (gate.armed && !gate.released) {
if (gate.firstRelease === null) {
await new Promise<void>((r) => { gate.firstRelease = r; });
return actual.promoteExclusive(stagedPath, filePath);
}
const result = await actual.promoteExclusive(stagedPath, filePath);
gate.released = true;
gate.firstRelease?.();
return result;
}
return actual.promoteExclusive(stagedPath, filePath);
},
};
});
// setup: createRun + createHook, then:
gate.armed = true;
const results = await Promise.allSettled(
[storage, createStorage(testDir)].map((inst) =>
inst.events.create(runId, {
eventType: 'hook_received', specVersion: SPEC_VERSION_CURRENT,
correlationId: hook.hookId,
eventData: { token: hook.token, payload: new Uint8Array([1]) },
}, { resumeId: 'resume_1', resumePayloadDigest: 'resume_1' })
)
);Result: zero rejections, and the log holds evnt_…003:hook_received and evnt_…004:hook_received, both with resumeId: 'resume_1'.
To be clear about provenance: this window is not introduced here — pre-PR, the same interleaving existed at the staging write (adopter stages the id-keyed path first → owner collides → bumps → duplicates). The nonce moves the collision from staging to promote, but the owner-loses arm is still resolved by bumping.
Suggested fix, symmetric with the one you added: run this occupant/isResumeEvent convergence for hook_received with a resumeId before bumpEventSlot, regardless of pinning — if the occupant at the lost position is this same resume, return it instead of bumping. The pinned case then falls out of the same check, and an unrelated occupant still bumps (unpinned) or conflicts (pinned) as today.
There was a problem hiding this comment.
Confirmed, and fixed in c6bf782.
I verified the asymmetry before changing anything: on a slot run the claim owner keeps its own id and eventIdPinned = !isSlotEventId(eventId) leaves it unpinned, while the adopter is pinned to the claimed position. So the loser of the promote can be the unpinned owner, it bumps, and a second hook_received lands for one resumeId.
The convergence now runs inside the publish loop, ahead of bumpEventSlot, for any hook_received carrying a resumeId, with no pinning condition. An occupant that is not this resume is the unrelated-event collision the bump exists for and still bumps, or conflicts when pinned. The post-loop pinned block is gone, since a resume that lost to its own committed event now returns from inside the loop, and reaching the end means the occupant is unrelated.
Regression guard: writes one event when the claim owner loses the position to an adopter. It mocks promoteExclusive to park whichever caller arrives first until the other has linked, which is the interleaving that decides the winner. Falsifiability check: restoring the eventIdPinned && guard makes it fail with expected [ { …(8) }, { …(8) } ] to have a length of 1 but got 2.
| expect(data.filter((e) => e.eventType === 'hook_received')).toHaveLength(1); | ||
| }); | ||
|
|
||
| it('keeps the log dense when two instances resume the same hook at once', async () => { |
There was a problem hiding this comment.
This test passes without the fix — I reverted the two events-storage.ts hunks (keeping the tests) and ran this file five times: tests 1 and 2 failed deterministically every run, but this one passed 5/5.
That matches the old code's behavior for this shape: with two live stagers and no terminal transition, the bumped-off slot always gets backfilled — the loser of the id-keyed staging write bumps to N+1, but the staging winner still promotes N, so the log ends dense either way. The hole needs the stager to be rejected (terminal marker / reap) or crashed, which is what test 1 stages.
So the PR description's "Each regression guard was verified to fail with the fix removed" doesn't hold for this one. Two options:
- make it a real guard by racing a terminal transition into the window (stager drawn and staged, then reaped, then a later writer draws the same slot), or
- keep it as-is but reword the description/comment to position it as a sanity check that the new promote-point arbitration keeps density under live-vs-live contention (which it does usefully exercise — the
'exists'→ bump path now only exists at the promote).
There was a problem hiding this comment.
You're right, and thanks for actually running it rather than reading it. With two live stagers and no terminal transition the pre-fix code also ends dense, because the writer bumped off the position is the one that goes on to publish it. The hole needs the stager to be rejected or killed, which is what the crashed-attempt test stages.
Rather than contrive a guard here, I reframed it honestly and let the new owner/adopter test carry the weight. It is now keeps the log dense under live contention on one position, and the comment says outright that density here is not a regression guard, plus what it does cover: arbitrating at the promote still resolves two instances drawing the same position, which is the CLI-plus-app configuration this backend supports (each instance's allocator watermark is its own, so both hand out the same candidate).
Also corrected the PR description, which claimed all three tests fail with the fix removed. True for tests 1, 2, and the new one; not for this one.
| # an absolute path so the app's cwd does not enter into it. `setupWorld` | ||
| # recomputes the same path for the harness process. | ||
| case "$APP_NAME" in | ||
| nextjs*|next-*) DATA_DIR_NAME=".next/workflow-data" ;; |
There was a problem hiding this comment.
This prefix glob doesn't mirror the harness's derivation. setupWorld (packages/core/e2e/utils.ts:507) uses substring matching:
const isNextJs = appName.includes('nextjs') || appName.includes('next-');so an app named e.g. example-nextjs would get .next/workflow-data from the harness but .workflow-data from this case — the exact silent split-brain the comment above warns about, where the app and the harness talk to different directories. Today it can't bite (only nextjs-turbopack/nextjs-webpack carry the repro fixtures, and both match), but since the whole point of this block is pinning the two processes to one path:
*nextjs*|*next-*) DATA_DIR_NAME=".next/workflow-data" ;;There was a problem hiding this comment.
Good catch. Fixed to *nextjs*|*next-*) so it mirrors setupWorld. I checked packages/core/e2e/utils.ts:507 and it is the substring form you quoted, so an app named example-nextjs would have sent the app to .workflow-data and the harness to .next/workflow-data, which is exactly the split-brain the block exists to prevent. Comment above the case now states why it is a substring match.
| if (await bumpEventSlot(attempt)) { | ||
| continue; | ||
| } | ||
| // A nonced path cannot already exist. Surfacing rather than |
There was a problem hiding this comment.
Nit: the comment is right that this can't be a real duplicate — which makes EntityConflictError ("Event already exists") a slightly misleading surface for it. EntityConflictError is the shape the runtime's concurrent-replay paths treat as a benign duplicate publish, so a genuine filesystem fault here would get absorbed as "someone else already wrote it" instead of surfacing as infra trouble. A WorkflowWorldError would keep the impossible case loud. Fine to leave if you'd rather not grow the error surface, since the branch is effectively unreachable.
There was a problem hiding this comment.
Taken. It is now a WorkflowWorldError. EntityConflictError is the shape the runtime reads as a benign duplicate publish, so raising it for a nonced path that cannot collide would absorb a filesystem fault as "someone else already wrote it". The comment says that.
Only one of the two takers of a resume claim is pinned. The taker that writes the claim keeps its own id, unpinned, because a slot is a position another instance also hands out for unrelated events and refusing to move would fail the append outright. The taker that adopts an existing claim is pinned to the claimed position. So the loser of the promote can be the unpinned owner, and a loser that bumps publishes a second `hook_received` for one resumeId. The log stays dense and both callers report success, but replay delivers the resume twice, which is what the dedup contract forbids. Run the occupant convergence inside the publish loop, before the bump, for any `hook_received` carrying a resumeId. An occupant that is not this resume is the unrelated-event collision the bump is for and still bumps, or conflicts when pinned. The post-loop pinned check is now redundant. Also: - staging-path faults raise WorkflowWorldError rather than EntityConflictError, which the runtime absorbs as a benign duplicate. - the repro script's app-name case mirrors `setupWorld`'s substring match so a future `example-nextjs` cannot split-brain the data dir. - the live-vs-live density test says what it actually guards: it passes without the fix, because a bumped-off position still gets published by the stager that won it.
pranaygp
left a comment
pranaygp
left a comment
There was a problem hiding this comment.
All four findings addressed in c6bf782, and I re-verified each empirically on the branch:
- Duplicate-resume window: the convergence now runs inside the publish loop before
bumpEventSlot, ungated on pinning — exactly the symmetric fix. I confirmed the newwrites one event when the claim owner loses the position to an adopterguard is real: with that hunk reverted it fails deterministically (length of 1 but got 2, the duplicate), and with it the file and the full suite pass (546/546,tsc --noEmitclean). - Density test: honestly reframed as not-a-regression-guard, and the PR description now matches what the tests actually prove.
- Script glob mirrors
setupWorld's substring match, with the reasoning in a comment. - Staging fault now raises
WorkflowWorldErrorso infra trouble can't be absorbed as a benign duplicate.
One non-blocking observation, pre-existing and inherited rather than introduced: isResumeEvent matches an occupant with resumeId === undefined by position, so the in-loop convergence could in principle adopt a plain-path hook_received (no resumeId) for the same hook as this resume's committed event, dropping the resume's payload. That requires concurrently mixing the lazy and plain resume paths on one hook plus a slot collision — outside the dedup contract's supported shape, and the same predicate already governs converge/findCommittedResumeEvent. Fine to leave; noting it in case slot-run positional matching ever gets tightened.
|
CI update: everything is green except I opened #3503 to fix it on main. It is a marginal budget rather than a step regression: same 245 tests, whole-file duration on the Windows runner went 143491ms (last green) to 154816ms (first red), 8% apart. Since |
|
No backport to This is a genuine correctness fix, but it targets code that only exists on To override, re-run the Backport to stable workflow manually via |
…oles (#3492) Co-Authored-By: shalabhchaturvedi-7802 <shalabh.chaturvedi@vercel.com>
2 participants
What
Three fixes in
@workflow/world-local, plus the local event-log race repro script gains a--world locallane.The corruption
hook_receivedis the one event that does not publish straight intoevents/. It stages under.locksfirst, so a terminal transition can reap it before it ever becomes reader-visible (#2987). That staging path was keyed by the event id alone, and a collision on it bumped the writer to the next slot.Under slot event ids (#3389) that bump is wrong. The slot allocator probes
events/and nothing else, so a staged file is not evidence the position is taken. Bumping moves the writer past a position nothing will ever fill,notePublishedSlotadvances the watermark past it, andscanRunEventIdsis max-based so no later writer backfills. The runtime reads the missing position as a durable hole and fails the run withCORRUPTED_EVENT_LOG.Two ways in:
finallythe kill skips, and the only other reaper runs on a terminal transition the run has not reached. Every later writer that draws that slot bumps off it, permanently.Provenance: staging arrived in
850777a03b(#2987) when ids were ULIDs, where the old comment was correct that the path "can only be occupied by a previous crashed attempt of this very event".6786db9953(#3389) turned ids into positions and kept the id-keyed staging name.Fix: the staging name carries a nonce, so it is private to one attempt. The slot is then arbitrated only where it is actually taken, at the promote. This restores the file's own stated invariant: a slot is claimed by the publish that occupies it, never reserved ahead of a write that might still be rejected.
The spurious conflict, and the duplicate resume
When a resume loses the publish, the event now at that position can be the same resume, written by the other taker of the claim. That is the convergence the claim exists to force, and
convergeearlier in the function already answers it with the committed event. It just could not see it yet, because the other taker had not published when this attempt read.The first pass answered that only for a pinned loser, which left the symmetric case open (caught in review). Only one of the two takers of a claim is pinned: the taker that writes the claim keeps its own id, unpinned, because a slot is a position another instance also hands out for unrelated events and refusing to move would fail this resume's append outright. The taker that adopts an existing claim is pinned to the claimed position. So the loser of the promote can be the unpinned owner, and a loser that bumps publishes a second
hook_receivedfor oneresumeId. Nothing looks wrong afterwards (the log stays dense, both callers report success) but the resume is delivered twice on replay.Fix: run the occupant convergence inside the publish loop, ahead of the bump, for any
hook_receivedcarrying aresumeId, with no pinning condition. An occupant that is not this resume is the unrelated-event collision the bump is for and still bumps, or conflicts when pinned. Both takers return the one committed event, matching the dedup contracthook-resume-dedup.test.tsalready asserts. ReportingEntityConflictErrorinstead gave the caller an error it cannot act on for a resume that did land (HTTP 500, queue retry).Separately, a failure to stage under the nonced path now raises
WorkflowWorldErrorrather thanEntityConflictError: a nonced path cannot collide, so it is a filesystem fault, andEntityConflictErroris the shape the runtime absorbs as a benign duplicate publish.Repro script
scripts/event-log-race-repro-local.shwas postgres-only. It now takes--world postgres|local(defaultpostgres, unchanged). Under--world localit exportsWORKFLOW_TARGET_WORLD=localplus an absoluteWORKFLOW_LOCAL_DATA_DIRandWORKFLOW_LOCAL_QUEUE_CONCURRENCY, clears the data directory instead of the queue, and skips all container bring-up, migration, and teardown.pnpm run test:e2e:event-log-race-repro:local --world localTesting
New
packages/world-local/src/storage/hook-staging-slots.test.ts, 4 tests. Three are regression guards verified to fail with the fix removed:[1, 2, 4]instead of[1, 2, 3].hook_receivedis written and both takers return it. This one mockspromoteExclusiveto park whichever caller reaches it first until the other has linked, since the outcome hinges on that interleaving. Restoring theeventIdPinned &&guard makes it fail withto have a length of 1 but got 2.The fourth,
keeps the log dense under live contention on one position, is not a regression guard and its comment says so: with two live stagers and no terminal transition the pre-fix code also ended dense, because the writer it bumped off the position was the one that went on to publish it. It covers that arbitrating at the promote still resolves two instances drawing one position.Full world-local suite: 546/546 across 16 files.
tsc --noEmitclean.On the storm harness, stated plainly: it has never produced a
CORRUPTED_EVENT_LOGoutcome or an on-disk hole against world-local, across one 14-run pass and two 16-run passes before the fix. The corruption is demonstrated by the unit test, not by the storm. What the storm does show is the conflict volume: ~12-27EntityConflictErrorper pass before, 1 after (ahook_createdbenign duplicate, which is the documented path), with all 14 runs completing and every run dense on disk (count == max, 8931 event files checked).This matches the note now in AGENTS.md: world-local's storms come out clean far more often than world-postgres's, so reach for a unit test in
packages/world-local/src/storage/when a suspected filesystem race can be staged directly.