[core] Ignore duplicate events per event class instead of failing the run - #3381
Conversation
🦋 Changeset detectedLatest commit: 1fbb446 The changes in this PR will be included in the next version bump. This PR includes changesets to release 20 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✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ vercel-multi-region
|
📊 Workflow Benchmarks⏳ Benchmarks are running for
commit Backend:
📜 Previous results (2)c1cad50Mon, 10 Aug 2026 22:51:29 GMT · run logs
284986dFri, 07 Aug 2026 01:14:58 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 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 |
VaguelySerious
added
the
event-log-race-repro
Event Log Race ReproNo event-log regressions in the latest repro job. Run History
Latest Scenario Breakdown
|
VaguelySerious
changed the title
VaguelySerious
changed the title
d6f8d17 to
9a5e0fe
Compare
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: |
TooTallNate
left a comment
TooTallNate
left a comment
There was a problem hiding this comment.
Reviewed at 9a5e0fe (4 behind main, merges clean, no overlap with the interim commits).
Verified locally:
- Full core suite green: 92 files, 2051 passed / 3 expected fail; duplicate/consumer/workflow tests also green under
WORKFLOW_RETAINED_VM=0. - Red-test proof: main's
events-consumer.ts/workflow.ts/world files under this PR's test files → both duplicate cases fail with the production divergence, and the negative control (still reports divergence for an event repeating nothing in the log) passes on both. Load-bearing, with the false-negative direction pinned.
The properties checklist, independently confirmed in code:
- Marking is consumption-only —
recordEventClassfires solely inoffer()when a callback consumed the event, andskipDuplicateEventdeliberately does not mark. So a skip requires a consumed precedent: an event class first seen unclaimed falls through to park/divergence exactly as before. That conservatism is what makes the negative control meaningful. - Skip-before-park ordering — the docstring's
run_cancelledargument is right: parked-then-stranded-at-terminal-end is precisely the divergence this exists to avoid, and I verified themayPark=falseend-of-log recheck correctly bypasses both the identity guard and the skip (a parked event isn't at the cursor, so neither applies). - Clock — skips bypass
notifyConsumedEvent; the run_started dedup in the lifecycle subscriber (consume first, decline repeats → deferred check → skip, since run events share theundefined-correlation bucket) closes the double-advance hole the old always-consume behavior had. Covered by the dedicated clock test. - Deliveries excluded —
hook_received/hook_conflictclassless, keeping the parking path; the one-shotresolvedguard remains as a backstop behind the skip forwait_completed, so the two mechanisms agree rather than race. - Live consumers always win — the skip is consulted only after every callback declined, inside the deferred window behind the delivery-idle gate (#3439), so a retry's
step_startedstill reaches its consumer and still counts as an attempt. Thenever takes an event a registered callback still wantstest pins this.
The design fit is what convinces me: with bump-and-report, the backend deliberately never refuses a stale write — duplicates are an expected product of that design, and until now the reader punished the run for what the writer permitted. First-of-class-wins is deterministic across replays (every replay reads the same first event at the same position), and the alternative — CORRUPTED_EVENT_LOG on a log whose observable history is fine — told the operator nothing actionable. The onDuplicateEvent info-log keeps the two-replays-wrote evidence visible without making it fatal.
One residual worth naming (no action needed): a duplicate step_terminal with a different payload (a nondeterministic step raced by two replays to different results) is silently dropped in favor of the first. That's the correct and pre-existing semantics of the log — but if onDuplicateEvent ever grows a metric, distinguishing same-class-different-outcome from pure re-commits would be the interesting split to count.
CI: only the ubiquitous python-workbench baseline deploy failure. Changeset (core + world patch) fits.
The event-class table in the PR description with an explicit row for every type — including the ones that never reach the check and why — is the reviewability standard the rest of us should be held to. Approving.
shalabhc
left a comment
shalabhc
left a comment
There was a problem hiding this comment.
EventsConsumer tracks which event classes it has already passed for each entity, keyed :. When no callback wants an event and the cursor already passed that class for that entity, the cursor moves past it instead of reporting divergence.
I think the EventConsumer should just ignore these in all cases where it knows its a duplicate? Why even test if a callback wants one of these events? It should be as if these events dont exist in the stream. I think we should just remove these events as early as possible. Eg when we take the next event in the log, see if it is a dup*, if so, just short circuit and continue to the next event?
*dup = excludes valid retries
| * that are also parkable would otherwise be handled inconsistently: a | ||
| * repeated `wait_completed` is declined by park anyway (its {@link resolved} | ||
| * guard asks the same question for one-shot types), but a repeated | ||
| * `run_cancelled` would be parked, and a parked event nothing claims strands |
There was a problem hiding this comment.
I don't think this paragraph's scenario is reachable because
nothing consumes a run terminal event? So they will always get parked anyway.
There was a problem hiding this comment.
(AI) You're right, and it was worse than unreachable prose: the whole run_terminal class entry was dead. Recording a class requires a consumer to take an event of it, and nothing takes a terminal run event, so the class could never be recorded and a second one could never match. Verified directly: with two run_cancelled in the log, onDuplicateEvent is never called and both park.
Removed the three run-terminal entries from ENTITY_EVENT_CLASS_BY_TYPE and dropped the paragraph. The docstring in events.ts now says why they are absent rather than implying they are handled, and the PR table row is corrected. Added a test asserting a duplicate run_cancelled goes to parking and not to the skip, so nothing re-adds the entry on the assumption it works.
| // Only subscribe() cancels the check, so this is reachable. | ||
| return; | ||
| } | ||
| if (this.isDuplicateEvent(currentEvent)) { |
There was a problem hiding this comment.
Does this mean a single duplicate in a run will cost 100ms per run for every replay? IIUC this will wait the 100ms for the duplicate events that will never have a consumer arrive.
I think just removing the dup events early might be best (suggested in top comment)
There was a problem hiding this comment.
(AI) Confirmed and fixed. Measured on a unit harness driving the real consumer: 0 stragglers = 6ms, 1 = 105ms, 3 = 310ms, so it was one full window per straggler, serially, on every replay. In production over a 2h window 0.75% of runs carry at least one, and the p99 among those runs is 155 stragglers (max 726), which would have been ~72s of pure waiting per replay on the worst ones.
The skip now happens in the synchronous pass that offers the event, before the deferred check is scheduled. The window is safe to skip here specifically: seenEventClasses only grows when a consumer takes an event, so a recorded class means that entity's consumer already registered in this same replay, and correlation ids are minted as monotonic ULIDs, so no consumer arriving later can want an id the cursor already passed. A test pins the walk to finish inside one window.
On "just removing the dup events early": I kept the offer-first ordering, because a live consumer is the only thing that can tell a legitimate repeat from an inert one. A retry's step_started, or a second step_created on a step that has not finished, is consumed by the step's live consumer and feeds inline-ownership; attempt on step_started is optional, so the log cannot disambiguate them structurally. Filtering before offering would drop those. Verified the live case takes them with no skip involved.
| // the consumer skips the rest rather than advancing the workflow clock | ||
| // twice. | ||
| if (event.eventType === 'run_started') { | ||
| if (consumedRunStarted) { |
There was a problem hiding this comment.
Just a question: can we produce two run_started?
There was a problem hiding this comment.
we shouldn't be able to, though with the new idempotent hook work coming up, technically a race can happen where this might be the case
There was a problem hiding this comment.
(AI) Noted in the code for the hook case: the hook_created entry is safe only because the runtime mints hook identity today, so a second hook_created under one id can only be a straggler. If caller-supplied idempotency keys ever let two distinct hooks share an id, that entry has to go, and the docstring says so.
| step_started: 'step_started', | ||
| step_retrying: 'step_retrying', | ||
| step_completed: 'step_terminal', | ||
| step_failed: 'step_terminal', |
There was a problem hiding this comment.
step_completed followed by step_failed seems like a bug somewhere. Or can it be legitimately produced? We should probably just log this discrepancy as an error or warning, while still ignoring the 2nd step terminal event.
There was a problem hiding this comment.
I can't imagine a real case where this would happen. Let's error log on this, why not
There was a problem hiding this comment.
(AI) Implemented. onDuplicateEvent now receives the type of the event that recorded the class, so workflow.ts logs at error when the repeat decides the class differently (step_completed then step_failed) and stays at info for a plain re-commit of the same type. The second event is still ignored either way: the first outcome is what every replay observes, so dropping it is the only consistent choice, but it is worth seeing in the logs. Covered by a test.
| // cancelled has definitely fired. | ||
| function waitPastDeferredCheck(): Promise<void> { | ||
| return new Promise((resolve) => | ||
| setTimeout(resolve, DEFERRED_CHECK_DELAY_MS * 2) |
There was a problem hiding this comment.
Minor:
Should this use MIN_DEFERRED_CHECK_DELAY_MS or a derived value instead?
There was a problem hiding this comment.
(AI) Done. That block now stubs WORKFLOW_DEFERRED_CHECK_DELAY_MS to MIN_DEFERRED_CHECK_DELAY_MS and derives its wait from it, so nothing in the suite hardcodes a number. One test deliberately unstubs and runs at the real DEFERRED_CHECK_DELAY_MS: it asserts the walk finishes inside a single window with three stragglers, and shortening the delay would erase the signal it is testing for.
Move the duplicate-class skip onto the synchronous walk instead of the deferred unconsumed-event check. The window exists for a consumer that has yet to register, and no such consumer can want an event of a class this replay already consumed, so paying it cost DEFERRED_CHECK_DELAY_MS per straggler per replay for nothing. Drop the run-terminal class entries: recording a class requires a consumer to take an event of it, and nothing consumes run_completed / run_failed / run_cancelled, so those entries could never match. Report the type that recorded the class alongside the duplicate, so a repeat deciding an already-decided outcome differently logs at error rather than info.
The window is a lower bound on when the timer becomes eligible, not on when it runs: the Windows runner took longer than four of them, so the assertion that a check fired read as a check that never fired.
|
Backport PR opened against |
3 participants
Concurrent replays of one run share a single event log and write to it without a currency guard. A replay working from a stale prefix can commit a second
step_created/step_started/wait_createdfor an entity the log already records one of. Those writes are committed but inert: every replay reads the first event of that class at the same log position, so the straggler cannot change what the workflow observes.Today the straggler has no consumer left to claim it, because the entity's consumer deregistered when it took the step's result. That surfaces as
ReplayDivergenceErrorand, after retries, a terminalCORRUPTED_EVENT_LOGon a run whose log is fine.What changes
EventsConsumertracks which event classes it has already consumed for each entity, keyed<class>:<correlationId>. When no callback wants an event and this replay already consumed that class for that entity, the cursor steps over it instead of reporting divergence.Classes are independent, and they stack: a step whose result is in the log has still recorded exactly one
step_created, so a second one is ignorable, and so is a secondstep_started. Types sharing a class are the mutually exclusive outcomes of one decision, so the first one recorded is the one that counts.What the runtime now allows and disallows
Every row below describes an event that no registered callback wanted. The skip is consulted only after every callback declined, so nothing here changes what a live consumer receives.
run_createdrun_startedrun_startedrun_completed,run_failed,run_cancelledattr_setsetAttributescall.step_createdstep_createdstep_startedstep_startedstep_retryingstep_retryingstep_completed,step_failedstep_terminalwait_createdwait_createdwait_completedwait_completedhook_createdhook_createdhook_disposedhook_disposedhook_receivedmain.hook_conflictmain.Properties worth checking in review
step_startedstill reaches the step's live consumer and still counts as an attempt; only the copies nobody claims are skipped. This is also what makes "a completed step still accepts morestep_created/step_started" work: after completion there is no consumer left, so those fall through to the skip. Offering first is what distinguishes a legitimate repeat from an inert one — the log cannot do it structurally, sinceattemptonstep_startedis optional.seenEventClassesonly grows on consumption, which means the entity's consumer registered in this same replay, and correlation ids are minted monotonically so a later one cannot reuse the id. Paying the window anyway would costDEFERRED_CHECK_DELAY_MSper straggler per replay, serially. Measured on the unit harness: 0 stragglers = 6ms, 1 = 105ms, 3 = 310ms. In production over a 2h window, 0.75% of runs carry at least one straggler and the p99 among those is 155 of them (max 726), so the deferred variant would have added up to ~72s per replay on the worst runs. A test pins the walk to finish inside one window.onConsumedEvent, so a log containing a straggler produces the same timestamps as one that does not. Covered by a test.error.onDuplicateEventreceives the type of the event that recorded the class, soworkflow.tscan tell a plain re-commit (step_completedtwice,info) from two replays racing a nondeterministic step to opposite outcomes (step_completedthenstep_failed,error). The first outcome is what every replay observes either way; the second is dropped, and that is worth seeing in the logs.hook_receivedis not a repeat of a decided outcome and has no class to match against. Those keep the parking path they have onmain.hook.test.tsalready covers a post-disposehook_receivedbeing legitimately consumed, which is whyhook_disposedno longer suppresses later deliveries.hook_createdskipping assumes the runtime mints hook identity. It does today, so a secondhook_createdunder one id can only be a straggler. If caller-supplied idempotency keys ever let two distinct hooks share an id, that entry has to go.