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

@VaguelySerious VaguelySerious 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.

run unstarted step step_created at delivered at invocation events after
wrun_…P45SY4 recoverStep 21:28:43.313 21:28:43.761 200, 1104ms, warm none
wrun_…P45SY5 releaseStep 21:28:45.557 21:28:45.901 200, 1232ms, prewarmed none
wrun_…P45SY8 finalizeStep 21:28:48.268 21:28:48.591 200, 1164ms, prewarmed none

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 every EntityConflictError 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 run head skipping lines of those, write contention stuck corrupted
31472848287 (08:21 UTC) pre-#3389 399 0 0 4
31474232239 (08:40 UTC) pre-#3389 7 0 0 1
31513248592 (16:35 UTC) slot branch 568 16 4 0
31537832737 (21:25 UTC) main 1066 5 3 0

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 zero Event 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:

time what
21:47:28.389 the step's dispatch is delivered. HTTP 200 after 2.6s. Its step_started is the last thing written for it
21:47:30.554 the 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.066 the same step id is delivered a second time, 860.7s after the first. The inline ownership lease is 860s
22:03:15 the 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-bot Bot 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
Name Type
@workflow/core Patch
@workflow/builders Patch
@workflow/cli Patch
@workflow/next Patch
@workflow/nitro Patch
@workflow/vitest Patch
@workflow/web-shared Patch
@workflow/web Patch
workflow Patch
@workflow/world-testing Patch
@workflow/astro Patch
@workflow/nest Patch
@workflow/rollup Patch
@workflow/sveltekit Patch
@workflow/vite Patch
@workflow/nuxt Patch

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

vercel Bot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

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

Project Deployment Actions Updated (UTC)
example-nextjs-workflow-turbopack Ready Ready Preview Aug 11, 2026 10:18pm
example-nextjs-workflow-webpack Ready Ready Preview Aug 11, 2026 10:18pm
example-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-astro-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-express-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-fastify-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-hono-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-nestjs-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-nitro-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-nuxt-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-python-workflow Error Error Aug 11, 2026 10:18pm
workbench-sveltekit-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-tanstack-start-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workbench-vite-workflow Ready Ready Preview Aug 11, 2026 10:18pm
workflow-docs Ready Ready Preview, v0 Aug 11, 2026 10:18pm
workflow-swc-playground Ready Ready Preview Aug 11, 2026 10:18pm
workflow-tarballs Ready Ready Preview Aug 11, 2026 10:18pm
workflow-web Ready Ready Preview Aug 11, 2026 10:18pm

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

github-actions Bot 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

Metric Scenario Best (ms) P75 (ms) P90 (ms) P99 (ms) Samples
TTFS step 265 (-18%) 💚 1380 🔴 (+31%) 🔻 1396 🔴 (+25%) 🔻 1411 🔴 (+0.9%) 30
TTFS stream 1307 (+722%) 🔻 1373 🔴 (+28%) 🔻 1380 🔴 (+26%) 🔻 1425 🔴 (+15%) 🔻 30
TTFS hook + stream 1583 (+18%) 🔻 1649 🔴 (+13%) 1661 🔴 (+11%) 1684 🔴 (+7.2%) 30
STSO 1020 steps (inline) 113 (-11%) 158 (-16%) 💚 177 (-18%) 💚 279 (-34%) 💚 1019
WO 1020 steps 156787 (-15%) 156787 (-15%) 156787 (-15%) 156787 (-15%) 1
SL stream latency 83 (-4.6%) 111 🔴 (-13%) 117 🔴 (-15%) 157 🔴 (-68%) 💚 30
SO stream overhead (text) 105 (-2.8%) 157 (-22%) 💚 161 (-49%) 💚 193 (-59%) 💚 30
SO stream 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

Metric Scenario Best (ms) P75 (ms) P90 (ms) P99 (ms) Samples
TTFS step 1459 (+352%) 🔻 1520 🔴 (+44%) 🔻 1537 🔴 (+37%) 🔻 1603 🔴 (+15%) 30
TTFS stream 1451 (+813%) 🔻 1536 🔴 (+43%) 🔻 1564 🔴 (+43%) 🔻 1614 🔴 (+30%) 🔻 30
TTFS hook + stream 1394 (+4.3%) 1770 🔴 (+21%) 🔻 1803 🔴 (+21%) 🔻 2019 🔴 (+29%) 🔻 30
STSO 1020 steps (inline) 109 (-14%) 166 (-12%) 184 (-15%) 273 (-35%) 💚 1019
WO 1020 steps 168876 (-8.4%) 168876 (-8.4%) 168876 (-8.4%) 168876 (-8.4%) 1
SL stream latency 85 (-2.3%) 121 🔴 (-4.7%) 145 🔴 (+5.8%) 212 🔴 (-56%) 💚 30
SO stream overhead (text) 110 (+1.9%) 157 (-22%) 💚 163 (-48%) 💚 240 (-50%) 💚 30
SO stream 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

Metric Scenario Best (ms) P75 (ms) P90 (ms) P99 (ms) Samples
TTFS step 1309 (+305%) 🔻 1398 🔴 (+33%) 🔻 1419 🔴 (+27%) 🔻 1451 🔴 (+3.8%) 30
TTFS stream 1312 (+725%) 🔻 1414 🔴 (+31%) 🔻 1448 🔴 (+33%) 🔻 1785 🔴 (+44%) 🔻 30
TTFS hook + stream 1312 (-1.8%) 1783 🔴 (+22%) 🔻 1841 🔴 (+23%) 🔻 2006 🔴 (+28%) 🔻 30
STSO 1020 steps (inline) 112 (-12%) 171 (-9.5%) 188 (-13%) 309 (-27%) 💚 1019
WO 1020 steps 172126 (-6.6%) 172126 (-6.6%) 172126 (-6.6%) 172126 (-6.6%) 1
SL stream latency 113 (+30%) 🔻 158 🔴 (+24%) 🔻 181 🔴 (+32%) 🔻 327 🔴 (-32%) 💚 30
SO stream overhead (text) 118 (+9.3%) 189 (-6.0%) 230 (-27%) 💚 421 (-12%) 30
SO stream 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

Metric Scenario Best (ms) P75 (ms) P90 (ms) P99 (ms) Samples
TTFS step 1290 (+46%) 🔻 1378 🔴 (+12%) 1418 🔴 (+8.6%) 1669 🔴 (-7.6%) 30
TTFS stream 1301 (+24%) 🔻 1366 🔴 (+21%) 🔻 1387 🔴 (+19%) 🔻 1469 🔴 (+18%) 🔻 30
TTFS hook + stream 1588 (+13%) 1709 🔴 (+9.8%) 1758 🔴 (+11%) 1945 🔴 (+22%) 🔻 30
STSO 1020 steps (inline) 121 (-23%) 💚 165 (-33%) 💚 188 (-40%) 💚 344 (-51%) 💚 1019
WO 1020 steps 171752 (-29%) 💚 171752 (-29%) 💚 171752 (-29%) 💚 171752 (-29%) 💚 1
SL stream latency 91 (-27%) 💚 138 🔴 (-25%) 💚 281 🔴 (+19%) 🔻 464 🔴 (+47%) 🔻 30
SO stream overhead (text) 105 (-29%) 💚 150 (-40%) 💚 171 (-51%) 💚 296 (-50%) 💚 30
SO stream 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-actions Bot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

E2E Test Summary

Summary
Passed Failed Skipped Total
✅ ▲ Vercel Production 3466 0 590 4056
✅ 💻 Local Development 3536 0 520 4056
✅ 📦 Local Production 3810 0 558 4368
✅ 🐘 Local Postgres 3810 0 558 4368
✅ 🪟 Windows 312 0 0 312
✅ vercel-multi-region 27 0 0 27
Total 14961 0 2226 17187
Details by Category

✅ ▲ Vercel Production

App Passed Failed Skipped
✅ astro-node 128 0 28
✅ astro-quickjs 128 0 28
✅ example-node 128 0 28
✅ example-quickjs 128 0 28
✅ express-node 128 0 28
✅ express-quickjs 128 0 28
✅ fastify-node 128 0 28
✅ fastify-quickjs 128 0 28
✅ hono-node 128 0 28
✅ hono-quickjs 128 0 28
✅ nest-node 128 0 28
✅ nest-quickjs 128 0 28
✅ nextjs-turbopack-node 153 0 3
✅ nextjs-turbopack-quickjs 153 0 3
✅ nextjs-webpack-node 153 0 3
✅ nextjs-webpack-quickjs 153 0 3
✅ nitro-node 128 0 28
✅ nitro-quickjs 128 0 28
✅ nuxt-node 128 0 28
✅ nuxt-quickjs 128 0 28
✅ sveltekit-node 147 0 9
✅ sveltekit-quickjs 147 0 9
✅ tanstack-start-node 128 0 28
✅ tanstack-start-quickjs 128 0 28
✅ vite-node 128 0 28
✅ vite-quickjs 128 0 28

✅ 💻 Local Development

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-stable-node 156 0 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 📦 Local Production

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-canary-node 137 0 19
✅ nextjs-webpack-canary-quickjs 137 0 19
✅ nextjs-webpack-stable-node 156 0 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 🐘 Local Postgres

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-canary-node 137 0 19
✅ nextjs-webpack-canary-quickjs 137 0 19
✅ nextjs-webpack-stable-node 156 0 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 🪟 Windows

App Passed Failed Skipped
✅ nextjs-turbopack-node 156 0 0
✅ nextjs-turbopack-quickjs 156 0 0

✅ vercel-multi-region

App Passed Failed Skipped
✅ nextjs-turbopack 27 0 0

📋 View full workflow run

@github-actions

github-actions Bot 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

scenario outcome events virt replay violations
smoke-no-steps completed 3 0ms ok 0
smoke-one-step completed 6 0ms ok 0
hook-at-step-started completed 12 0ms ok 0
hook-at-step-completed completed 12 0ms ok 0
hook-at-hook-created completed 12 0ms ok 0
deadline-hook-wins completed 7 1.0h ok 0
deadline-expires completed 7 1.0h ok 0
long-sleep completed 11 30.0d ok 0
hook-never-arrives stalled 3 0ms skipped 0
step-retries-twice completed 10 2.0s ok 0
parallel-steps completed 9 0ms ok 0
lost-step-dispatch completed 15 2.0m ok 0
hook-on-execution-state completed 12 0ms ok 0
peek-hook-before-branch completed 12 0ms ok 0
peek-hook-after-branch completed 12 0ms ok 0
peek-hook-at-registration completed 12 0ms ok 0
race-hook-before-probe completed 12 0ms ok 0
race-hook-after-probe completed 12 0ms ok 0
race-duplicate-delivery completed 13 0ms ok 0
attr-hook-before-step completed 11 0ms ok 0
attr-hook-after-step completed 11 0ms ok 0
attr-from-step-body completed 13 0ms ok 0
fork-hook-after-timeout completed 14 1.0m ok 0
fork-hook-before-timeout completed 14 1.0m ok 0
count-hook-after-timeout completed 17 1.0m ok 0
count-hook-before-timeout completed 20 1.0m ok 0
stale-read-step-count-fork completed 17 1.0m MISMATCH 1
stale-read-equal-step-counts completed 14 1.0m MISMATCH 1
step-vs-step-fork completed 12 0ms MISMATCH 1
step-vs-step-fork-fenced completed 12 0ms MISMATCH 1
fence-catches-benign-direction completed 12 5ms ok 0
in-flight-before-decision completed 17 1.0m MISMATCH 1
in-flight-before-decision-counted completed 20 1.0m ok 0
in-flight-after-decision failed 14 2.0m MISMATCH 1
stale-read-step-count-fork-fenced completed 20 1.0m ok 0
fork-hook-wins completed 13 1.0m ok 0
fork-timeout-wins completed 13 1.0m ok 0
unclaimed-payload-under-fork completed 17 1.0m ok 0
claimed-payload-under-fork completed 17 1.0m ok 0
writers-independent-step-bodies completed 12 0ms ok 0
writers-scripted-tempo completed 12 0ms ok 0
cancel-mid-step cancelled 7 0ms skipped 0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 42 total

log=append-only · fence=per-spec

scenario outcome events virt replay violations
smoke-no-steps completed 3 0ms ok 0
smoke-one-step completed 6 0ms ok 0
hook-at-step-started completed 12 0ms ok 0
hook-at-step-completed completed 12 0ms ok 0
hook-at-hook-created completed 12 0ms ok 0
deadline-hook-wins completed 7 1.0h ok 0
deadline-expires completed 7 1.0h ok 0
long-sleep completed 11 30.0d ok 0
hook-never-arrives stalled 3 0ms skipped 0
step-retries-twice completed 10 2.0s ok 0
parallel-steps completed 9 0ms ok 0
lost-step-dispatch completed 15 2.0m ok 0
hook-on-execution-state completed 12 0ms ok 0
peek-hook-before-branch completed 12 0ms ok 0
peek-hook-after-branch completed 12 0ms ok 0
peek-hook-at-registration completed 12 0ms ok 0
race-hook-before-probe completed 12 0ms ok 0
race-hook-after-probe completed 12 0ms ok 0
race-duplicate-delivery completed 13 0ms ok 0
attr-hook-before-step completed 11 0ms ok 0
attr-hook-after-step completed 11 0ms ok 0
attr-from-step-body completed 13 0ms ok 0
fork-hook-after-timeout completed 14 1.0m ok 0
fork-hook-before-timeout completed 14 1.0m ok 0
count-hook-after-timeout completed 17 1.0m ok 0
count-hook-before-timeout completed 20 1.0m ok 0
stale-read-step-count-fork completed 20 1.0m ok 0
stale-read-equal-step-counts completed 14 1.0m ok 0
step-vs-step-fork completed 12 0ms ok 0
step-vs-step-fork-fenced completed 12 0ms ok 0
fence-catches-benign-direction completed 12 5ms ok 0
in-flight-before-decision completed 17 1.0m ok 0
in-flight-before-decision-counted completed 17 1.0m ok 0
in-flight-after-decision completed 19 2.0m ok 0
stale-read-step-count-fork-fenced completed 20 1.0m ok 0
fork-hook-wins completed 13 1.0m ok 0
fork-timeout-wins completed 13 1.0m ok 0
unclaimed-payload-under-fork completed 17 1.0m ok 0
claimed-payload-under-fork completed 17 1.0m ok 0
writers-independent-step-bodies completed 12 0ms ok 0
writers-scripted-tempo completed 12 0ms ok 0
cancel-mid-step cancelled 7 0ms skipped 0

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-actions Bot commented Aug 11, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

No event-log regressions in the latest repro job.

Run History

Metric 2026-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
Result 1/14 regressions no regressions no regressions no regressions no regressions — partial (0 of 14 planned) no regressions — partial (6 of 14 planned) no regressions — partial (6 of 14 planned) no regressions
Total 14 14 14 14 0 6 6 14
completed 13 14 14 14 0 6 6 14
CORRUPTED_EVENT_LOG 0 0 0 0 0 0 0 0
USER_ERROR 0 0 0 0 0 0 0 0
RUNTIME_ERROR 0 0 0 0 0 0 0 0
stuck 1 0 0 0 0 0 0 0
other 0 0 0 0 0 0 0 0
infra 0 0 0 0 0 0 0 0
Config 14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 6 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 6 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8
Timing watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 240000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / timeout 1100000ms

Latest Scenario Breakdown

Scenario Total completed CORRUPTED_EVENT_LOG USER_ERROR RUNTIME_ERROR stuck other infra
step-storm 6 6 0 0 0 0 0 0
hook-storm 6 6 0 0 0 0 0 0
hook-sleep 2 2 0 0 0 0 0 0

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

Labels

event-log-race-repro Run the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant