[test] Event log corruption fixes + append-tail-fence backend - #3177
Draft
VaguelySerious wants to merge 12 commits into
Draft
[test] Event log corruption fixes + append-tail-fence backend#3177VaguelySerious wants to merge 12 commits into
VaguelySerious wants to merge 12 commits into
Conversation
…by event-log position Two production runs on `@workflow/core@5.0.0-beta.36` burned all three divergence-recovery replays at the same event and terminated with CORRUPTED_EVENT_LOG: wrun_41KYJENABV0GSF5YTE9EETV5DD (step vs wait) wrun_41KYJEE01S0GPC9RWT5MEKVCX8 (step vs hook) Replay divergence: step event step_created for step_X belongs to "A", but the current step consumer is "B" `useStep` proxies draw deterministic ULIDs in invocation order, so the ULID -> stepName allocation is a function of the order in which promise resolutions are delivered to workflow code. The delivery-barrier registry pinned that order to event-log position for hook payloads and wait completions, but step results were delivered straight off the serial `promiseQueue` — and their latency varies between replays of the SAME invocation, because the first replay pays full hydration while later replays memo-hit primitive results in the shared `ReplayPayloadCache`. A step completion adjacent in the log to a `wait_completed` was therefore delivered wait-first on a cold replay and step-first on a warm one; whichever order the invocation that wrote the follow-up `step_created` events happened to see became law, and every replay computing the other order diverged permanently. Step results and step failures now register a 'step' delivery barrier at their event-log index and resolve from a detached continuation after every relevant earlier-in-log delivery, mirroring the hook payload path: hydration stays inside the serial queue slot (which also releases `pendingDeliveries`), while the barrier wait and the resolve run off the queue so a queue slot never blocks on a resolution the queue itself drives. Waits and hook payloads likewise defer behind earlier step results. Two details are what actually make the ordering hold, and both were found by testing rather than by reading the code: The deferral set is captured while CONSUMING the event, not at the start of the hydration slot. Captured at slot start it is not merely less deterministic, it is usually empty: an earlier delivery whose own slot runs first on the serial queue has typically already resolved and deregistered its barrier before the later slot begins, so the later delivery does not defer at all. Every event in one drain window is consumed before any slot runs, so consumption time sees all of them. A delivery that had to wait then yields a macrotask before resolving. An earlier delivery being "delivered" only means its `resolve()` ran; the branch it woke may need arbitrarily many further microtask hops before it reaches its next `useStep` call (a `for await` over a hook resumes the generator, settles the promise from `next()`, and only then runs the loop body). Ordering the `resolve()` calls alone therefore buys a fixed hop or two of margin and leaves a hop-count race that holds only for the shortest consumers; yielding a macrotask lets the earlier branch drain completely, whatever its shape. One asymmetry is load-bearing: a step result skips any earlier delivery that will not resolve on its own, i.e. one blocked directly or transitively on a buffered hook payload no consumer has claimed. Such a payload is delivered only when the workflow next reads the hook, and reaching that read commonly requires the step result itself, so gating the step on it stalls the run until the barrier's idle safety net fires — which then releases every delivery queued behind that payload at once and loses the very race the ordering exists to protect. Waits and hooks keep gating on unclaimed payloads, where waiting for the claim IS the guarantee. Tests come in two files. `step-delivery-ordering.test.ts` is byte-identical to the file in the repro-only companion PR #3137 apart from two `it.fails` markers there (which let a repro-only branch have green CI); `sed 's/it\.fails(/it(/g' | cmp` verifies it. Each of its five cases replays one committed log twice through a shared `ReplayPayloadCache`, and the two warm-replay cases fail on main with the production error text. `step-delivery-hop-count.test.ts` exists because those five cases cannot tell "delivered in log order" apart from "resolves a hop or two later than before". It replays logs a live run legitimately produced — the live invocation received the two events in separate deliveries, so the first branch finished long before the second event existed — while the replay receives both in one drain window, and pads the consumer with a varying number of extra awaits so hop count is the only variable. It covers step results against both wait completions and hook payloads, plus step FAILURES against wait completions, since a rejection decides whether a `catch` continuation runs and so which ULID the `useStep` there draws. All 18 cases fail on main; of the 12 that predate the macrotask, 9 still fail with the resolve-ordering-only version of this fix; all 18 pass here. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Signed-off-by: Pranay Prakash <pranay.gp@gmail.com>
Follow-up on the step-delivery barrier work, addressing three cases the registry did not yet cover. Each has a regression test in the new `delivery-barrier-coverage.test.ts` that reproduces the production `ReplayDivergenceError` when its fix is reverted. - Step results now defer behind earlier STEP results. The old exclusion assumed the serial `promiseQueue` fixes step-vs-step order, which stopped holding once a step began resolving from a detached continuation instead of its queue slot: two steps consumed in different drain windows can disagree on their deferral set, and the earlier one — parked on the macrotask yield — gets overtaken. - `sleep.ts` and `hook.ts` (waiting-consumer path) now capture their deferral at event-consumption time, as `step.ts` already does. Reading the registry after their queue work misses an earlier step or hook that delivered and retired its barrier in the meantime, skipping both the gate and the macrotask yield. The buffered hook payload path deliberately keeps evaluating at claim time; a consumption-time snapshot there stalls the e2e `hookWithSleepWorkflow`. - Abort deliveries participate in the registry. `_setAborted` fires the signal's listeners, which may invoke a step and draw a ULID, so an abort is as branch-deciding as any other delivery. Also memoizes `resolvesOnItsOwn`. The walk is exponential in the number of live hook/wait barriers, and the registry is not bounded — a fan-out of `Promise.race([hook, sleep])` branches accumulates one barrier per branch per kind (49 measured for 24 branches). At 40 barriers a single scan took 92s before, and is instant after.
…process A replay-context event creation previously described its snapshot with a single watermark, which only proves no event landed above it. It cannot detect a *missing* event below it, so a replay working from a log with a hole still committed events derived from that hole — and because correlation IDs are positional ordinals of one seeded sequence, a one-event difference renames every downstream entity and corrupts the log. Creations now also send the snapshot's event count and its cursor, and a rejection restarts the replay inside the same invocation instead of re-posting the rejected payload (whose IDs the corrected log invalidates) or paying a queue round trip. A world may attach the missing events to its 412, in which case the first restart needs no event-log request. Also guards the suspension `attr_set` write, and re-sorts a merged event log by event ID when an append arrives out of order. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Also makes the v4 event tests derive their mock origin from the override like the rest of the file already does, so a non-empty override does not fail unit tests. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The matching world-vercel guard shipped and is live in production, so the e2e lanes exercise both halves against the default endpoint. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Resolves the overlap with #3110, which introduced the same event-log merge consolidation this branch had added as `mergeEvents`: `appendUniqueEvents` now carries the optional id set from main plus the out-of-order re-sort and warning, and `mergeEvents` is gone. Main's `withPreconditionRetry` edit drops out with the function itself. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Contributor
🦋 Changeset detectedLatest commit: 700ba3d The changes in this PR will be included in the next version bump. This PR includes changesets to release 21 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
Contributor
🧪 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
|
Contributor
📊 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 |
Contributor
Event Log Race Repro805 of 1400 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
Showing 20 of 805 non-completed runs. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Measurement-only branch. Identical SDK code to #3172, with
WORKFLOW_SERVER_URL_OVERRIDEpointed at a backend preview that runs an append-tail fence instead of the missing-event count check.Why: on the corrupted runs studied so far the losing writer's snapshot has no hole in it — it is a complete prefix of the log, just an old one. The count check compares
recordedAtOrBelow(W)against the client's count, so a complete-but-stale prefix passes by construction, which is whystaleverdicts stay at 0 even with the index fixed (#3172). Under positional correlation IDs staleness alone is fatal: a prefix that is short by one event renames every entity after it.The fence rejects unless the snapshot is the tail of the log, crediting each suspension's sibling creates to the snapshot they share so they don't fence each other.
Purpose of this PR is the
event-log-race-reprocomparison against #3172's run (554/600 step-storm, 177/600 hook-storm, 0/200 hook-sleep). Not for merge.