[measurement] Call-site-addressed correlation ids - #3179
Draft
VaguelySerious wants to merge 13 commits into
Draft
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>
Correlation ids are the Nth draw of one per-run ULID sequence, which makes every id an ordinal: two concurrent replays that disagree about a single event assign different ids to every entity after it, so one replay appends events the other can neither match nor consume and the run fails with CORRUPTED_EVENT_LOG out of a one-event difference. With WORKFLOW_CALLSITE_CORRELATION_IDS=1 an id is derived from the call site that creates the entity — a step's name plus an argument fingerprint, a hook's pinned token — plus a per-scope invocation counter, so the same entity gets the same id in both replays and a late write collides idempotently instead of renaming everything downstream. Ids stay syntactically valid ULIDs; hook tokens for unpinned hooks are derived from the correlation id rather than drawn from the run's PRNG stream. The flag defaults off, and with it off the generator is the positional sequence itself, so nothing about the default path changes. Also sets the flag on the nextjs-turbopack workbench for the race repro.
🦋 Changeset detectedLatest commit: 0c38930 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 |
Contributor
VaguelySerious
added
the
event-log-race-repro
…ation-ids # Conflicts: # packages/core/src/delivery-barrier-coverage.test.ts # packages/core/src/step-delivery-hop-count.test.ts # packages/core/src/step-delivery-ordering.test.ts
Contributor
🧪 E2E Test Results❌ Some tests failed ❌ Failed E2E Tests▲ Vercel Production (1 failed)nextjs-turbopack (1 failed):
📦 Local Production (1 failed)nextjs-turbopack-stable (1 failed):
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 Repro95 of 1400 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
Showing 20 of 95 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 PR — not for merge as-is. Fix attempt 5 for the residual
CORRUPTED_EVENT_LOGin the storm repro. Labelledevent-log-race-reproso it can be compared against the #3172 baseline (step-storm 554/600, hook-storm 177/600, hook-sleep 0/200 corrupted). Based on the same commit as #3172/#3177 so the numbers are comparable.What this changes
Correlation ids today are the Nth draw of one seeded ULID sequence per run (
generateUlid: () => ulid(fixedTimestamp)), so every id is an ordinal. Two concurrent replays of the same run that disagree about a single event therefore assign different ids to every entity after that point, and whichever writes second appends events the other can neither match (ReplayDivergenceErroronstepName) nor consume (onUnconsumedEvent) — a one-event difference amplified intoCORRUPTED_EVENT_LOG.With
WORKFLOW_CALLSITE_CORRELATION_IDS=1(default off) an id is instead derived from the call site:Scopes: steps use the step name plus a fingerprint of the arguments; hooks use a pinned token when there is one; waits, attribute writes and abort controllers use a per-kind scope. Ids stay syntactically valid 26-char ULIDs, so the backend's id validation is unaffected. Hook tokens for unpinned hooks are derived from the hook's correlation id instead of drawn from the run's PRNG stream, which was positional for the same reason.
The consequence for the repro: a write that lands out of order becomes an idempotent collision with the entity it duplicates, instead of renaming everything downstream of it.
Why the amplifier and not the write path
The three preceding attempts all targeted write admission and none moved the step-storm number: the server-side step identity fence (no effect), the event-index completeness fix (#669, no effect on this workload), and the run-level append-tail fence (#670, neutral on step-storm and worse on hook-storm — its own metrics showed 0.6% of writes rejected and zero false positives, i.e. it is blind to the writers that matter). Measured directly on 12 corrupted hook-storm logs from each of the baseline and fence runs, the rate of
step_createdwrites landing at a lower ordinal than one already observed was 53% and 52% — unchanged by any admission check, because both replays are legitimately live and neither snapshot has a hole. Only sequential replays helped (#3175, hook-storm −53%), by removing the concurrency rather than the amplification.Flag off is the positional sequence itself
With the flag off,
createCorrelationIdGeneratorreturns the run's existing monotonic sequence unchanged, so there is one call path and no behavioural difference.STABLE_ULID(stream ids) keeps drawing from that sequence under both schemes.Tests
packages/core/src/correlation-id.test.ts— 14 unit tests: id shape anddecodeTimeround-trip, shape parity with the positional scheme, the positional scheme's rename behaviour asserted as the control, call-site stability across a prefix disagreement, per-scope ordinals, scope and run separation, zero draws from the run PRNG, hash diffusion over 200 near-identical scopes,fingerprintValuedeterminism/cycle/BigInt safety,deriveHookTokendeterminism and sensitivity.packages/core/src/callsite-correlation-ids.test.ts— 5 end-to-end tests throughrunWorkflowwith no hardcoded ids. Both schemes run the same scenario: a canonical replay that consumed three step completions and a stale one that consumed two, both reaching the same next call site. Positional ⇒ different ids (the corruption mechanism, asserted so the test is known to discriminate); call-site ⇒ the same id.Known gaps, disclosed
workflow.test.ts(32),runtime/wait-completion-replay.test.ts(4) andruntime/precondition-guard-replay.test.ts(2). All of them pin literal positional-scheme correlation ids in fixtures (111 hardcoded id occurrences inworkflow.test.ts) or reconstruct the sequence locally frommonotonicFactory. This is fixture coupling, not a runtime failure; the new e2e test file covers the flag-on path with derived ids. Those fixtures need rewriting before the flag could ever default on.hash128is a non-cryptographic mixer. It is only required to be deterministic and well-diffusing, and its output must not outlive a deployment's replays.Measurement setup, to be reverted before any merge
workbench/nextjs-turbopack/vercel.jsonsetsWORKFLOW_CALLSITE_CORRELATION_IDS=1on the preview deployment. No backend change is needed — the wire format is unchanged.Two costs/limits worth knowing before reading the numbers
sleep()has no distinguishing input, so wait ids remain ordinals within the wait kind. Two replays that disagree about how many sleeps were created still rename subsequent waits. The storm workflows put onesleep(watchdogMs)per branch against roughly four steps, so most of the log is call-site addressed, but this is the obvious residual amplifier and the reason a real end state wants a compiler-injected static call-site id rather than a runtime per-scope counter.JSON.stringifyon every step creation. Those arguments are already serialized for the event write, so this is a constant-factor addition rather than a new order of magnitude, but it is a per-creation cost on large payloads.