fix(core): keep the error message and stack in the run-failure log - #4145
Conversation
🦋 Changeset detectedLatest commit: 5a48073 The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
There was a problem hiding this comment.
🟡 Changes recommended
Restrict error-message detection to the stack header so unrelated frames cannot suppress the message row.
Get a fresh assessment by requesting another Copilot review.
Pull request overview
Improves workflow failure logging so error messages and stacks are preserved.
Changes:
- Passes
errorMessagefrom runtime failure handling. - Promotes metadata stacks and formats missing messages.
- Adds regression tests and a patch changeset.
File summaries
| File | Changes |
|---|---|
packages/core/src/runtime.ts |
Includes error messages in failure logs. |
packages/core/src/runtime.test.ts |
Adds run-failure logging coverage. |
packages/core/src/logger.test.ts |
Updates log snapshots. |
packages/core/src/log-format.ts |
Preserves stacks and renders error details. |
packages/core/src/log-format.test.ts |
Tests formatting behavior. |
.changeset/run-failure-log-error-details.md |
Records the core patch release. |
Review details
- Files reviewed: 6/6 changed files
- Comments generated: 1
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
| const errorMessageShown = | ||
| errorMessage !== null && | ||
| (framing.includes(errorMessage) || body.includes(errorMessage)); |
`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>
693028f to
5a48073
Compare
🧪 E2E Test Results✅ All tests passed 🛠 Infra Events (absorbed by the harness)Platform anomalies the e2e harness detected and worked around (e.g. a run the queue never picked up, replaced by a fresh run). Clustered timestamps indicate a backend blip; a steady drip indicates a platform issue worth escalating.
E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 🌐 Cross-language Conformance
✅ vercel-http-transport
✅ vercel-multi-region
✅ vercel-ws-transport
|
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 165479ms → this run 157036ms (Δ -8443ms, -5%) 📈 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): ℹ️ 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. |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 world-sim scenario book — 1 fail of 41 total
Full trace: |
About these numbersSizes are gzip; parentheses show the change against
|
|
No backport to The fix is entirely about To override, re-run the Backport to stable workflow manually via |
The bug
When a workflow run fails,
packages/core/src/runtime.tscomputes a source-map-remappederrorStackand logs it alongside a framing line that has no body of its own:composeLogLineinpackages/core/src/log-format.tsdoesredundant.add('errorStack')unconditionally. That's correct for the step executor and the combined runtime, which render${framing}\n${stack}into the message string — but this call site logs a bare, single-line framing, so the stack is dropped with nothing to replace it.#4021 hit the same wall from the
errorMessageside and worked around it, leaving a comment at the call site that names the problem exactly:So today the message survives but the stack still doesn't — a user tailing logs sees that their run failed and what the error said, but never where it was thrown.
Reproduction
packages/core/src/runtime.test.tsgains a test that drives a throwing workflow through the realworkflowEntrypointand asserts the emittedconsole.errorline. Againstmainit fails on the stack assertion:The fix
composeLogLinepromotes theerrorStackfield into the stack body when the message carries no body of its own. It then goes through the sametrimStackBodyframe collapsing as an embedded stack, and is still never duplicated when the caller did embed one. This also lets [core] Log pending consumers in divergence diagnostics #4021's existingbody.includes(errorMessage)check suppress the now-redundanterrorrow here, since the promoted stack header already carries the message.errorName.runtime.tsis updated;errorMessagestays passed, since it's still the row shown when a throw produced no stack at all.Before / after at this call site:
Tests
runtime.test.ts(the reproduction above).log-format.test.tscases: stack promoted when the message has none; no duplication when the message already embeds it; class row kept when a badge is present; class row kept when the stack names a different class.pnpm vitest run srcinpackages/core: 2443 passed, 3 expected fail, 1 skipped.tsc --noEmitclean;biome checkwarning count unchanged frommain(301).🤖 Generated with Claude Code