Stop logging on healthy workflow execution - #3878
Conversation
A successful run printed several lines that described the runtime working correctly. Most of it was fallout from defaulting the events transport to WebSockets (#3702): three breadcrumbs written while the transport was opt-in became default-path output, because each one reported a choice the caller no longer makes. - `world-vercel: using ws events transport (…)` ran once per cold start on every deployment, naming the transport it was always going to use. - The `projectConfig` proxy fallback warned once per process. That World cannot hold a socket, so with WS on by default every CLI command and the observability app warned about a fallback nobody asked for and nobody can act on. Debug-gated and reworded from "requested but" to "unavailable for". - The `max_duration` / `auth_expiry` drain notice is routine: the transport reconnects from the close that follows and no write is lost. Swept for the same shape elsewhere: - `world-local`'s queue-concurrency notice fired per message once a fan-out exceeded the limit — the semaphore doing its job. - `@workflow/world`'s active-run recovery line printed on every dev-server restart with work in flight. The re-enqueue *failure* above it stays unconditional; that one leaves a run unresumed. - The port-detection diagnostics in `@workflow/utils` keyed off `NODE_ENV=development`, which is the only environment that reaches them, so the gate made them unconditional for their whole audience. All of it moves behind `DEBUG=workflow:*` via a new `debugLog` in `@workflow/utils`, joining world-vercel's existing `httpLog` and `logRetry` output under one selector. Warnings and errors are untouched, so a run that actually goes wrong is no quieter than before — the ws-transport tests that assert failures are never silent still pass unchanged. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Co-Authored-By: Pranay Prakash <1797812+pranaygp@users.noreply.github.com>
🦋 Changeset detectedLatest commit: 1d5f28b The changes in this PR will be included in the next version bump. This PR includes changesets to release 23 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 153650ms → this run 155201ms (Δ +1551ms, +1%) 📈 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)64343e9Fri, 28 Aug 2026 01:46:43 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. |
🧪 E2E Test Results❌ Some tests failed ❌ Failed E2E Tests▲ Vercel Production (8 failed)python-node (8 failed):
🌐 Cross-language Conformance (9 failed)python (9 failed):
|
| Passed | Failed | Skipped | Total | |
|---|---|---|---|---|
| ❌ ▲ Vercel Production | 3570 | 8 | 742 | 4320 |
| ✅ 💻 Local Development | 3922 | 0 | 558 | 4480 |
| ✅ ��� Local Production | 3922 | 0 | 558 | 4480 |
| ✅ 🐘 Local Postgres | 3922 | 0 | 558 | 4480 |
| ✅ 🪟 Windows | 320 | 0 | 0 | 320 |
| ❌ 🌐 Cross-language Conformance | 0 | 9 | 132 | 141 |
| ✅ vercel-http-transport | 817 | 0 | 143 | 960 |
| ✅ vercel-multi-region | 27 | 0 | 0 | 27 |
| ✅ vercel-ws-transport | 553 | 0 | 87 | 640 |
| Total | 17053 | 17 | 2778 | 19848 |
Details by Category
❌ ▲ Vercel Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-node | 132 | 0 | 28 |
| ✅ astro-quickjs | 132 | 0 | 28 |
| ✅ example-node | 132 | 0 | 28 |
| ✅ example-quickjs | 132 | 0 | 28 |
| ✅ express-node | 132 | 0 | 28 |
| ✅ express-quickjs | 132 | 0 | 28 |
| ✅ fastify-node | 132 | 0 | 28 |
| ✅ fastify-quickjs | 132 | 0 | 28 |
| ✅ hono-node | 132 | 0 | 28 |
| ✅ hono-quickjs | 132 | 0 | 28 |
| ✅ nest-node | 132 | 0 | 28 |
| ✅ nest-quickjs | 132 | 0 | 28 |
| ✅ nextjs-turbopack-node | 157 | 0 | 3 |
| ✅ nextjs-turbopack-quickjs | 157 | 0 | 3 |
| ✅ nextjs-webpack-node | 157 | 0 | 3 |
| ✅ nextjs-webpack-quickjs | 157 | 0 | 3 |
| ✅ nitro-node | 132 | 0 | 28 |
| ✅ nitro-quickjs | 132 | 0 | 28 |
| ✅ nuxt-node | 132 | 0 | 28 |
| ✅ nuxt-quickjs | 132 | 0 | 28 |
| ❌ python-node | 0 | 8 | 152 |
| ✅ sveltekit-node | 151 | 0 | 9 |
| ✅ sveltekit-quickjs | 151 | 0 | 9 |
| ✅ tanstack-start-node | 132 | 0 | 28 |
| ✅ tanstack-start-quickjs | 132 | 0 | 28 |
| ✅ vite-node | 132 | 0 | 28 |
| ✅ vite-quickjs | 132 | 0 | 28 |
✅ 💻 Local Development
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 📦 Local Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🐘 Local Postgres
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🪟 Windows
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-quickjs | 160 | 0 | 0 |
❌ 🌐 Cross-language Conformance
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ❌ python | 0 | 9 | 132 |
✅ vercel-http-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ hono | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ nitro | 132 | 0 | 28 |
| ✅ vite | 132 | 0 | 28 |
✅ vercel-multi-region
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack | 27 | 0 | 0 |
✅ vercel-ws-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ vite | 132 | 0 | 28 |
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
|
shalabhc
left a comment
shalabhc
left a comment
There was a problem hiding this comment.
changeset looks too large tho
| '@workflow/world': patch | ||
| --- | ||
|
|
||
| Stop logging on healthy workflow execution. A successful run now prints nothing; |
There was a problem hiding this comment.
make this more terse (see the other changlogs. should just be one-two line. not a story)
There was a problem hiding this comment.
Trimmed to two sentences in 1d5f28b — matches the AGENTS.md guidance (one sentence, two at most) and the length of the other changelogs. The per-log-site rationale stays in the PR description. Package list and bump types are unchanged.
| // Debug-gated: this is the semaphore doing its job. A fan-out wider | ||
| // than the limit queues behind it and every message still runs, so a | ||
| // per-message warning turns a healthy wide run into a wall of output. | ||
| debugLog( |
Review feedback: the changeset read as a story. AGENTS.md asks for one sentence, or two at most; the per-log-site rationale already lives in the PR description. Package list and bump types are unchanged. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Co-Authored-By: Pranay Prakash <1797812+pranaygp@users.noreply.github.com>
|
No backport to This is log-noise cleanup, not a stability fix: it changes existing logging behavior (warn/log downgraded to a To override, re-run the Backport to stable workflow manually via |
2 participants
What
Normal workflow execution should print nothing. Today a healthy run emits several lines that only describe the runtime working correctly.
Most of it is fallout from #3702, which defaulted the events transport to WebSockets. Three log sites written while the transport was opt-in became default-path output, because each one reports a choice the caller no longer makes:
world-vercel: using ws events transport (…)…requested but a World with projectConfig … falling backprojectConfigWorlds — warn about a fallback they neither chose nor can act on…received a drain notice (reason: max_duration…)max_durationandauth_expiryare routine; the transport reconnects from the close that follows and no write is lostSwept for the same shape elsewhere and found three more:
world-localqueue concurrency — warned per message once a fan-out exceeded the limit. That is the semaphore doing its job; every message still runs.@workflow/worldactive-run recovery — printed on every dev-server restart with work in flight. Resuming active runs is what a restart is for.@workflow/utilsport detection — two diagnostics gated onNODE_ENV=development, which is the only environment that reaches this code, so the gate made them unconditional for their entire audience. ThegetWorkflowPortone fires on an ordinary startup race (dev server still compiling its workflow routes) that the fallback then resolves correctly.How
A new
debugLogin@workflow/utilsgates onDEBUG=workflow:*(or*), the same selector@workflow/core's logger already uses, so these join world-vercel's existinghttpLogandlogRetryoutput under one switch. It readsDEBUGper call rather than at module load, since Worlds are built long after import.@workflow/worldhand-rolls the same check — that package deliberately carries no workspace dependencies, matching howenv-config.tshand-rollsglobalSingleton().Nothing about error logging changed. Every
console.error/console.warnon a genuine fault is untouched, including the ws-transport's "failures are never silent" set and the re-enqueue failure sitting directly above the recovery line that did get gated — that one leaves a run unresumed.logger.warn/logger.errorin@workflow/corestill print unconditionally.Testing
packages/{utils,world,world-local,world-vercel}/src— 1449 passed, 4 skipped.packages/core/src— 2268 passed (unchanged; core consumes@workflow/utils).debug-log.test.ts(off by default, acceptsworkflow:*/*, ignores another library's selector, re-reads per call); ws-transport tests split into DEBUG / no-DEBUG pairs; recovery tests assert a successful recovery logs at no level while a failed re-enqueue still warns withoutDEBUG.ws-transport.tsalone fails exactly 4 of them.biome checkon the changed files reports the same 7 pre-existing warnings as base (exit 0);turbo typecheckclean for all four packages.Two
packages/utils/src/check-data-dir.test.tscases fail on this machine on unmodified main as well — a leftover gitignored.workflow-dataat the repo root that the test walks up and finds. Unrelated to this change.Docs
worlds/v5/vercel.mdxclaimed theprojectConfigfallback logs a warning once per process. Updated to say it is silent and reported underDEBUG, and to point atworkflow.events.transporton the per-write span as the durable answer to which transport carried a run.🤖 Generated with Claude Code