Skip to content

[core] Re-dispatch a pending step whose dispatch ended without a terminal event - #3465

Closed
VaguelySerious wants to merge 15 commits into
mainfrom
peter/step-dispatch-watchdog
Closed

[core] Re-dispatch a pending step whose dispatch ended without a terminal event#3465
VaguelySerious wants to merge 15 commits into
mainfrom
peter/step-dispatch-watchdog

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 11, 2026

Copy link
Copy Markdown
Member

Draft. Fixes the stuck runs 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_created with no step_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 the main comparison 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 with step_createdstep_started → nothing, attempt=1, updatedAt == startedAt. Deduping the request logs by requestId gives 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 stayed running. 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 main dispatch of the repro (run 31537832737, against main's production deployment) left 3 of 14 runs running, and all three are the same shape: one step_created with no step_started, settled == started, zero terminal events, nothing written after 21:28:5x. Checked again over an hour later, all three are still stranded.

rununstarted stepstep_created atdelivered atinvocationevents after
wrun_…P45SY4recoverStep21:28:43.31321:28:43.761200, 1104ms, warmnone
wrun_…P45SY5releaseStep21:28:45.55721:28:45.901200, 1232ms, prewarmednone
wrun_…P45SY8finalizeStep21:28:48.26821:28:48.591200, 1164ms, prewarmednone

The 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/flow invocation carrying that step's id, 320-450ms after the step's own step_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_…P45SY4 wrote five step_created events 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 DEBUG on, so its branch is on the record. All three stranded steps logged this and nothing else:

[workflow:runtime:debug] Step in terminal state, skipping {
stepName: 'step//./workflows/103_event_log_corruption_repro//recoverStep',
stepId: 'step_01KZSBKMG4QD735A2CDNQKP8BR',
workflowRunId: 'wrun_…P45SY4',
error: 'Transaction conflict: another operation is in progress for this resource'
}

step_executor's startErrorToResult maps everyEntityConflictError on step_started to { type: 'skipped' }, which the flow route answers with 200, which acks the message. world-vercel raises EntityConflictError for any 409. And a world-vercel backend 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, skipping lines, 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:

repro runheadskipping linesof those, write contentionstuckcorrupted
31472848287 (08:21 UTC)pre-#3389399004
31474232239 (08:40 UTC)pre-#33897001
31513248592 (16:35 UTC)slot branch5681640
31537832737 (21:25 UTC)main1066530

Before #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 stuck class is the corruption class, traded.

The fence itself is not involved. Across 2.3M log lines from the main window there are zeroEvent creation rejected as stale warnings, 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_…S4CM3 from a repro pass on this branch (run 31539228176) is shape 2, and the runtime logs record the whole recovery:

timewhat
21:47:28.389the step's dispatch is delivered. HTTP 200 after 2.6s. Its step_started is the last thing written for it
21:47:30.554the run's last other step delivery. For the next 14m19s it is replayed continuously by the storm driver and delivers no step at all: one step outstanding, nothing that will execute it
22:01:49.066the same step id is delivered a second time, 860.7s after the first. The inline ownership lease is 860s
22:03:15the run completes

Exactly 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 stuck at 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.

  • Unstarted: one watchdog interval after its durable step_created. Nothing else bounds how long a dispatch may sit before it produces a start.
  • Started: the end of its ownership lease. That is the deadline stepLeaseRemainingSeconds already 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.
  • Out of scope: 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 delaySeconds was 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 asserts now + delaySeconds passes nextStepDispatchBoundaryMs for 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_created write. This branch composes with it rather than competing:

  • The watchdog epoch is a suffix on the identity key, and epoch 0 is byte-identical to it. Every producer of a step message (the dispatch pass, the suspension handler's parallel publish, the delayed retry) keeps sharing one key, and only a dispatch that is presumed lost moves off it.
  • Steps published by the parallel path are skipped by the dispatch pass, but they still count for the boundary wake. Their dispatch can end without a terminal event too, and that suspension is the only one that will see them before something else has to wake the run.
  • Both parallel create+publish paths now stamp the step's creation timestamp on the queue item, which is what anchors the watchdog from the first hand-off on.

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_started is counted as an attempt, bounded by the step's max retries, so the step either completes or fails; either way the run leaves running.

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_SECONDS tunes it, clamped to 10..900. The started-step deadline is the inline ownership lease, tuned by WORKFLOW_INLINE_OWNERSHIP_LEASE_SECONDS.

Harness deadline

The repro declared a run stuck after a hardcoded 240s, well inside the runtime's own longest recovery deadline, so a run on its way back was reported as permanently stranded. runTimeoutMs now 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-storm and nothing in hook-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

  • New unit tests for the lost-at deadline in both shapes (including a lazily-created inline step, which has only its own start to date from), the epoch, key stability across replays within an epoch, the identity key surviving the epoch suffix, out-of-scope steps keeping the unsuffixed key, missing and future creation timestamps, the env clamp, boundary computation, and wake selection including the tie-break, the re-arm past the lease, and the delay bounds in both directions.
  • A world-sim scenario that drops a queued step message without settling it, so the key stays claimed, and asserts the run still reaches a terminal state.
  • A quickjs suspension test against a mocked VM: a created-but-unstarted step arms the wake, and it still does when the run also holds a pending wait resuming a day out. Verified to catch the parity gap by restoring the old if (!soonestWait) behaviour (1 failed, 1 passed) before restoring the fix.
  • Unit suites green: packages/core (2090 passed), @workflow/world-local, @workflow/world-sim, and packages/world's 110 tests (that package has no test script of its own; they run from the root as npx vitest run packages/world/src).
  • Repro on this branch: run 31531590670 came back 14/14 completed, zero stuck, zero CORRUPTED_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, head 6d087db): 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.
  • Same-day main dispatch for comparison (run 31537832737, production): 3/14 running, all hook-storm, all in the unstarted-dispatch shape described above.
  • The pass that caught the recovery above (run 31539228176) is the one that came back partial, 6 of 14, for the launch-budget reason under "Harness deadline". Zero regressions in the six it launched, and one of them is the recovered run.
  • After the interleave fix, two passes on head 81d75f7 (runs 31541607446 and 31541605853): both 14/14 completed, 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.
  • Local world-postgres soak, 84 attempts (36 step-storm, 36 hook-storm, 12 hook-sleep): 84/84 completed, 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.

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-bot

changeset-botBot commented Aug 11, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: 81d75f7

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 16 packages
NameType
@workflow/corePatch
@workflow/buildersPatch
@workflow/cliPatch
@workflow/nextPatch
@workflow/nitroPatch
@workflow/vitestPatch
@workflow/web-sharedPatch
@workflow/webPatch
workflowPatch
@workflow/world-testingPatch
@workflow/astroPatch
@workflow/nestPatch
@workflow/rollupPatch
@workflow/sveltekitPatch
@workflow/vitePatch
@workflow/nuxtPatch

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

@vercel

vercelBot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 11, 2026 10:18pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 11, 2026 10:18pm
example-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-astro-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-express-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-fastify-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-hono-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-nestjs-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-nitro-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-nuxt-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-python-workflowErrorErrorAug 11, 2026 10:18pm
workbench-sveltekit-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workbench-vite-workflowReadyReadyPreviewAug 11, 2026 10:18pm
workflow-docsReadyReadyPreview, v0Aug 11, 2026 10:18pm
workflow-swc-playgroundReadyReadyPreviewAug 11, 2026 10:18pm
workflow-tarballsReadyReadyPreviewAug 11, 2026 10:18pm
workflow-webReadyReadyPreviewAug 11, 2026 10:18pm

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 11, 2026
@github-actions

github-actionsBot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit 81d75f7 · Tue, 11 Aug 2026 22:33:02 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep265 (-18%) 💚1380 🔴 (+31%) 🔻1396 🔴 (+25%) 🔻1411 🔴 (+0.9%)30
TTFSstream1307 (+722%) 🔻1373 🔴 (+28%) 🔻1380 🔴 (+26%) 🔻1425 🔴 (+15%) 🔻30
TTFShook + stream1583 (+18%) 🔻1649 🔴 (+13%)1661 🔴 (+11%)1684 🔴 (+7.2%)30
STSO1020 steps (inline)113 (-11%)158 (-16%) 💚177 (-18%) 💚279 (-34%) 💚1019
WO1020 steps156787 (-15%)156787 (-15%)156787 (-15%)156787 (-15%)1
SLstream latency83 (-4.6%)111 🔴 (-13%)117 🔴 (-15%)157 🔴 (-68%) 💚30
SOstream overhead (text)105 (-2.8%)157 (-22%) 💚161 (-49%) 💚193 (-59%) 💚30
SOstream overhead (structured)120 (+12%)161 (-9.0%)172 (-28%) 💚216 (-51%) 💚30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 183209ms → this run 155363ms (Δ -27846ms, -15%)

100-150 ms ██████░░░░░░░░░░░░░░┃ main 168 this 600 +432
150-200 ms ████████████┃███████████ main 675 this 372 -303
200-250 ms ┃████ main 129 this 33 -96
250-300 ms ┃ main 23 this 7 -16
300-350 ms ┃ main 8 this 4 -4
350-400 ms ┃ main 3 this 0 -3
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 3 this 1 -2
500-550 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 1 this 0 -1
800-850 ms ┃ main 1 this 0 -1
850-900 ms ┃ main 1 this 0 -1
900-950 ms ┃ main 1 this 0 -1
📜 Previous results (3)

596021a

Tue, 11 Aug 2026 22:03:31 GMT · run logs

vercel / nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1459 (+352%) 🔻1520 🔴 (+44%) 🔻1537 🔴 (+37%) 🔻1603 🔴 (+15%)30
TTFSstream1451 (+813%) 🔻1536 🔴 (+43%) 🔻1564 🔴 (+43%) 🔻1614 🔴 (+30%) 🔻30
TTFShook + stream1394 (+4.3%)1770 🔴 (+21%) 🔻1803 🔴 (+21%) 🔻2019 🔴 (+29%) 🔻30
STSO1020 steps (inline)109 (-14%)166 (-12%)184 (-15%)273 (-35%) 💚1019
WO1020 steps168876 (-8.4%)168876 (-8.4%)168876 (-8.4%)168876 (-8.4%)1
SLstream latency85 (-2.3%)121 🔴 (-4.7%)145 🔴 (+5.8%)212 🔴 (-56%) 💚30
SOstream overhead (text)110 (+1.9%)157 (-22%) 💚163 (-48%) 💚240 (-50%) 💚30
SOstream overhead (structured)106 (-0.9%)160 (-9.6%)183 (-24%) 💚439 (±0%)30

22f54b9

Tue, 11 Aug 2026 20:57:56 GMT · run logs

vercel / nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1309 (+305%) 🔻1398 🔴 (+33%) 🔻1419 🔴 (+27%) 🔻1451 🔴 (+3.8%)30
TTFSstream1312 (+725%) 🔻1414 🔴 (+31%) 🔻1448 🔴 (+33%) 🔻1785 🔴 (+44%) 🔻30
TTFShook + stream1312 (-1.8%)1783 🔴 (+22%) 🔻1841 🔴 (+23%) 🔻2006 🔴 (+28%) 🔻30
STSO1020 steps (inline)112 (-12%)171 (-9.5%)188 (-13%)309 (-27%) 💚1019
WO1020 steps172126 (-6.6%)172126 (-6.6%)172126 (-6.6%)172126 (-6.6%)1
SLstream latency113 (+30%) 🔻158 🔴 (+24%) 🔻181 🔴 (+32%) 🔻327 🔴 (-32%) 💚30
SOstream overhead (text)118 (+9.3%)189 (-6.0%)230 (-27%) 💚421 (-12%)30
SOstream overhead (structured)119 (+11%)199 (+12%)230 (-4.2%)348 (-21%) 💚30

b9f2ca4

Tue, 11 Aug 2026 19:43:41 GMT · run logs

vercel / nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1290 (+46%) 🔻1378 🔴 (+12%)1418 🔴 (+8.6%)1669 🔴 (-7.6%)30
TTFSstream1301 (+24%) 🔻1366 🔴 (+21%) 🔻1387 🔴 (+19%) 🔻1469 🔴 (+18%) 🔻30
TTFShook + stream1588 (+13%)1709 🔴 (+9.8%)1758 🔴 (+11%)1945 🔴 (+22%) 🔻30
STSO1020 steps (inline)121 (-23%) 💚165 (-33%) 💚188 (-40%) 💚344 (-51%) 💚1019
WO1020 steps171752 (-29%) 💚171752 (-29%) 💚171752 (-29%) 💚171752 (-29%) 💚1
SLstream latency91 (-27%) 💚138 🔴 (-25%) 💚281 🔴 (+19%) 🔻464 🔴 (+47%) 🔻30
SOstream overhead (text)105 (-29%) 💚150 (-40%) 💚171 (-51%) 💚296 (-50%) 💚30
SOstream overhead (structured)105 (-35%) 💚165 (-45%) 💚179 (-49%) 💚437 (-58%) 💚30
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 6 fail of 42 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
lost-step-dispatchcompleted152.0mok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted171.0mMISMATCH1
stale-read-equal-step-countscompleted141.0mMISMATCH1
step-vs-step-forkcompleted120msMISMATCH1
step-vs-step-fork-fencedcompleted120msMISMATCH1
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mMISMATCH1
in-flight-before-decision-countedcompleted201.0mok0
in-flight-after-decisionfailed142.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 42 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
lost-step-dispatchcompleted152.0mok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

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.
@github-actions

github-actionsBot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

No event-log regressions in the latest repro job.

Run History

Metric2026-08-11 19:34 UTC #1
logs / deploy
2026-08-11 20:37 UTC #1
logs / deploy
2026-08-11 20:45 UTC #1
logs / deploy
2026-08-11 21:30 UTC #1
logs / deploy
2026-08-11 21:40 UTC #1
logs / deploy
2026-08-11 21:43 UTC #1
logs / deploy
2026-08-11 22:02 UTC #1
logs / deploy
2026-08-11 22:21 UTC #1
logs / deploy
Result1/14 regressionsno regressionsno regressionsno regressionsno regressions — partial (0 of 14 planned)no regressions — partial (6 of 14 planned)no regressions — partial (6 of 14 planned)no regressions
Total1414141406614
completed1314141406614
CORRUPTED_EVENT_LOG00000000
USER_ERROR00000000
RUNTIME_ERROR00000000
stuck10000000
other00000000
infra00000000
Config14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x814 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x814 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x814 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x86 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x86 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x814 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8
Timingwatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 240000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000mswatchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms

Latest Scenario Breakdown

ScenarioTotalcompletedCORRUPTED_EVENT_LOGUSER_ERRORRUNTIME_ERRORstuckotherinfra
step-storm66000000
hook-storm66000000
hook-sleep22000000

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.
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious