[core] Re-dispatch a pending step whose dispatch ended without a terminal event - #3465
[core] Re-dispatch a pending step whose dispatch ended without a terminal event#3465VaguelySerious wants to merge 15 commits into
Conversation
A pending step is handed to the queue under an idempotency key equal to its correlation ID. Queues dedupe a key for the lifetime of the message sent under it, so once a dispatch has been accepted every later replay's re-send is absorbed. That is what keeps concurrent wake replays from multiplying the dispatch, but it also means a step whose message never produces a step_started can never be dispatched again: the run replays forever with one pending step nothing will execute, reaching no terminal state and raising no error. Give those dispatches an epoch derived from the step's durable step_created timestamp. Every replay computes the same epoch, so fan-out stays capped at one message per epoch, while a step still unstarted a full watchdog interval later gets a key the queue has not seen and is dispatched again. A suspension also arms a timer on the soonest boundary, since a run whose only outstanding work is the lost dispatch would otherwise never replay. Scope is steps awaiting their FIRST step_started. A started step is either running (no client-visible completion deadline) or inline-owned, which the ownership lease and its backstop already cover. Both VM engines dispatch pending steps, so both take the epoch key and the boundary wake.
🦋 Changeset detectedLatest commit: 81d75f7 The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 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 |
📊 Workflow Benchmarkscommit Backend:
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 183209ms → this run 155363ms (Δ -27846ms, -15%) 📜 Previous results (3)596021aTue, 11 Aug 2026 22:03:31 GMT · run logs
22f54b9Tue, 11 Aug 2026 20:57:56 GMT · run logs
b9f2ca4Tue, 11 Aug 2026 19:43:41 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 |
🧪 E2E Test Results✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ vercel-multi-region
|
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 6 fail of 42 total
Full trace: 🟢 Append-only log — 0 fail of 42 total
Full trace: |
The watchdog keyed off the replay-observed step_created, so the suspension that creates a step dispatched under the bare key with no boundary wake armed. Both engines now stamp the creation timestamp from the write itself, putting the step in scope from its first hand-off.
Event Log Race ReproNo event-log regressions in the latest repro job. Run History
Latest Scenario Breakdown
|
A pending step's queue dispatch is keyed by its correlation ID, and a queue dedupes that key for the lifetime of the message sent under it. So once a dispatch stops making progress, every later replay's re-send is absorbed and the run replays forever with one step nothing will finish. The watchdog already covered a step that was never delivered. It did not cover the other shape: the message is delivered, the step writes step_started, and the invocation running the body disappears before writing a terminal event. Inline ownership arms a backstop wake at the lease for exactly that, but the re-dispatch that wake triggers carried the bare correlation ID the queue had already claimed, so the recovery was deduped away and the run went silent permanently. Measured on the race repro: 432 replays in 57s, the last one 0.6s past the lease boundary, then nothing for the remaining 25 minutes of the run. Both shapes now share one deadline, dispatchLostAtMs: a watchdog interval after step_created for an unstarted step, the end of the ownership lease for a started one. Past it the key is epoch-scoped and a boundary wake is armed, and the epoch advances once per watchdog interval so a lost recovery is itself retried. Anchoring the started case on the lease rather than on a watchdog interval is what keeps healthy long-running bodies from being duplicated. A step in step_retrying stays out of scope: its retry is queued under the bare key with a backoff that can legitimately exceed either deadline. The repro harness called a run stuck after 4 minutes, well inside the runtime's own longest recovery deadline, so a run on its way back was reported as permanently stranded. Its run timeout is now derived from the lease plus a watchdog interval instead of being a second copy of a number the runtime owns.
Reconciles the re-dispatch watchdog with #3365's resilient step dispatch: - The watchdog epoch is now a suffix on #3365's step-identity dispatch key rather than a competing key scheme, so every producer of a step message still shares one key while a lost dispatch can still be re-sent. - Steps the suspension handler published in parallel with their step_created are skipped by the dispatch pass but still count for the boundary wake: their message can be lost too, and that suspension is the only one that will see them before something else has to wake the run. - The parallel create+publish paths (node and quickjs) stamp the step's creation timestamp, which is what anchors the watchdog from the first hand-off on.
The wake's delay was capped at one watchdog interval, but a started step's boundary sits at the end of its ownership lease, ~13 minutes further out. The wake landed early, computed the same epoch, re-armed the boundary-keyed message the queue still held a claim for, and was absorbed, leaving the run with no timer at all. The ceiling now covers the larger of the two deadlines and exists only to bound clock skew. Also corrects the module docs: an unacked queue delivery is redelivered on its own, so the watchdog is not about lost messages. It is about dispatches that ended without a terminal event and have nothing outstanding to retry them.
The watchdog does not compensate for a queue dropping messages: an unacked delivery is redelivered on its own. It re-opens a dispatch that ended without a terminal event and has nothing outstanding to retry it.
The quickjs suspension returned as soon as it scheduled a delayed wait continuation, so the watchdog timer was skipped whenever the run held both a pending wait and a pending step. The step would then not be re-evaluated until the wait elapsed, which can be hours out. The node engine already sends both messages from one suspension.
…rve the rest The launch budget was positional: scenarios launched as contiguous blocks, so an attempt that spends its full runTimeoutMs holds its block open past the budget and every scenario behind it reports zero runs. Attempts now launch interleaved in one bounded pass, so a truncated run is proportionally short in every scenario. Cross-run concurrency is unchanged.
Draft. Fixes the
stuckruns the event-log-race repro reports after #3389 landed.What is wrong
A pending step is handed to the queue under an idempotency key derived from the step. The dedupe claim on that key outlives the message sent under it: a queue records the claim with a TTL of its own and does not release it when the message is delivered, acked, or exhausted, so a later send under the same key produces no message at all. That is the intended behaviour while the dispatch is doing its job, since concurrent wake replays must not multiply it. It also means a dispatch that stopped short of a terminal event cannot be revived by re-sending the same key. The run keeps replaying with one pending step that nothing will execute: no divergence, no error, no terminal state, until the harness calls it
stuck.This is not a claim that the queue lost a message, and the fix does not assume one. Delivery is at-least-once: an unacked delivery comes back on its own, so a redundant send being absorbed is harmless while a dispatch is still in flight. A run only strands when both halves hold: the delivery was acked, so nothing is outstanding to redeliver, and the key is still claimed, so nothing new can be sent. An HTTP 200 from the flow route is the ack, so the question worth answering is not why a message was lost. It is why a delivery that never started the step returned 200. That is answered below, from production logs, and the answer is a defect in the SDK's classification of one backend response.
Two wedged runs from the repro, and what the evidence does and does not say:
1. A step created and never started (860 events, specVersion 6): exactly one
step_createdwith nostep_started. Its correlation ordinal sits mid-batch in one un-diverged sequence and the ordinal created after it started and completed normally, so this is not divergence. 210 invocations over the following 51s each replayed all 860 events, returned 200, and wrote nothing. The dispatch was delivered, and delivered once, promptly: see the runtime-log evidence under themaincomparison below. No delivery was outstanding at the end, and no key the run could send would reach the queue.2. A step started and never settled (
wrun_41KZS4PMAS0GSWNE33K36MSENK, 990 events): one step out of ~100 withstep_created→step_started→ nothing,attempt=1,updatedAt == startedAt. Deduping the request logs byrequestIdgives 36 invocations, all HTTP 200, from 19:42:25.121Z to 19:43:22.544Z, and then silence for over an hour while the run stayedrunning. Every delivery was acked and nothing was outstanding.The last invocation of that run lands 61s after its suspension burst, which is exactly one watchdog interval, and that is a defect this branch introduced: see the clamp below.
Shape 1 is not preview-only and not specific to this branch. A
maindispatch of the repro (run 31537832737, against main's production deployment) left 3 of 14 runsrunning, and all three are the same shape: onestep_createdwith nostep_started,settled == started, zero terminal events, nothing written after 21:28:5x. Checked again over an hour later, all three are still stranded.step_createdatwrun_…P45SY4recoverStepwrun_…P45SY5releaseStepwrun_…P45SY8finalizeStepThe message is delivered. The invocation acks without starting the step.
Each of those three steps appears in its deployment's runtime logs exactly once: one
POST /.well-known/workflow/v1/flowinvocation carrying that step's id, 320-450ms after the step's ownstep_created(the measured dispatch-to-start p50 on a heavy storm run is 454ms), running just over a second, HTTP 200.The same run gives a controlled comparison. One replay of
wrun_…P45SY4wrote fivestep_createdevents inside 11ms, and all five dispatches were delivered inside the following 110ms. Four started and completed. The fifth is the stranded one, and its invocation shared a warm instance with one of the four that succeeded, so nothing about the environment separates them.So the delivery side is not at fault. The message was delivered, once, on time. What produced no start is the receiving invocation, and that deployment had
DEBUGon, so its branch is on the record. All three stranded steps logged this and nothing else:step_executor'sstartErrorToResultmaps everyEntityConflictErroronstep_startedto{ type: 'skipped' }, which the flow route answers with 200, which acks the message.world-vercelraisesEntityConflictErrorfor any 409. And aworld-vercelbackend under write contention answered exhausted internal write retries with 409, the same status it uses for "this entity already exists". Exhaustion means the write did not apply: the step was not started by anyone, and the 409 asserted the opposite.The step never started, its terminal-state claim was false, and the ack threw away the only message that would have run it. The idempotency key then made the mistake permanent.
That branch is common and almost always correct: in the same 14-minute window this deployment logged 1066
Step in terminal state, skippinglines, and 1061 of them are duplicate deliveries of steps that genuinely had finished. Exactly 5 rows (4 distinct steps) carry the contention message, and 3 of those 4 are the 3 stranded runs.Attribution: what #3389 changed
The same repro on pre-#3389 heads, same project and same scenario mix:
skippinglinesmainBefore #3389 the repro corrupts and never strands, and write contention on a run's events does not occur at all. From the slot work on it stops corrupting and starts stranding, and contention appears in the same window. That is the expected consequence of allocating a dense per-run slot: writers that previously touched disjoint items now serialize on a shared one, so a storm that used to produce stale snapshots produces contention instead. The
stuckclass is the corruption class, traded.The fence itself is not involved. Across 2.3M log lines from the
mainwindow there are zeroEvent creation rejected as stalewarnings, so no 412 fired, and neither did the dispatch-revoke path that a 412 feeds.The 409 is fixed on the backend: exhausted write retries now answer 5xx, which leaves the message unacked so the queue redelivers it, and no SDK version reads it as a terminal state. That removes this source of the false ack for every deployed client, including ones pinned to old SDKs by skew protection.
This branch is the backstop, and it is needed independently of that: any delivery that ends without a terminal event strands its run today, whatever the reason, because re-sending the same key produces nothing. Under the watchdog the dispatch is re-sent under a fresh key past its deadline, and both the repro and the world-sim scenario show the re-dispatch does start the step.
One run recovering, on world-vercel, at the deadline the design predicts
Run
wrun_…S4CM3from a repro pass on this branch (run 31539228176) is shape 2, and the runtime logs record the whole recovery:step_startedis the last thing written for itExactly one step of that run's 134 was delivered twice, so this is the re-dispatch doing its job and not a duplicate storm. Under the old 240s harness deadline the run would have been reported
stuckat 21:51; on main's production deployment the same shape was still stranded when checked an hour later.The fix
Both shapes get one deadline,
dispatchLostAtMs: the instant this step's current dispatch is presumed lost.step_created. Nothing else bounds how long a dispatch may sit before it produces a start.stepLeaseRemainingSecondsalready uses to schedule the inline backstop wake, so the wake and the key its re-dispatch carries move together. Anchoring on the lease rather than a flat interval is what keeps healthy long-running step bodies from being duplicated: the lease is the runtime's existing statement of how long an executing step may be presumed alive.step_retrying. That retry is already queued with a backoff that can legitimately exceed any deadline here.Past the deadline the dispatch key is suffixed with an epoch, and the epoch advances once per watchdog interval, so a re-dispatch that is itself lost is followed by another. Every replay derives the epoch from durable event timestamps, so concurrent replays agree on the key and fan-out stays at one message per epoch.
A suspension also arms a delayed wake on the soonest boundary among its pending steps. Without it the watchdog would only help runs that happen to keep receiving hooks or wait timers, and a run whose sole outstanding work is the lost dispatch would never replay again. One wake per suspension, keyed on the boundary so concurrent replays arm one timer between them.
The wake's delay has to reach its own boundary
The wake's
delaySecondswas capped at one watchdog interval, while a started step's boundary sits at the end of its ownership lease, roughly 13 minutes further out. The wake therefore landed early, computed the same epoch, re-armed the same boundary-keyed message the queue still held a claim for, and was absorbed. The run was left with no timer at all: an early wake is worse than no wake, because it also spends the key. The ceiling now covers the larger of the two deadlines and exists only to bound clock skew (a timestamp stamped in the future must not ask for a delay above the queue's per-message maximum). The regression test assertsnow + delaySecondspassesnextStepDispatchBoundaryMsfor a started step.Both engines arm the wake unconditionally
Both VM engines dispatch pending steps, so both take the epoch key and the boundary wake. The quickjs engine returned as soon as it had scheduled a delayed wait continuation, which skipped the wake for any run holding a pending wait and a pending step: that step would not be re-evaluated until the wait elapsed, which can be hours out. The wake is now armed before the wait continuation, so one suspension sends both, as the node engine already did.
Relationship to #3365
#3365 landed the step-identity dispatch key (correlation id plus hashed step name) and a path that publishes a newly created step in parallel with its
step_createdwrite. This branch composes with it rather than competing:The trade
Re-dispatch is at-least-once. If the original message was merely slow rather than lost, both deliveries execute the step body and the loser's terminal write is rejected as a conflict. A second
step_startedis counted as an attempt, bounded by the step's max retries, so the step either completes or fails; either way the run leavesrunning.The default interval is 60s, against measured dispatch-to-start latency on a heavy storm run (n=191: p50 454ms, p90 954ms, p99 1929ms, max 2232ms, nothing over 5s). That is roughly 27x p99.
WORKFLOW_STEP_DISPATCH_WATCHDOG_SECONDStunes it, clamped to 10..900. The started-step deadline is the inline ownership lease, tuned byWORKFLOW_INLINE_OWNERSHIP_LEASE_SECONDS.Harness deadline
The repro declared a run
stuckafter a hardcoded 240s, well inside the runtime's own longest recovery deadline, so a run on its way back was reported as permanently stranded.runTimeoutMsnow derives from the lease plus the watchdog interval plus slack, read from the same constants the runtime uses, and the CI job timeout follows. Only a run that actually needs recovery spends that deadline; healthy attempts still finish in tens of seconds.Raising it exposed a second harness defect. Scenarios launched as contiguous blocks, so the launch budget was positional: the recovering attempt above spent 973s of a 720s budget and held its block open, and every scenario behind it reported zero runs. That is why one pass came back 6 of 14 with all six in
step-stormand nothing inhook-storm, the production shape. Attempts now launch interleaved across scenarios in one bounded pass, so a truncated run is proportionally short in every scenario. Cross-run concurrency is unchanged: one bounded launch holds the same number of attempts in flight regardless of which scenarios they belong to, and each attempt's race is between replays within its own run.Testing
if (!soonestWait)behaviour (1 failed, 1 passed) before restoring the fix.packages/core(2090 passed),@workflow/world-local,@workflow/world-sim, andpackages/world's 110 tests (that package has notestscript of its own; they run from the root asnpx vitest run packages/world/src).completed, zerostuck, zeroCORRUPTED_EVENT_LOG, across step-storm (6), hook-storm (6) and hook-sleep (2). Repeated on the merge with main (run 31533339827, the pass that exercises the Resilient step dispatch: parallelize step_created writes with queue publishes #3365 reconciliation): again 14/14. Repeated again on the clamp fix (run 31537669027, head6d087db): 14/14, durations 22-105s. Progression: post-World-side incrementing event ID (specVersion 6) #3389 baseline 4 stuck → 1 → 2 → 0, holding across the merge and the clamp fix. At 14 runs that is a regression check, not a rate measurement.maindispatch for comparison (run 31537832737, production): 3/14running, all hook-storm, all in the unstarted-dispatch shape described above.81d75f7(runs 31541607446 and 31541605853): both 14/14completed, neither partial nor budget-exhausted, with all three scenarios represented in each (step-storm 6, hook-storm 6, hook-sleep 2). 28 attempts, zero stuck, zero corrupted.world-postgressoak, 84 attempts (36 step-storm, 36 hook-storm, 12 hook-sleep): 84/84completed, zero stuck, zero corrupted. Inspecting the resulting event log directly (447k events, 97,178 started steps): 0 steps with a duplicate terminal event, 0 steps left unsettled, and 249 steps started more times than their retry count accounts for. Every one of those duplicate starts is within 10s of the first (p50 0.98s, max 10.1s), so none of them came from the watchdog: its shortest deadline is a 60s interval. The duplicates are the pre-existing immediate re-enqueue on wake. A healthy soak never reaches the watchdog's deadlines, so this measures no-regression; the recovery path itself is covered by the world-sim scenario.