From d96f264de76bc522ce0564fdd51d37b093dde9a6 Mon Sep 17 00:00:00 2001 From: ChiGao Date: Wed, 19 Aug 2026 12:21:49 +0000 Subject: [PATCH] feat(telemetry): link daemon HTTP request spans to inbound W3C traceparent (#9391) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat(telemetry): link daemon HTTP request spans to inbound W3C traceparent The daemon HTTP surface records a request span per request, but every span starts a new trace: a caller forwarding the standard W3C traceparent header (OTel-instrumented clients, proxies, gateways) gets no linkage back to its own trace. Extract traceparent/tracestate from inbound request headers in the daemon telemetry middleware and parent the request span to that remote context. Extraction reuses the same path as the existing JSON-RPC _meta extraction (global propagator first, strict manual fallback so behavior is identical without a registered SDK) and fails closed: requests without a valid header keep the exact current span shape. * fix(telemetry): guard inbound traceparent sampling and align W3C fallback - Force TraceFlags.SAMPLED on inbound HTTP parents via the existing shouldForceSampled() matrix: an unsampled remote parent under the default parentbased_always_on sampler silently dropped the request span, the whole next() subtree, and the session-subprocess spans forwarded via _meta (review C1). - Replace the hand-rolled manual fallback parser with a direct W3CTraceContextPropagator instance so acceptance rules (future versions, tracestate, all-zero ids, version-00 extension field) match the registered path with or without an initialized SDK. - Gate middleware extraction behind isTelemetrySdkInitialized() to skip the hot-path parse when telemetry is off, and emit a debug daemon log when a present-but-invalid traceparent header is rejected. - Re-export DaemonRequestSpanOptions from the core barrel and add a type-level guard so the parentContext field cannot silently disappear (vitest alone cannot catch its removal). * chore(vscode): regenerate companion NOTICES.txt for @opentelemetry/core * fix(telemetry): lazy-load OTel core fallback propagator behind SDK init Address review feedback on the inbound traceparent linkage: - Keep @opentelemetry/core out of the static graph. The module-level W3CTraceContextPropagator in daemon-tracing.ts pulled the CJS barrel (bot-measured +65,046 bytes) into every closure loading that module, including telemetry-off deployments. daemon-tracing.ts now keeps only a holder + setter (setDaemonFallbackPropagator, typed against @opentelemetry/api — type imports stay free at runtime); the lazy sdk-impl.ts chunk, whose closure already contains @opentelemetry/core via sdk-node/resources, constructs and injects the W3C instance on the successful SDK assembly path. Until injection, extraction returns no parent context: the HTTP edge is already gated on isTelemetrySdkInitialized (nothing changes when telemetry is off), and the _meta edge's consumers (withDaemonSpan / withInteractionSpan) short-circuit on the same flag, so an unresolved pre-init parent never had an observable effect. - Add the mutation-verified fail-closed test for the header-extraction try/catch in daemonTelemetryMiddleware: a throwing extractor leaves the request settling normally (recordDaemonHttpRequest still fires once) with no parentContext on the span options. - Record the rejected traceparent value (truncated to 128 chars) as http.request.header.traceparent on the invalid-header breadcrumb — traceparent only carries trace-id/span-id/flags, so this is privacy-safe and makes broken cross-service joins diagnosable. Also document why the _meta extraction path deliberately skips shouldForceSampled (trusted in-process bridge vs external HTTP input). * feat(telemetry): carry inbound trace id into daemon access log with telemetry off Telemetry off (the default) left daemon logs without any trace id: with no request span, the log trace prefix never fires, so a caller forwarding W3C traceparent could not be joined to its daemon log lines. The middleware now parses the header with a plain regex (extractInboundTraceId — same shape/all-zero/ff rejections as the W3C propagator, no OTel machinery) and stores the trace id on the per-response telemetry context. The access log emits it as the camelCase traceId field of "request completed", keeping the log-based join alive with no telemetry config and no trace backend. With telemetry on nothing changes: the request span already carries the caller's trace id into the log prefix. * fix(telemetry): unify _meta/HTTP sampling and repair build export - Export extractInboundTraceId from the core barrel: the previous commit exported it from daemon-tracing.ts only, so downstream package builds failed with TS2305. - extractDaemonTraceContext now applies the same shouldForceSampled() matrix as the HTTP edge: the _meta path is also reachable from direct ACP clients (acpAgent newSession/loadSession/unstable_resumeSession and Session.prompt pass caller-controlled _meta), so an external sampled=0 parent no longer silences daemon spans there either. The in-process bridge is unaffected (its injected values are already SAMPLED). - The rejected-header breadcrumb now goes through sanitizeLogText so a crafted traceparent cannot forge log line structure with control characters. - Add the sdk-impl wiring test: after initializeTelemetry the injected W3C fallback propagator resolves inbound HTTP parents. * fix(telemetry): align log-path traceparent parsing and emit traceId in both modes - extractInboundTraceId now mirrors the vendored W3C propagator's acceptance exactly: single optional leading/trailing whitespace and trailing extension fields above version 00 (version 00 must stay four fields). Previously the strict four-field anchor made the two paths disagree on the same forward-compatible header, silently dropping the access-log traceId for exactly the callers the propagator path supports. - The camelCase traceId access-log field is now captured whenever a valid header parses, regardless of telemetry mode, so one saved log query / alert shape works for every deployment; with telemetry on the snake_case span prefix carries the same id redundantly. * fix(telemetry): move inbound trace id getter out of the middleware module 52d572c0f2 made the access log statically import the telemetry middleware module to read the captured inbound trace id. The access log sits inside the serve fast-path pre-listen closure (run-qwen-serve imports it directly), so the middleware's core-barrel import graph came along for the ride and check-serve-fast-path-bundle started failing: the 5.6MB core chunk (shell tool, glob, chokidar, @iarna/toml, fzf) became statically reachable from run-qwen-serve. Move the response-context symbol, its type, and the getDaemonTelemetryInboundTraceId getter into a new import-light telemetry-context.ts; the middleware imports the symbol from there and re-exports the getter, so the access log no longer links against the telemetry module at all. * fix(telemetry): capture inbound trace id pre-auth under a dedicated symbol * test(telemetry): pin the trace id seam through the context module getter --------- Co-authored-by: 秦奇 --- ...08-18-daemon-http-inbound-trace-context.md | 142 +++ docs/developers/development/telemetry.md | 39 + package-lock.json | 1 + packages/cli/src/serve/server.ts | 11 +- .../cli/src/serve/server/access-log.test.ts | 37 + packages/cli/src/serve/server/access-log.ts | 7 + .../cli/src/serve/server/telemetry-context.ts | 51 ++ .../cli/src/serve/server/telemetry.test.ts | 365 +++++++- packages/cli/src/serve/server/telemetry.ts | 129 ++- packages/core/package.json | 1 + .../core/src/telemetry/daemon-tracing.test.ts | 288 ++++++ packages/core/src/telemetry/daemon-tracing.ts | 166 +++- packages/core/src/telemetry/index.ts | 3 + packages/core/src/telemetry/sdk-impl.ts | 12 + packages/core/src/telemetry/sdk.test.ts | 20 +- packages/core/src/telemetry/tracer.ts | 2 +- packages/vscode-ide-companion/NOTICES.txt | 828 +++++++++--------- 17 files changed, 1638 insertions(+), 464 deletions(-) create mode 100644 docs/design/2026-08-18-daemon-http-inbound-trace-context.md create mode 100644 packages/cli/src/serve/server/telemetry-context.ts diff --git a/docs/design/2026-08-18-daemon-http-inbound-trace-context.md b/docs/design/2026-08-18-daemon-http-inbound-trace-context.md new file mode 100644 index 0000000000..8efc0a8c93 --- /dev/null +++ b/docs/design/2026-08-18-daemon-http-inbound-trace-context.md @@ -0,0 +1,142 @@ +# Daemon HTTP inbound trace context + +## Motivation + +The daemon already _propagates_ trace context outbound: prompt requests carry a +`traceparent` inside JSON-RPC `_meta`, and the daemon extracts it to parent its +bridge spans (`extractDaemonTraceContext`). The HTTP surface, however, only +_records_ request spans — every `qwen-code.daemon.request` span starts a new +trace. An HTTP caller that forwards the standard W3C `traceparent` header +(corporate proxies, OTel-instrumented clients, ACP gateways) gets no linkage: +the server-side span cannot be joined back to the caller's trace, so +cross-service debugging falls back to timestamps. + +W3C Trace Context extraction at the HTTP server edge is standard +`SpanKind.SERVER`-adjacent behavior per the OTel HTTP semantic conventions, and +the plumbing already exists: `withDaemonSpan` accepts an explicit +`parentContext`. + +## Design + +1. **Core** (`daemon-tracing.ts`): the existing `_meta` extraction logic + (global `propagation.extract` first, then a direct + `W3CTraceContextPropagator` instance as fallback, so acceptance rules — + future traceparent versions, `tracestate`, all-zero ids — are identical + with and without a registered global propagator) moves into a shared + `contextFromTraceparentValues` helper. A new + `extractDaemonHttpTraceContext(headers)` reads `traceparent`/`tracestate` + from a Node-style (lowercased) header object and reuses that helper. + `DaemonRequestSpanOptions` gains an optional `parentContext` passed straight + through to `withDaemonSpan`. +2. **Serve middleware**: `daemonTelemetryMiddleware` extracts from + `req.headers` per request (fail-closed to `undefined`, telemetry never + affects handling) and passes the context only when extraction succeeded — + requests without a valid header keep the exact current span shape. + Span-context extraction is gated on `isTelemetrySdkInitialized()`, so + telemetry-off deployments pay no OTel machinery on the hot path — only the + single-regex trace-id capture described under Log correlation — and a + present-but-invalid header emits a debug daemon log + (`qwen-code.daemon.traceparent.invalid`) so a rejected header is + diagnosable from daemon logs alone. + + Note the whole subtree relocates with the request span, not just + `daemon.request` itself: session-subprocess spans reached via `_meta` + (prompt / model / tool) also join the caller's trace, so anything + aggregating or alerting by `traceId` sees session-side spans change + ownership too. + +## Log correlation + +Daemon log lines already carry a `[trace_id=… span_id=…]` prefix when written +inside an active recording span (`getActiveTraceContext`, #9084). Telemetry +on, this PR closes the loop end to end: the request span parents to the +caller's trace, so every daemon log line for that request — including the +access log's `request completed` — is prefixed with the caller's trace id. +(The access log's `finish` listener reads the active span through the same +AsyncLocalStorage propagation as the logger, so ordering of the two `finish` +listeners is irrelevant for the prefix.) + +Telemetry off — the default — there is no span, so the prefix never fires. +A separate lightweight path keeps the log-based join alive with no telemetry +config and no trace backend: the middleware parses the `traceparent` header +with a plain regex (`extractInboundTraceId`, acceptance mirroring the vendored +W3C propagator — same shape/all-zero/`ff` rejections, single optional +leading/trailing whitespace, trailing extension fields above version `00` — +so a header either joins on both paths or neither; `tracestate` stays in the +propagator path since a log line only needs a plausible trace id) and stores +the trace id on the per-response telemetry context (the same +symbol the workspace hash uses). The access log's `finish` callback reads it +back and emits it as the camelCase `traceId` field of `request completed` — +distinct from the logger's reserved snake_case `trace_id` prefix keys, so a +caller cannot spoof the span-derived prefix. The camelCase field is captured +in both telemetry modes whenever a valid header parses, so one log query +shape works for every deployment; with telemetry on the snake_case span +prefix carries the same id redundantly. The field is omitted, not +empty, when no valid header is present, and every step stays fail-closed +(telemetry must not affect request handling). + +## Sampling policy + +The caller's `sampled` bit is not adopted verbatim on the HTTP path. Under +the default `parentbased_always_on` sampler (the daemon SDK configures no +sampler), a remote unsampled parent delegates to `AlwaysOffSampler` and would +silently delete the request span, everything under `next()`, and — via the +`_meta` forwarding — the session-subprocess spans. `sampled=0` is simply the +caller's head-based ratio sampling, so inbound HTTP parents force +`TraceFlags.SAMPLED` through the same `shouldForceSampled()` decision matrix +as the synthetic session root: `parentbased_*` defaults and `always_on` force +sampling; `parentbased_always_off` honors the operator's opt-out; +non-parentbased samplers (e.g. `traceidratio`) keep the caller's flags and +decide per span. The `_meta` path applies the same forcing: for the +in-process bridge (daemon → subprocess) it is a no-op — that parent is our +own span, already SAMPLED under this policy — while direct ACP clients can +also attach `_meta` with a caller-controlled `sampled=0`, which is external +input exactly like the HTTP header and gets the same protection. + +## Non-goals + +- No new span kinds or attributes: existing `qwen-code.daemon.request` spans + stay `SpanKind.INTERNAL` with the same attributes; only the parent link + changes when a valid header is present. +- No `traceparent` _response_ injection and no W3C `tracingresponse` support. +- No new sampling configuration surface: the inbound policy reuses the + existing `shouldForceSampled()` matrix (see above); the SDK's own sampler + remains the only sampler authority. + +## Alternatives considered + +- Changing the request span to `SpanKind.SERVER` per HTTP semconv: **known + gap** — `qwen-code.daemon.request` is the daemon's only SERVER-adjacent + span (`HttpInstrumentation` never patches the server side here because the + SDK loads lazily), so backends deriving service topology / RED metrics + from SERVER spans (Tempo service-graph, ARMS) will not recognize the + daemon as a service inside the caller's trace. Switching would mutate the + shape of every existing daemon.request span and can shift backend + grouping; deferred as a follow-up. +- Extracting inside the core `withDaemonRequestSpan` from a raw header bag: + rejected because core request-span options are transport-primitive today; + the middleware is the only place that knows the carrier is HTTP headers. + +## Testing + +- Unit: header extraction (valid / absent / malformed / all-zero ids / array + value / version `ff` / version `00` with extension field / future version + `01` / inbound `tracestate`), request-span parenting through + `withDaemonRequestSpan`, the sampled-flag decision matrix (default forced, + `parentbased_always_off` and `traceidratio` verbatim, `_meta` path forced + under the default sampler and verbatim on opt-out), middleware pass-through + (present vs omitted key, telemetry-off + skip, rejected-header debug log), and a type-level guard keeping + `parentContext` on `DaemonRequestSpanOptions`. +- Unit (telemetry-off log join): `extractInboundTraceId` (valid / absent / + malformed / all-zero ids / version `ff` / array value / future version, + plus no-propagator-needed in the fresh-module state), middleware capture + (telemetry off with and without a header, telemetry on emitting the + camelCase field alongside the span prefix), + handler-resolved context initialization not clobbering the stored id), and + the access log emitting / omitting the `traceId` field. +- Dry run: `serve` with `QWEN_TELEMETRY_OUTFILE`, one curl with a fixed + `traceparent` — exported span must share the header's traceId and parent to + its spanId; a control request without the header must stay on its own trace. + With telemetry disabled, the same curl must still log + `request completed` with `traceId` matching the header. diff --git a/docs/developers/development/telemetry.md b/docs/developers/development/telemetry.md index d0eac94883..d0cfaed2e7 100644 --- a/docs/developers/development/telemetry.md +++ b/docs/developers/development/telemetry.md @@ -403,6 +403,45 @@ established the principle: "telemetry's scope of work doesn't include sending identifiers to LLM providers"; correlation-header work moves to its own design discussion rather than landing under telemetry. +## Inbound correlation (daemon HTTP API) + +The daemon HTTP API accepts the standard W3C `traceparent` header on every +request. Two consumers read it independently: + +- **Request span re-parenting (telemetry enabled).** When the telemetry SDK + is initialized, a valid header is extracted as the request span's remote + parent, so daemon spans attach under the caller's trace instead of + starting a new one. The `_meta` forwarding path reads the same parent + chain, so session subprocess spans forwarded through a daemon request + inherit it too. +- **Access-log `traceId` field (both modes).** A dedicated pre-auth capture + middleware parses the header on every request — including ones + short-circuited at auth (401), the rate limiter (429), the JSON body + parser (400), or never matched by any route (404) — and the access log + emits the caller trace id as a camelCase `traceId` field. With telemetry + disabled this field is the only join between a daemon log line and the + caller's logs (or trace backend), so one saved query works for both modes + with no telemetry configuration. + +An invalid-but-present header is rejected (the span stays parentless) and +leaves a rate-limited DEBUG breadcrumb +(`qwen-code.daemon.traceparent.invalid`) recording the rejected value, so a +broken cross-service join is diagnosable from daemon logs alone. + +### Forced sampling under inbound parents + +Under the default `parentbased_always_on` sampler (and other parentbased +defaults), a remote parent's `sampled=0` flag is a head-based decision on +the caller's side, not a request to drop daemon telemetry, so extraction +forces the SAMPLED flag on inbound parents. The only opt-out is +`OTEL_TRACES_SAMPLER=parentbased_always_off`, which honors the caller's +flags — note it also disables root-span sampling for the whole daemon, not +just inbound-linked requests. + +**Warning:** a constant `traceparent` (e.g. hardcoded in a load-test +client) re-parents every daemon request into one single trace; generate a +fresh header per request. + ## Aliyun Telemetry ### Manual OTLP Export diff --git a/package-lock.json b/package-lock.json index bd9d2b5c9a..dc7d929ba9 100644 --- a/package-lock.json +++ b/package-lock.json @@ -28696,6 +28696,7 @@ "@iarna/toml": "^2.2.5", "@modelcontextprotocol/sdk": "^1.30.0", "@opentelemetry/api": "^1.9.0", + "@opentelemetry/core": "^2.0.1", "@opentelemetry/exporter-logs-otlp-grpc": "^0.203.0", "@opentelemetry/exporter-logs-otlp-http": "^0.203.0", "@opentelemetry/exporter-metrics-otlp-grpc": "^0.203.0", diff --git a/packages/cli/src/serve/server.ts b/packages/cli/src/serve/server.ts index a462864133..03cf5a2ce4 100644 --- a/packages/cli/src/serve/server.ts +++ b/packages/cli/src/serve/server.ts @@ -181,7 +181,10 @@ import { parseClientIdHeader, safeBody, } from './server/request-helpers.js'; -import { daemonTelemetryMiddleware } from './server/telemetry.js'; +import { + daemonInboundTraceIdCaptureMiddleware, + daemonTelemetryMiddleware, +} from './server/telemetry.js'; import { installAccessLogMiddleware } from './server/access-log.js'; import { setupDeviceFlowRegistry } from './server/device-flow-registry.js'; import { @@ -1722,6 +1725,12 @@ export function createServeApp( installAccessLogMiddleware(app, daemonLog); + // Capture the caller trace id BEFORE authenticate / rate limiter / body + // parser: those layers short-circuit (401/429/400) before the telemetry + // middleware ever runs, and the access log still needs the captured id + // to join their log lines (and 404s) with the caller's trace. + app.use(daemonInboundTraceIdCaptureMiddleware); + // Serve the Web Shell static assets (/ and /assets) BEFORE bearerAuth. The // static shell carries no secrets and a browser cannot attach an // Authorization header to a `