Repository navigation
[core] Log pending consumers in divergence diagnostics - #4021
Conversation
…stics A replay divergence is reported as "could not consume event X" with nothing about why nobody could. The usual reason is that the pending invocation holding the event's ordinal is a different kind of entity (a step where the log recorded a wait), and the message now says so, along with where the consumer's walk stands. The recovery WARN and the terminal CorruptedEventLogError log carry which pass of which invocation diverged (loopIteration, retained-VM vs cold replay, event log length/tail/cursor, hookInput/waitContinuation presence, setup source), the recovery message accumulates a bounded history of divergent event ids that the terminal message prints, and the console renderer no longer drops `errorMessage` when the message itself does not carry the text. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
🦋 Changeset detectedLatest commit: c6f7d03 The changes in this PR will be included in the next version bump. This PR includes changesets to release 20 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
🧪 E2E Test Results✅ All tests passed
|
| Passed | Failed | Skipped | Total | |
|---|---|---|---|---|
| ✅ ▲ Vercel Production | 3662 | 0 | 685 | 4347 |
| ✅ 💻 Local Development | 3922 | 0 | 586 | 4508 |
| ✅ 📦 Local Production | 3922 | 0 | 586 | 4508 |
| ✅ 🐘 Local Postgres | 3922 | 0 | 586 | 4508 |
| ✅ 🪟 Windows | 320 | 0 | 2 | 322 |
| ✅ 🌐 Cross-language Conformance | 68 | 0 | 74 | 142 |
| ✅ vercel-http-transport | 823 | 0 | 143 | 966 |
| ✅ vercel-multi-region | 27 | 0 | 0 | 27 |
| ✅ vercel-ws-transport | 557 | 0 | 87 | 644 |
| Total | 17223 | 0 | 2749 | 19972 |
Details by Category
✅ ▲ Vercel Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-node | 133 | 0 | 28 |
| ✅ astro-quickjs | 133 | 0 | 28 |
| ✅ example-node | 133 | 0 | 28 |
| ✅ example-quickjs | 133 | 0 | 28 |
| ✅ express-node | 133 | 0 | 28 |
| ✅ express-quickjs | 133 | 0 | 28 |
| ✅ fastify-node | 133 | 0 | 28 |
| ✅ fastify-quickjs | 133 | 0 | 28 |
| ✅ hono-node | 133 | 0 | 28 |
| ✅ hono-quickjs | 133 | 0 | 28 |
| ✅ nest-node | 133 | 0 | 28 |
| ✅ nest-quickjs | 133 | 0 | 28 |
| ✅ nextjs-turbopack-node | 158 | 0 | 3 |
| ✅ nextjs-turbopack-quickjs | 158 | 0 | 3 |
| ✅ nextjs-webpack-node | 158 | 0 | 3 |
| ✅ nextjs-webpack-quickjs | 158 | 0 | 3 |
| ✅ nitro-node | 133 | 0 | 28 |
| ✅ nitro-quickjs | 133 | 0 | 28 |
| ✅ nuxt-node | 133 | 0 | 28 |
| ✅ nuxt-quickjs | 133 | 0 | 28 |
| ✅ python-node | 66 | 0 | 95 |
| ✅ sveltekit-node | 152 | 0 | 9 |
| ✅ sveltekit-quickjs | 152 | 0 | 9 |
| ✅ tanstack-start-node | 133 | 0 | 28 |
| ✅ tanstack-start-quickjs | 133 | 0 | 28 |
| ✅ vite-node | 133 | 0 | 28 |
| ✅ vite-quickjs | 133 | 0 | 28 |
✅ 💻 Local Development
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 27 |
| ✅ astro-stable-quickjs | 134 | 0 | 27 |
| ✅ express-stable-node | 134 | 0 | 27 |
| ✅ express-stable-quickjs | 134 | 0 | 27 |
| ✅ fastify-stable-node | 134 | 0 | 27 |
| ✅ fastify-stable-quickjs | 134 | 0 | 27 |
| ✅ hono-stable-node | 134 | 0 | 27 |
| ✅ hono-stable-quickjs | 134 | 0 | 27 |
| ✅ nest-stable-node | 134 | 0 | 27 |
| ✅ nest-stable-quickjs | 134 | 0 | 27 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 1 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 1 |
| ✅ nitro-stable-node | 134 | 0 | 27 |
| ✅ nitro-stable-quickjs | 134 | 0 | 27 |
| ✅ nuxt-stable-node | 134 | 0 | 27 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 27 |
| ✅ sveltekit-stable-node | 153 | 0 | 8 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 8 |
| ✅ tanstack-start-node | 134 | 0 | 27 |
| ✅ tanstack-start-quickjs | 134 | 0 | 27 |
| ✅ vite-stable-node | 134 | 0 | 27 |
| ✅ vite-stable-quickjs | 134 | 0 | 27 |
✅ 📦 Local Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 27 |
| ✅ astro-stable-quickjs | 134 | 0 | 27 |
| ✅ express-stable-node | 134 | 0 | 27 |
| ✅ express-stable-quickjs | 134 | 0 | 27 |
| ✅ fastify-stable-node | 134 | 0 | 27 |
| ✅ fastify-stable-quickjs | 134 | 0 | 27 |
| ✅ hono-stable-node | 134 | 0 | 27 |
| ✅ hono-stable-quickjs | 134 | 0 | 27 |
| ✅ nest-stable-node | 134 | 0 | 27 |
| ✅ nest-stable-quickjs | 134 | 0 | 27 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 1 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 1 |
| ✅ nitro-stable-node | 134 | 0 | 27 |
| ✅ nitro-stable-quickjs | 134 | 0 | 27 |
| ✅ nuxt-stable-node | 134 | 0 | 27 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 27 |
| ✅ sveltekit-stable-node | 153 | 0 | 8 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 8 |
| ✅ tanstack-start-node | 134 | 0 | 27 |
| ✅ tanstack-start-quickjs | 134 | 0 | 27 |
| ✅ vite-stable-node | 134 | 0 | 27 |
| ✅ vite-stable-quickjs | 134 | 0 | 27 |
✅ 🐘 Local Postgres
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 27 |
| ✅ astro-stable-quickjs | 134 | 0 | 27 |
| ✅ express-stable-node | 134 | 0 | 27 |
| ✅ express-stable-quickjs | 134 | 0 | 27 |
| ✅ fastify-stable-node | 134 | 0 | 27 |
| ✅ fastify-stable-quickjs | 134 | 0 | 27 |
| ✅ hono-stable-node | 134 | 0 | 27 |
| ✅ hono-stable-quickjs | 134 | 0 | 27 |
| ✅ nest-stable-node | 134 | 0 | 27 |
| ✅ nest-stable-quickjs | 134 | 0 | 27 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 1 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 20 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 20 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 1 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 1 |
| ✅ nitro-stable-node | 134 | 0 | 27 |
| ✅ nitro-stable-quickjs | 134 | 0 | 27 |
| ✅ nuxt-stable-node | 134 | 0 | 27 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 27 |
| ✅ sveltekit-stable-node | 153 | 0 | 8 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 8 |
| ✅ tanstack-start-node | 134 | 0 | 27 |
| ✅ tanstack-start-quickjs | 134 | 0 | 27 |
| ✅ vite-stable-node | 134 | 0 | 27 |
| ✅ vite-stable-quickjs | 134 | 0 | 27 |
✅ 🪟 Windows
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack-node | 160 | 0 | 1 |
| ✅ nextjs-turbopack-quickjs | 160 | 0 | 1 |
✅ 🌐 Cross-language Conformance
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ python | 68 | 0 | 74 |
✅ vercel-http-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 133 | 0 | 28 |
| ✅ express | 133 | 0 | 28 |
| ✅ hono | 133 | 0 | 28 |
| ✅ nextjs-turbopack | 158 | 0 | 3 |
| ✅ nitro | 133 | 0 | 28 |
| ✅ vite | 133 | 0 | 28 |
✅ vercel-multi-region
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack | 27 | 0 | 0 |
✅ vercel-ws-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 133 | 0 | 28 |
| ✅ express | 133 | 0 | 28 |
| ✅ nextjs-turbopack | 158 | 0 | 3 |
| ✅ vite | 133 | 0 | 28 |
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 134043ms → this run 141697ms (Δ +7654ms, +6%) 📈 CRTT drill-down vs main (RTT distributions & profiles)RTT over stream progress (avg per tenth of stream, bars scaled min→max): RTT by chunk size (avg per log size bin, ~160B → ~12KB serialized, bars scaled min→max): Delivery jitter over stream progress (avg positive CDV per tenth of stream, bars scaled min→max): 📜 Previous results (1)f2af506Tue, 08 Sep 2026 20:49:37 GMT · run logs
Streams
ℹ️ Metric definitions & methodologyStreams: first-chunk RTT (the stream-open path, before any buffering/backpressure), CRTT percentiles, and worst delivery stall (CDV max). Cells are medians across iterations; per-run values in the artifacts. No 🔴/🟢 marks until targets attach. The collapsed STSO distribution section above buckets every step gap, split inline (same warm process — pure framework overhead) vs queue-hop (fresh process — dispatch, reinit, replay). The collapsed CRTT drill-down: per-variant RTT histograms (fixed log bins, 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) · Fan-out TTFS: fan-out time to first step (in-deployment start() → first of the parallel step bodies to complete) · Fan-out TTLS: fan-out time to last step (in-deployment start() → last of the parallel step bodies to complete, i.e. when the Promise.all resolves) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · CRTT: chunk round-trip time (per-chunk write → read latency, one clock domain: deployment → stream backend → same deployment) · CDV: chunk delay variation / delivery jitter (inter-arrival gap minus inter-write gap per seq-adjacent pair; skew-free; the row is each run's MAX positive value, so one stall moves it) 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 · Promise.all(100 steps): 100 trivial no-op steps started together in a single Promise.all; Fan-out TTFS is the first of them to complete and Fan-out TTLS the last, both from the in-deployment clientStart, so their gap is the spread the runtime adds across the fan-out · paced control (100/s, 60B): the control: 300 tiny (~60B) deltas metronome-paced at 100/s — zero workload structure, so it reads the transport floor and flush cadence, and disambiguates transport-wide vs workload-specific when a replay row moves · size sweep (100/s, 160B-12KB): same pacing as the control with deltas padded in rotation across seven log-spaced sizes (~160B–12KB) — rotation decouples size from stream position, so it isolates whether chunk size causes latency · replay gateway-gpt-5.4-nano-2000t (1x): raw provider SSE cadence captured at the AI gateway boundary (gpt-5.4-nano, the most popular gateway model; per-token deltas p50 208B = the modal production chunk size), replayed exactly as measured — the typical customer's workload; its CDV is the typical customer's real delivery jitter · replay eve-gpt-5.6-sol-2000t (1x): a captured eve turn (gpt-5.6-sol, the most-used demanding eve model; ~2000 output tokens = production p50 turn length) replayed exactly as measured — eve's envelope protocol re-ships the cumulative message so sizes ramp 142B→13KB; the demanding outlier tenant's reality · replay eve-gpt-5.6-sol-2000t (2x): the same eve capture at 2x — the headroom/stress row; real fast-tier models emit the same chunk sizes at proportionally higher rate, so time compression is a faithful speed model · first chunk (pooled): every run's seq-0 RTT pooled across all stream scenarios — the first chunk precedes any workload differentiation, so pooling samples one shared stream-open path with exact percentiles Replay cadences (semantic sha256) — eve-gpt-5.6-sol-2000t 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 All timestamps are deployment-side; runs are triggered in-deployment, so the CI runner and api.vercel.com sit outside every measured window. TTFS = Cold starts stay in the numbers (real bursty-workload latency, inflates P75+); Best is the warm floor. |
… page Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Sim WorldSimulated world deterministic testing for races. Traces 🟠 world-sim scenario book — 1 fail of 41 total
Full trace: |
| ? (eventLog.cursor ?? undefined) | ||
| : eventLog.type === 'loadAfter' | ||
| ? eventLog.cursor | ||
| : undefined, |
There was a problem hiding this comment.
nit: the nesting here is getting insane, im not sure how much this stuff matters in the current era of software dev but seems like we might be due for refactor
|
No backport to This is a diagnostics enhancement, not a fix: it adds new observability surface (a new To override, re-run the Backport to stable workflow manually via |
…ry-2 * origin/main: [core] Log pending consumers in divergence diagnostics (#4021) fix(web-shared): stop event payload stub flash in events view (#3951) fix: order the 429 check before the 4xx check in the workflow skill (#3915) test(swc-plugin): verify class-name preservation at runtime (#4015) (chore) Update Next.js to 16.3.4 in the workbench apps and @workflow/next (#4026)
`runtime.ts` computes a source-map-remapped `errorStack` when a run fails and
passes it to a log whose framing line — "Error while running workflow" — has
no body of its own. `composeLogLine` drops `errorStack` unconditionally, on
the assumption (true for the step executor and the combined runtime, which
render `${framing}\n${stack}`, false here) that the message already carries
it. The stack never reaches the console; #4021 noted this at the call site
and worked around it by adding `errorMessage`, but the stack itself is still
discarded.
- `composeLogLine` promotes the `errorStack` field into the stack body when
the message carries no body of its own, so it goes through the same frame
trimming and is still never duplicated when the caller did embed one. This
also lets #4021's existing `body.includes(errorMessage)` check suppress the
now-redundant `error` row at this call site.
- The header row is skipped when it would be a lone class name that the
promoted stack header already states. A badge still always renders —
attribution is the one thing the stack cannot express — so the step
executor and combined-runtime sites are untouched, as is a stack naming a
different class than `errorName`.
Adds a runtime-level regression test that drives a throwing workflow through
`workflowEntrypoint` and asserts the emitted `console.error` line carries the
message and a stack frame, plus formatter unit tests for the promote,
don't-duplicate, badge and different-class cases. No existing snapshot
changes: the composition is identical everywhere except the run-failure log.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Pranay Prakash <1797812+pranaygp@users.noreply.github.com>
`runtime.ts` computes a source-map-remapped `errorStack` when a run fails and
passes it to a log whose framing line — "Error while running workflow" — has
no body of its own. `composeLogLine` drops `errorStack` unconditionally, on
the assumption (true for the step executor and the combined runtime, which
render `${framing}\n${stack}`, false here) that the message already carries
it. The stack never reaches the console; #4021 noted this at the call site
and worked around it by adding `errorMessage`, but the stack itself is still
discarded.
- `composeLogLine` promotes the `errorStack` field into the stack body when
the message carries no body of its own, so it goes through the same frame
trimming and is still never duplicated when the caller did embed one. This
also lets #4021's existing `body.includes(errorMessage)` check suppress the
now-redundant `error` row at this call site.
- The header row is skipped when it would be a lone class name that the
promoted stack header already states. A badge still always renders —
attribution is the one thing the stack cannot express — so the step
executor and combined-runtime sites are untouched, as is a stack naming a
different class than `errorName`.
Adds a runtime-level regression test that drives a throwing workflow through
`workflowEntrypoint` and asserts the emitted `console.error` line carries the
message and a stack frame, plus formatter unit tests for the promote,
don't-duplicate, badge and different-class cases. No existing snapshot
changes: the composition is identical everywhere except the run-failure log.
Co-authored-by: vercel[bot] <35613825+vercel[bot]@users.noreply.github.com>
Co-authored-by: Pranay Prakash <1797812+pranaygp@users.noreply.github.com>
Why
A production run failed with
CORRUPTED_EVENT_LOGafter four divergences on onewait_createdevent, and diagnosing it took hours because the runtime did not say the decisive facts: what was holding that event's ordinal, which pass of which invocation diverged, and whether every divergence hit the same slot. This PR adds those to the existing messages and logs. No behavior change.What
1. Name what holds the ordinal (
@workflow/core)Step, wait and hook correlation ids share one ULID draw per entity (
step_<ulid>,wait_<ulid>,hook_<ulid>). When a replay cannot consume an event, theReplayDivergenceErrormessage now appends the pending invocation holding that ULID body and a snapshot of the consumer's walk, on both theReplay could not consume eventandReplay finished without consuming eventpaths. The leading sentence is unchanged. NewEventsConsumer.describe()supplies the snapshot instead of reaching into private fields.2. Say which pass of which invocation diverged (
@workflow/core)The
Workflow replay diverged; queueing a recovery replay…WARN and the terminalError while running workflowlog gainloopIteration,servedByRetainedSession,eventLogState,eventLogLength,eventLogLastEventId,cursor,hasHookInput,hasWaitContinuation,isRecoveryReplay,setupSource, anddivergenceEventIds. All in scope already, no network calls.The console renderer (
log-format.ts) listederrorMessageas a well-known field but never rendered it, so any warn/error whose message had no stack body silently dropped the error text. That is how the production WARN lost the divergence text. It now renders as anerrorrow whenever neither the framing nor the body carries it. The terminalError while running workflowlog had the same gap (itserrorStackis dropped by design and the message has no body), so it now passeserrorMessagetoo.3. Divergence history on the recovery message (
@workflow/world,@workflow/core)replayDivergenceon the queue payload gains an optionaleventIds: string[], accumulated across hops and capped at the recovery budget + 1. Parsed with.catch(undefined)so a malformed value degrades to "no history" instead of failing every delivery of the message. The terminalCorruptedEventLogErrormessage lists it:Tests
replay-divergence.test.ts: drives a replay where the body callsuseStep('drainStep')while the log holdswait_createdunder the same ULID body; asserts the message names the step and the consumer snapshot. Plus unit tests for the ordinal lookup anddescribe().runtime.test.ts: the existing divergence test now spies on console output and asserts the WARN fields, the history on the recovery message, and the terminal message listing all ids.log-format.test.ts/logger.test.ts: new test for the WARN shape; two snapshots updated because they were pinning the droppederrorMessage.queue.test.ts(@workflow/world): round-trip, absent, and malformedeventIds.🤖 Generated with Claude Code