diff --git a/docs/design/telemetry-subagent-spans-design.md b/docs/design/telemetry-subagent-spans-design.md new file mode 100644 index 00000000000..7881f477aa5 --- /dev/null +++ b/docs/design/telemetry-subagent-spans-design.md @@ -0,0 +1,525 @@ +# Subagent Trace Tree Design (P3 Phase 3) + +> Issue #3731 — Phase 3 of hierarchical session tracing. Adds a `qwen-code.subagent` span so subagent invocations get isolated, queryable trace structure instead of interleaving silently under the parent `qwen-code.interaction` span. +> +> Builds on Phase 1 (#4126), Phase 1.5 (#4302), and Phase 2 (#4321). + +## Problem + +Today every `AgentTool.execute` invocation runs under the parent's `qwen-code.interaction` span. Three pathologies: + +1. **Concurrent subagents interleave.** `coreToolScheduler.ts:728` marks `AGENT` as concurrency-safe — `Promise.all` runs up to 10 subagents in parallel. Their LLM-request / tool / hook spans all attach to the single shared parent interaction span, so trace explorers cannot distinguish "this LLM request belongs to subagent A" from "this one belongs to subagent B". +2. **No span for the subagent boundary itself.** There's a `qwen-code.subagent_execution` LogRecord (emitted from `agent-headless.ts:268,329`) bridged to a span of the same name via `LogToSpanProcessor`, but it's a stand-alone marker, not a parent that nests the subagent's LLM / tool / hook spans underneath. +3. **Fork / background subagents float free.** Fire-and-forget paths (`runInForkContext` / background) outlive the parent `AgentTool.execute` and emit spans across multiple subsequent user turns. The parent tool span is already ended by the time those spans appear, so OTel's `context.active()` doesn't help — they attach to whichever interaction happened to be active at firing time, or none at all. + +## Existing surface (no change) + +| Component | Location | Why we don't touch it | +| ---------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | ----------------------------------------------------------- | +| Spawn site (unified) | `packages/core/src/tools/agent/agent.ts:1147` `AgentTool.execute()` | Single entrypoint; ideal hook for 3 invocation flavors | +| Three invocation flavors | foreground-named (`runFramed` at `:2154` — awaited), fork (`void runInForkContext(runFramedFork)` at `:1991` — fire-and-forget), background (`void framedBgBody()` at `:1934` — fire-and-forget) | Lifecycle differs — span design covers all three | +| Concurrency | `coreToolScheduler.runConcurrently` (`Promise.all`, cap 10) — driven by `partitionToolCalls` marking AGENT as `concurrent: true` | The thing that makes isolation necessary | +| `runInForkContext` ALS | `packages/core/src/tools/agent/fork-subagent.ts:32` `forkExecutionStorage` | Recursive-fork guard only — does NOT propagate OTel context | +| Agent identity ALS | `packages/core/src/agents/runtime/agent-context.ts:46` `runWithAgentContext(agentId, ...)` | Already carries `agentId`; we extend it with `depth` | +| `SubagentExecutionEvent` LogRecord | `agent-headless.ts:268,329` → `loggers.ts:773` → 3 downstreams (LogToSpanProcessor span bridge + QwenLogger RUM + `recordSubagentExecutionMetrics`) | LogRecord stays; downstreams depend on it | + +## Out-of-scope (deferred) + +- **Token usage aggregation per subagent** (`gen_ai.usage.*` summed across all LLM spans inside a subagent). Belongs in Phase 4 (LLM request decomposition). +- **Migrating the `qwen-code.subagent_execution` LogRecord onto the new span as span events.** RUM and metrics are tightly coupled to the LogRecord; deferred to a follow-up that can renegotiate all 3 consumers together. +- **Auto-cost rollup.** Same reason — needs token usage first. +- **Removing the AGENT-tool `concurrent: true` marker.** Concurrency is correct; we instrument it, we don't constrain it. + +## References (decision evidence) + +| Source | Key takeaway | +| ---------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| [OTel Trace Spec — Links between spans](https://opentelemetry.io/docs/specs/otel/overview/#links-between-spans) | Verbatim: "The new linked Trace may also represent a long running asynchronous data processing operation that was initiated by one of many fast incoming requests." → fork/background should be linked roots, not children. | +| [OTel GenAI Agent Spans](https://opentelemetry.io/docs/specs/semconv/gen-ai/gen-ai-agent-spans/) (status: Development) | Span name `invoke_agent {gen_ai.agent.name}`; required attrs `gen_ai.operation.name`, `gen_ai.provider.name`; recommended: `gen_ai.agent.id`, `gen_ai.agent.name`, `gen_ai.conversation.id`. | +| LangSmith — 25,000 runs / trace cap | Long agent sessions force trace splitting eventually; favors hybrid traceId design. | +| [Sentry — distributed tracing](https://docs.sentry.io/concepts/key-terms/tracing/distributed-tracing/) | "Child transactions may outlive the transactions containing their parent spans" — child-with-outliving-life is supported. | +| claude-code (Anthropic) | Has subagent hierarchy in local Perfetto JSON file only; OTel export is flat. No portable code. | +| opencode (sst/opencode) | Uses `@effect/opentelemetry` auto-instrumentation; explicit `context.with(trace.setSpan(active, span), fn)` for `withRunSpan`. **Validates the context.with isolation pattern.** Their warning about manual `AsyncLocalStorageContextManager` registration doesn't apply — qwen-code's `NodeSDK` registers it automatically. | + +## Design — six decisions, each justified + +### D1 — Span lifecycle: caller opens, callee runs inside `context.with(span, fn)` + +`agent.ts` (caller) constructs the span. The body — whether awaited (`runFramed`) or fire-and-forget (`runInForkContext` / background) — runs inside `runInSubagentSpanContext(span, fn)`, which calls `otelContext.with(trace.setSpan(active, span), fn)`. + +**Where exactly in `AgentTool.execute` does the span open?** Open it **right BEFORE the invocation-kind-specific setup** (`createAgentHeadless` / `createForkSubagent` etc.) — so setup time (config build, ToolRegistry rebuild, ContextOverride wiring) IS included in `qwen-code.subagent` duration. Operators tracking "why is this subagent slow?" see the full picture. Setup typically << LLM time, so this is noise-free. + +Alternative considered: open after setup, exclude setup time. Rejected because subagent's setup is itself work attributable to the subagent — hiding it makes total-duration math wrong when summing all subagent spans. + +**Why not callee-only**: by the time fork / background body actually runs, the caller has already returned. OTel `context.active()` then returns whatever ambient context the async runtime carries — which for `void` fire-and-forget after the parent ends is unreliable. The parent span has already been closed; reparenting after-the-fact is wrong. + +**Why not caller-only**: foreground works fine that way, but fork / background spans must continue emitting child spans (LLM / tool / hook) after `AgentTool.execute` returns. Those child spans need `context.active()` to return the subagent span — which only happens if the body explicitly runs inside `context.with(subagentSpan, body)`. + +Both ends are needed. **The design is the bridge** — caller creates span + invocationKind-aware traceId strategy, then hands off via `runInSubagentSpanContext`. + +### D2 — Hybrid traceId: foreground = child span, fork/background = new traceId + Link + +| Invocation kind | Parent | TraceId | Why | +| --------------- | --------------------------- | ----------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `foreground` | child of caller's tool span | inherits parent traceId | OTel default; caller fully encloses callee temporally | +| `fork` | linked root span | new traceId | Caller returns immediately; fork runs across multiple subsequent interactions. OTel spec verbatim recommends Link for this. Avoids inflating parent trace's duration / size. | +| `background` | linked root span | new traceId | Same reasoning as fork. | + +**Link payload**: + +```ts +tracer.startSpan( + 'qwen-code.subagent', + { + kind: SpanKind.INTERNAL, + links: [ + { + context: invokerSpanContext, + attributes: { 'qwen-code.link.kind': 'invoker' }, + }, + ], + } /* explicit context = root, not inheriting active */, +); +``` + +Cross-trace queryability via session id: `gen_ai.conversation.id` is set on every subagent span (foreground and linked-root alike), so an ARMS query by `session.id` returns both the parent interaction's trace AND the linked-root subagent traces. The Link itself shows up in the parent trace's UI as "Spawned: subagent X (other trace)" so navigation works. + +**Why not always-child**: 4-hour background subagent inflates the parent trace's wall-clock duration to 4 hours; trace size grows past several backends' caps (LangSmith's 25,000-run limit is the clearest documented bound). Foreground subagents that the user is actually waiting for don't have this problem because they're temporally enclosed. + +**Why not always-linked-root**: foreground breaks the natural trace tree. A user prompt that runs a synchronous Explore subagent SHOULD show one tree, not two linked traces. + +### D3 — TTL: type-aware, subagent fork/background = 4h, others = 30min + +`session-tracing.ts:124` defines `SPAN_TTL_MS = 30 * 60 * 1000`. The sweep at `:144-152` already special-cases `tool.blocked_on_user` to stamp `decision: 'aborted' + source: 'system'`. It's already type-aware in spirit. + +**Change**: introduce per-type TTL: + +```ts +const SPAN_TTL_MS_DEFAULT = 30 * 60 * 1000; // 30min +const SPAN_TTL_MS_LONG = 4 * 60 * 60 * 1000; // 4h + +function ttlFor(ctx: SpanContext): number { + if ( + ctx.type === 'subagent' && + ctx.attributes['qwen-code.subagent.invocation_kind'] !== 'foreground' + ) { + return SPAN_TTL_MS_LONG; + } + return SPAN_TTL_MS_DEFAULT; +} +``` + +On TTL expiry, subagent spans get stamped: + +```ts +{ + 'qwen-code.span.ttl_expired': true, + 'qwen-code.span.duration_ms': age, + 'qwen-code.subagent.status': 'aborted', + 'qwen-code.subagent.terminate_reason': 'ttl_swept', +} +``` + +**Why not 30min flat**: legit long subagents (large repo analysis, slow builds, deep research tasks) get mis-stamped as TTL-expired. 4h covers the 99th percentile without being so loose that real hangs go undetected. + +**Why not no-TTL**: process crash / OOM / kill -9 → span stays in `activeSpans` Map forever. The 30-min safety net protects against this; subagent fork/background just needs a wider window, not removal. + +**Where 4h came from**: pragmatic upper bound for non-trivial agent tasks (long deep-research / large codebase analysis). Configurable via constant if production data shows we're wrong. + +### D4 — LogRecord retention: keep emission, skip the LogToSpanProcessor bridge + +`SubagentExecutionEvent` LogRecord has 3 downstream consumers (verified by repo audit): + +| Consumer | Position | Action | +| ---------------------------------------------------------------------------------- | ------------------------------------------------- | --------------------------------------------------------------------------------------- | +| OTel LogRecord → `LogToSpanProcessor` → bridge span `qwen-code.subagent_execution` | `loggers.ts:773` → `log-to-span-processor.ts:346` | **Skip this bridge** for the subagent event — new `qwen-code.subagent` span replaces it | +| QwenLogger RUM ingestion (Aliyun internal stats) | `qwen-logger.ts:573-574` | Keep — RUM doesn't see OTel spans, only LogRecords | +| `recordSubagentExecutionMetrics` Counter | `metrics.ts:829` | Keep — metric consumer is independent of trace bridge | + +**Bridge skip** (the only change to LogToSpanProcessor): + +```ts +// log-to-span-processor.ts — inside onEmit, after deriveSpanName +const skipBridge = new Set([ + EVENT_SUBAGENT_EXECUTION, // covered by native qwen-code.subagent span +]); +if (skipBridge.has(eventName)) return; +``` + +**Trace consumer impact**: dashboards that filter on span name `qwen-code.subagent_execution` start returning zero results. They should be updated to `qwen-code.subagent`. Note this in release notes. + +**Why not delete the LogRecord**: it's the input to RUM and metrics. Deleting it is a 3-system refactor; out of scope here. + +**Why not keep both**: trace would show two spans per subagent (`qwen-code.subagent` + `qwen-code.subagent_execution`) carrying overlapping info — confusing for operators reading traces, duplicate span volume. + +### D5 — Span name + attrs: hybrid spec compliance, vendor-prefixed for extensions + +**Span name**: `qwen-code.subagent` (matches Phase 1/2 codebase convention: `qwen-code.interaction`, `qwen-code.tool`, `qwen-code.hook`, …). + +OTel GenAI spec says the canonical span name is `invoke_agent {gen_ai.agent.name}` — but **also** says "individual GenAI systems/frameworks MAY specify different span name formats." We use our own name and set `gen_ai.operation.name='invoke_agent'` so spec-aware tooling still identifies the span. Operators reading our trace tree see consistent `qwen-code.*` naming. + +**Span kind**: `INTERNAL` (in-process subagent invocation, per spec). + +**Attribute set**: + +| Category | Attribute | Source | Notes | +| ---------------------------------------------------------------- | ----------------------------------------------- | -------------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| **Required spec** | `gen_ai.operation.name='invoke_agent'` | literal | spec-required | +| **Required spec** | `gen_ai.provider.name='qwen-code'` | literal | spec-required; ambiguous for in-process agents (spec wrote it for LLM provider). Setting to `'qwen-code'` is the most honest interpretation | +| **Required (dual-emit)** | `gen_ai.agent.id` + `qwen-code.subagent.id` | `agentContext.agentId` | dual-emit until spec reaches Stable; remove vendor key later | +| **Required (dual-emit)** | `gen_ai.agent.name` + `qwen-code.subagent.name` | `agentConfig.subagentType` (e.g. `Explore`, `code-reviewer`, `fork`) | same dual-emit | +| **Recommended spec** | `gen_ai.conversation.id` | `config.getSessionId()` | enables cross-trace queries by session; co-exists with the existing `session.id` span attr (set globally per #4367) — both point at the same UUID, drop one when spec stabilises | +| **Recommended spec** | `gen_ai.request.model` | model override if any | only when subagent overrides parent model | +| **Vendor** | `qwen-code.subagent.invocation_kind` | `'foreground'` ❘ `'fork'` ❘ `'background'` | drives TTL + traceId strategy | +| **Vendor** | `qwen-code.subagent.is_built_in` | bool | dashboard filter | +| **Vendor** | `qwen-code.subagent.parent_agent_id` | parent ALS `agentId` | for nested subagents + cross-trace lineage | +| **Vendor** | `qwen-code.subagent.depth` | parent depth + 1 (top = 0) | recursion-bug detector | +| **Vendor** | `qwen-code.subagent.invoking_request_id` | from `agentContext` | request-level correlation | +| **End-of-span spec** | `error.type` (on failure) | error class | OTel standard | +| **End-of-span spec** | `exception.message` (on failure) | `truncateSpanError(error.message)` | OTel standard; reuses Phase 2 truncation | +| **End-of-span vendor** | `qwen-code.subagent.status` | `'completed'` ❘ `'failed'` ❘ `'cancelled'` ❘ `'aborted'` | finer than OTel SpanStatus (which is OK / ERROR / UNSET) | +| **End-of-span vendor** | `qwen-code.subagent.terminate_reason` | from `SubagentExecutionEvent.terminate_reason` | e.g. `task_complete`, `max_iterations`, `user_abort`, `ttl_swept` | +| **End-of-span vendor** | `qwen-code.subagent.result_summary_present` | bool | "did subagent produce output" — bounded | +| **Opt-in (sensitive)** gated on `includeSensitiveSpanAttributes` | `gen_ai.input.messages` | structured chat history | reuses #4097's gate | +| **Opt-in (sensitive)** | `gen_ai.output.messages` | model responses | same gate | +| **Opt-in (sensitive)** | `gen_ai.system_instructions` | system prompt | same gate | +| **Opt-in (sensitive)** | `gen_ai.tool.definitions` | tool schemas | same gate | + +**SpanStatus mapping**: + +- `status === 'completed'` → `SpanStatus { code: OK }` +- `status === 'failed'` → `SpanStatus { code: ERROR, message: truncated(error.message) }` +- `status === 'cancelled'` or `'aborted'` → `SpanStatus { code: UNSET }` (matches Phase 2 convention) + +**Why dual-emit on `id` + `name`**: spec is in Development (one step earlier than Experimental). `OTEL_SEMCONV_STABILITY_OPT_IN=gen_ai_latest_experimental` exists for opt-in. Spec attr names may rename before Stable. Dual-emit is the same pattern Phase 2 used for `call_id` → `tool.call_id`; remove the vendor key when spec reaches Stable. + +**Why `qwen-code.subagent.*` (not `qwen.subagent.*`)**: every existing vendor-prefixed key in `constants.ts` uses `qwen-code.*` (`qwen-code.user_prompt`, `qwen-code.tool_call`, etc.). Internal consistency > OTel naming-convention preference, since operators query ARMS by prefix. + +**Cardinality**: span attrs are not metric labels in OTel; UUID-keyed attrs (`id`, `parent_agent_id`, `invoking_request_id`) are safe at the span layer. Don't promote them to metric labels later. + +**~10-15 attrs per span** (depending on invocation kind, failure, nesting). Same order as `qwen-code.tool`. + +### D6 — `AgentContext.depth` field added directly + +`AgentContext` (`agent-context.ts:32`) is **not exported** — only the helpers (`getCurrentAgentId`, `runWithAgentContext`, `getRuntimeContentGenerator`, `runWithRuntimeContentGenerator`) are. Zero TypeScript-level downstream breakage. The 6 known readers via `getCurrentAgentId()` only read `agentId`; adding `depth?: number` is invisible to them. + +```ts +interface AgentContext { + agentId: string; + subagentName: string; + invokingRequestId: string; + invocationKind: 'spawn' | 'resume'; + isBuiltIn: boolean; + depth?: number; // NEW — default 0 in readers +} +``` + +`runWithAgentContext` already uses `{ ...current, agentId }` spread, so `depth` survives existing call sites unchanged. **Update `runWithAgentContext` to auto-increment depth internally** — no caller needs to know about depth: + +```ts +function runWithAgentContext(agentId: string, fn: () => T): T { + const parent = agentContextStorage.getStore(); + const next: AgentContext = { + ...parent, + agentId, + depth: (parent?.depth ?? -1) + 1, // auto-increment + }; + return agentContextStorage.run(next, fn); +} +``` + +Top-level subagent: no parent ALS → `depth: 0`. Nested: parent depth+1. + +A new tiny accessor `getCurrentAgentDepth(): number` returns `agentContextStorage.getStore()?.depth ?? 0` — used by `startSubagentSpan` to populate `qwen-code.subagent.depth`. + +**Why not a separate ALS just for telemetry**: would duplicate the same context shape we already maintain. Bad. Reuse the existing one. + +## Helper API (`session-tracing.ts`) + +```ts +// constants.ts +export const SPAN_SUBAGENT = 'qwen-code.subagent'; + +// session-tracing.ts +export interface StartSubagentSpanOptions { + agentId: string; + subagentName: string; + invocationKind: 'foreground' | 'fork' | 'background'; + isBuiltIn: boolean; + parentAgentId?: string; + depth: number; + invokingRequestId?: string; + sessionId: string; + modelOverride?: string; + invokerSpanContext?: SpanContext; // required for fork / background (Link source) +} + +export interface SubagentSpanMetadata { + status: 'completed' | 'failed' | 'cancelled' | 'aborted'; + terminateReason?: string; + resultSummaryPresent?: boolean; + error?: string; + errorType?: string; +} + +export function startSubagentSpan(opts: StartSubagentSpanOptions): Span; +export function endSubagentSpan( + span: Span, + metadata: SubagentSpanMetadata, +): void; +export function runInSubagentSpanContext( + span: Span, + fn: () => Promise, +): Promise; +``` + +`runInSubagentSpanContext` is the isolation primitive: + +```ts +export function runInSubagentSpanContext( + span: Span, + fn: () => Promise, +): Promise { + const ctx = trace.setSpan(otelContext.active(), span); + return otelContext.with(ctx, fn); +} +``` + +`startSubagentSpan` internally branches on `invocationKind`: + +```ts +function startSubagentSpan(opts: StartSubagentSpanOptions): Span { + const attributes = buildSpanAttributes(opts); + const tracer = getTracer(); + + if (opts.invocationKind === 'foreground') { + // Child of current active span (caller's tool span) + return tracer.startSpan(SPAN_SUBAGENT, { + kind: SpanKind.INTERNAL, + attributes, + }); + } + + // fork / background: linked root span + return tracer.startSpan(SPAN_SUBAGENT, { + kind: SpanKind.INTERNAL, + attributes, + links: opts.invokerSpanContext + ? [ + { + context: opts.invokerSpanContext, + attributes: { 'qwen-code.link.kind': 'invoker' }, + }, + ] + : undefined, + root: true, // forces new traceId; ignores active context as parent + }); +} +``` + +## Lifecycle wiring + +### Foreground named (the common path) + +```ts +// agent.ts:~2154 +// Pull parent ALS frame to set parentAgentId on the span. The new child's +// depth is computed inside runWithAgentContext automatically (D6) — we +// read it via getCurrentAgentDepth() once we're INSIDE the child ALS +// frame. Two-step: +const parentAgentId = getCurrentAgentId(); // BEFORE entering child frame + +// ... existing runFramed call enters runWithAgentContext(hookOpts.agentId, ...) ... + +// INSIDE runFramed, we can read child's depth: +// const depth = getCurrentAgentDepth(); +// +// Practical placement: thread `depth` as a closure variable, set after +// runWithAgentContext takes effect — OR compute it as +// `(getCurrentAgentDepth() outside) + 1` from the caller side (simpler). +const depth = getCurrentAgentDepth(); // outside frame; child will be this + 1 +// (set qwen-code.subagent.depth = depth in startSubagentSpan args) + +const span = startSubagentSpan({ + agentId, subagentName, invocationKind: 'foreground', + isBuiltIn, parentAgentId, depth, invokingRequestId, sessionId, + modelOverride, + // invokerSpanContext omitted — foreground inherits naturally via context.with +}); +let metadata: SubagentSpanMetadata = { status: 'aborted' }; +try { + await runInSubagentSpanContext(span, () => + runFramed(() => this.runSubagentWithHooks(...)), + ); + metadata = { status: 'completed' /* + resultSummaryPresent */ }; +} catch (error) { + metadata = { + status: signal.aborted ? 'aborted' : 'failed', + error: error instanceof Error ? error.message : String(error), + errorType: error?.constructor?.name, + }; + throw error; +} finally { + endSubagentSpan(span, metadata); +} +``` + +### Fork (fire-and-forget) + +```ts +const invokerSpanContext = trace.getSpan(otelContext.active())?.spanContext(); +const span = startSubagentSpan({ + ..., invocationKind: 'fork', invokerSpanContext, +}); +void runInForkContext(() => + runInSubagentSpanContext(span, async () => { + let metadata: SubagentSpanMetadata = { status: 'aborted' }; + try { + await runFramedFork(); + metadata = { status: 'completed' }; + } catch (error) { + metadata = { + status: signal.aborted ? 'aborted' : 'failed', + error: error instanceof Error ? error.message : String(error), + }; + } finally { + endSubagentSpan(span, metadata); + } + }), +); +// AgentTool.execute returns FORK_PLACEHOLDER_RESULT immediately; +// span lives across subsequent interactions of the parent session. +``` + +### Background + +Same shape as fork, with `invocationKind: 'background'` and `bgEventEmitter` instead of `eventEmitter`. TTL is 4h (same as fork — type rule from D3). + +## Concurrent isolation — the headline guarantee + +Three concurrent subagent invocations from one user prompt (model emits 3 AGENT tool_use blocks → `coreToolScheduler.runConcurrently` runs 3 `executeSingleToolCall` in parallel; each opens its own `qwen-code.tool` span per Phase 2): + +``` +qwen-code.interaction [traceId=T0] +├─ qwen-code.tool [agent call #A] +│ └─ qwen-code.subagent (A, foreground) [traceId=T0, child] +│ ├─ qwen-code.llm_request +│ └─ qwen-code.tool [...] +│ └─ qwen-code.tool.execution +├─ qwen-code.tool [agent call #B] +│ └─ qwen-code.subagent (B, foreground) [traceId=T0, child] +│ └─ qwen-code.llm_request +└─ qwen-code.tool [agent call #C] + └─ qwen-code.subagent (C, fork) [traceId=T1, linked root] + └─ qwen-code.llm_request [traceId=T1] + └─ ... [traceId=T1, may emit hours later] +``` + +`context.with(span, runX)` for each of A, B, C runs concurrently. `AsyncLocalStorageContextManager` (already auto-registered by NodeSDK at `sdk.ts:273`) scopes per fiber; no cross-talk. Each subagent's child LLM / tool / hook spans see `span` via `context.active()` inside their own async chain. + +Fork (C) is a separate trace — its child spans inherit `traceId=T1` even when emitted across multiple subsequent interactions of the parent session. ARMS query by `session.id` returns both T0 and T1; the Link from T1's root → C's invoking `qwen-code.tool` span provides explicit navigation. + +## Files to change + +| File | Change | LOC est | +| ----------------------------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------- | +| `packages/core/src/telemetry/constants.ts` | Add `SPAN_SUBAGENT`, `SPAN_TTL_MS_LONG`, attribute key constants | +8 | +| `packages/core/src/telemetry/session-tracing.ts` | Add `startSubagentSpan` (foreground/linked-root branch), `endSubagentSpan`, `runInSubagentSpanContext`, types; extend `SpanType` union with `'subagent'`; extend TTL sweep with `ttlFor(ctx)` | +120 | +| `packages/core/src/telemetry/log-to-span-processor.ts` | Skip-list to bypass bridging `qwen-code.subagent_execution` | +6 | +| `packages/core/src/telemetry/index.ts` | Re-export new helpers + types | +6 | +| `packages/core/src/agents/runtime/agent-context.ts` | Add `depth?: number` to `AgentContext` + `getCurrentAgentDepth()` accessor | +12 | +| `packages/core/src/tools/agent/agent.ts` | Wrap 3 execution paths (foreground/fork/background) in `runInSubagentSpanContext` with try/catch/finally | +60 | +| `packages/core/src/telemetry/session-tracing.test.ts` | New `describe('subagent spans')`: start/end, child vs linked-root, context propagation, depth, TTL per type, idempotent end, NOOP under SDK-uninitialized | +120 | +| `packages/core/src/telemetry/log-to-span-processor.test.ts` | Assert skip-list short-circuits subagent_execution bridging | +20 | +| `packages/core/src/tools/agent/agent.test.ts` | End-to-end: 3 concurrent subagents each get isolated subtree; fork's spans inherit new traceId via Link; background lifecycle | +80 | + +Total: 9 files, ~430 LOC. Larger than typical Phase 2 commits but justified — TTL change touches a separate file, LogToSpanProcessor skip is a separate file, and the test files double up. Splitting would land an incomplete telemetry surface. + +If review pushes back on size: split into 2 PRs — (A) telemetry helpers + tests, (B) `agent.ts` wiring + e2e tests. Helpers landed first don't change runtime behavior. + +## Testing strategy + +| Test | What it proves | +| ---------------------------------------------------------------------------- | --------------------------------------------------------------- | +| `startSubagentSpan foreground parents to active OTel span` | Child-span path | +| `startSubagentSpan fork creates new traceId + Link to invoker` | Linked-root path | +| `runInSubagentSpanContext propagates span through awaits / Promise.all` | Isolation primitive | +| `3 concurrent subagent spans don't share children` | Headline concurrency guarantee | +| `nested subagent records depth + parentAgentId` | Nesting metadata | +| `endSubagentSpan status mapping (completed / failed / cancelled / aborted)` | Status taxonomy | +| `endSubagentSpan dual-emits gen_ai.agent.id + qwen-code.subagent.id` | Spec-compliance dual-emit | +| `fork lifecycle: span survives AgentTool.execute return` | Fire-and-forget correctness | +| `TTL: subagent fork stays past 30min, gets stamped + ended at 4h` | Type-aware TTL | +| `TTL: foreground subagent at 30min gets default sweep` | TTL doesn't over-extend | +| `LogToSpanProcessor skips qwen-code.subagent_execution but still RUM-emits` | Bridge skip works | +| `runConcurrently of 3 agent tool calls produces 3 distinct subagent spans` | End-to-end at scheduler level | +| `failed subagent sets exception.message + error.type + SpanStatus=ERROR` | OTel-standard error path | +| `opt-in attrs gated on includeSensitiveSpanAttributes` | Reuses #4097's gate correctly | +| `startSubagentSpan returns NOOP_SPAN when SDK is uninitialized` | Matches Phase 1/2 NOOP discipline; downstream calls remain safe | +| `fork span Link.context matches invoker tool span's spanContext` | Cross-trace navigation works end-to-end | +| `runWithAgentContext auto-increments depth: parent=0, child=1, grandchild=2` | Depth bookkeeping is correct without caller cooperation | + +## Edge cases + +| Case | Handling | +| ----------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Subagent inside tool inside subagent (depth > 1) | `depth` attr tracks; recommend soft `debugLogger.warn` at depth ≥ 5 (infinite-recursion detector) | +| Subagent spawned during a parent tool's `awaiting_approval` | Subagent span is a child of the AGENT tool span; the AGENT tool's `tool.blocked_on_user` is a sibling, not parent — both children of the AGENT tool span. Tree stays correct | +| `signal.aborted` mid-subagent | `runInSubagentSpanContext`'s callback throws or resolves; `finally` sets `status='aborted'`, SpanStatus UNSET | +| Fork still alive when parent session ends | 4h TTL fires; sentinel attrs `qwen-code.span.ttl_expired:true`, `qwen-code.subagent.terminate_reason='ttl_swept'`, `status='aborted'` | +| `endSubagentSpan` called twice | Idempotent — checks `activeSpans` map; second call no-ops (matches Phase 2 pattern) | +| Subagent's LLM call uses a different model from parent | `gen_ai.request.model` set on subagent span; LLM-request sub-span ALSO records the model — no conflict | +| Sister subagent prelude throw escapes `attemptExecutionOfScheduledCalls` | Lands in Phase 2's recently-fixed `handleConfirmationResponse` catch which is OUTSIDE the try — not attributed to confirmed tool's span. Subagent span correctly closes via its own try/finally | +| Concurrent fork + foreground from one parent | Foreground inherits T0 traceId, fork gets T1. Both have correct context propagation independently. The parent tool span ends when its synchronous work returns; the fork span (separate trace) lives on | +| Fork span starts in caller sync flow but body runs later | `startSubagentSpan` is called BEFORE `void runInForkContext(...)` so the span (and its Link to the invoker) is captured while the invoker's spanContext is still readable. Span duration therefore includes any microtask-queue scheduling delay before the body actually starts — typically sub-ms; if production shows non-trivial gaps a separate `qwen-code.subagent.scheduling_delay_ms` attribute can be added (open question) | +| SDK not initialized (telemetry disabled) | `startSubagentSpan` early-returns NOOP_SPAN (matches every other Phase 1/2 helper). `runInSubagentSpanContext(NOOP_SPAN, fn)` still calls `fn` normally. `endSubagentSpan(NOOP_SPAN, …)` is a no-op | +| Fork's log-bridge spans (`tool_call`, `api_request`, etc.) use session-derived traceId while fork's native spans use T1 | Pre-existing behavior — log-bridge spans always use `deriveTraceId(sessionId)`, native spans use OTel context. The divergence is invisible inside one trace but means an ARMS-by-traceId lookup on T1 won't include log-bridge children of the fork. Out of scope for this PR; called out as open question #5 | +| Foreground vs background `SubagentStart` hook span parents differ | Foreground fires `fireSubagentStartEvent` inside `runSubagentWithHooks` → already inside `runInSubagentSpanContext`, so the hook span parents under `qwen-code.subagent`. Background fires it BEFORE the `runWithSubagentSpan` wrapping (so the subagent span doesn't yet exist), so its hook span parents under the AGENT `qwen-code.tool`. Operators querying "hook spans under subagent spans" should expect bg `SubagentStart` to be missing from that view. Moving the bg hook fire inside `framedBgBody` is mechanically simple (the `contextState` mutation reaches `bgSubagent.execute` either way), but it changes user-visible semantics: today the hook fires synchronously before `AgentTool.execute` returns the "Background agent launched" message, so any synchronous setup work the hook does happens inside the user-blocking turn; moving it makes the hook fire detached after the launch message returns. Deferred pending a deliberate decision on which semantic is preferred | + +## Rollback + +The change is additive at the OTel level — existing dashboards that don't filter on subagent-related span names keep working. Trace consumers that group by parent span will see new `qwen-code.subagent` nodes between `qwen-code.tool` and `qwen-code.llm_request`; document in release notes. + +Behavior-affecting change is the LogToSpanProcessor skip — dashboards previously consuming `qwen-code.subagent_execution` span return zero. Mitigation: keep the LogRecord intact (RUM + metrics still see it); only the span bridge is removed. Existing log-based queries unaffected. + +Rollback path: revert the single PR. The new span helpers are only invoked from `agent.ts`; dropping the wiring + the LogToSpanProcessor skip restores prior behavior 1:1. + +## Sampling implications + +| Invocation | Sampling decision source | +| ------------------------------------------------ | ------------------------------------------------------------------------ | +| `foreground` (child span, same traceId) | Inherits parent trace's sampled-or-not decision via parent-based sampler | +| `fork` / `background` (linked root, new traceId) | Independent sampling decision at root creation | + +For qwen-code's current default (per `tracer.ts:shouldForceSampled()` — parentbased + always_on else always_on), every span is sampled, so the divergence doesn't bite. For deployments using probabilistic samplers (e.g. `traceidratio=0.1`), this means: + +- A user prompt may be sampled (T0 fully captured) but its fork (T1) may be dropped, or vice versa. +- Operators reading parent T0 see "Link: subagent C (T1)" — clicking through may 404 if T1 was not sampled. + +Mitigation: document for operators. If full subagent capture matters, force sampling for fork/background via a future config knob. Out of scope here. + +## Sensitive attributes (#4097 integration) + +Reuse the existing `includeSensitiveSpanAttributes` gate. When true, set on the subagent span at lifecycle hooks where the data is available: + +| Spec attr | Source | When set | +| ---------------------------- | ---------------------------------------------------------- | ---------------------------------------------------------------------------------------- | +| `gen_ai.system_instructions` | rendered system prompt from `agentConfig` / parent context | `startSubagentSpan` (if available before span open) or via `setAttributes` early in body | +| `gen_ai.tool.definitions` | tool declarations available to the subagent | same as above | +| `gen_ai.input.messages` | initial input passed to subagent (prompt + extraHistory) | at start of body | +| `gen_ai.output.messages` | final response messages returned by subagent | in `endSubagentSpan` metadata | + +These are all already gated; #4097's pattern is to call `addSubagentSensitiveAttributes(span, opts)` helper from inside the body. Implementation detail — design just notes the integration point. + +## Sequencing + +- Independent of #4367 (resource attributes — in review). No merge-order constraint, but `gen_ai.conversation.id` on subagent spans benefits from #4367's `session.id` moved off resource. **Recommend landing #4367 first** so `getSessionId()` source-of-truth is settled. +- Independent of Phase 4 (LLM request decomposition / TTFT). Phase 4 attaches to `qwen-code.llm_request` spans regardless of whether they're under a subagent or an interaction. Recommend Phase 3 before Phase 4 so Phase 4's per-attempt metrics can be aggregated per-subagent. + +## Open questions + +1. **`gen_ai.provider.name`**: spec requires it but writes the description for LLM provider, not agent framework. Setting to `'qwen-code'` is best interpretation; if a future spec revision adds an `agent.provider.name` variant we should switch. +2. **Span name `qwen-code.subagent` vs spec `invoke_agent {name}`**: chose internal consistency. If GenAI-aware tooling adoption grows and `invoke_agent ${name}` becomes critical for auto-discovery, we can switch — span name is the most rebrandable thing in OTel. +3. **Soft-warn at depth ≥ 5**: arbitrary number. Could be a config knob. Defer until production data shows a need. +4. **`SubagentExecutionEvent.result`'s full LLM output is large**: today it bloats LogRecord volume. The migration plan (LogRecord → span events) is deferred but worth doing once token-usage aggregation lands in Phase 4. +5. **Log-bridge spans inside a fork end up on the session-derived traceId, not the fork's T1**: see edge cases. The fix is the broader "interaction span doesn't inherit session root context" issue raised in the sessionId-vs-traceId thread — a separate design that affects all native spans, not just subagent. Out of scope. diff --git a/packages/cli/src/gemini.tsx b/packages/cli/src/gemini.tsx index 55ceb70716e..a8253039f00 100644 --- a/packages/cli/src/gemini.tsx +++ b/packages/cli/src/gemini.tsx @@ -330,13 +330,13 @@ export async function startInteractiveUI( - + diff --git a/packages/cli/src/ui/components/InputPrompt.tsx b/packages/cli/src/ui/components/InputPrompt.tsx index 830a766f18e..55cd754ee00 100644 --- a/packages/cli/src/ui/components/InputPrompt.tsx +++ b/packages/cli/src/ui/components/InputPrompt.tsx @@ -545,7 +545,12 @@ export const InputPrompt: React.FC = ({ setLivePanelFocused(false); return true; } - if (key.sequence && key.sequence.length === 1 && !key.ctrl && !key.meta) { + if ( + key.sequence && + key.sequence.length === 1 && + !key.ctrl && + !key.meta + ) { setLivePanelFocused(false); return false; } diff --git a/packages/cli/src/ui/components/background-view/BackgroundTasksDialog.tsx b/packages/cli/src/ui/components/background-view/BackgroundTasksDialog.tsx index 0805b177307..b240f037d27 100644 --- a/packages/cli/src/ui/components/background-view/BackgroundTasksDialog.tsx +++ b/packages/cli/src/ui/components/background-view/BackgroundTasksDialog.tsx @@ -951,8 +951,7 @@ export const BackgroundTasksDialog: React.FC = ({ const selectedAgentIdForActivity = selectedEntry?.kind === 'agent' ? selectedEntry.agentId : undefined; useEffect(() => { - if (!dialogOpen || !isDetailMode || !selectedAgentIdForActivity) - return; + if (!dialogOpen || !isDetailMode || !selectedAgentIdForActivity) return; const registry = config.getBackgroundTaskRegistry(); const onActivity = (entry: AgentTask) => { if (entry.agentId !== selectedAgentIdForActivity) return; @@ -960,7 +959,13 @@ export const BackgroundTasksDialog: React.FC = ({ }; registry.setActivityChangeCallback(onActivity); return () => registry.setActivityChangeCallback(undefined); - }, [dialogOpen, dialogMode, isDetailMode, config, selectedAgentIdForActivity]); + }, [ + dialogOpen, + dialogMode, + isDetailMode, + config, + selectedAgentIdForActivity, + ]); // Wall-clock tick for the running agent's duration. Activity callbacks // fire when tools run, but duration needs to advance even when the agent @@ -1021,7 +1026,14 @@ export const BackgroundTasksDialog: React.FC = ({ ) { exitDetail(); } - }, [dialogOpen, dialogMode, isDetailMode, selectedEntryId, selectedStatus, exitDetail]); + }, [ + dialogOpen, + dialogMode, + isDetailMode, + selectedEntryId, + selectedStatus, + exitDetail, + ]); // Encapsulates the cancel flow with the foreground confirm-step. // Foreground entries: first `x` arms; second `x` confirms. Background diff --git a/packages/cli/src/ui/contexts/BackgroundTaskViewContext.tsx b/packages/cli/src/ui/contexts/BackgroundTaskViewContext.tsx index e7bba2a825a..43007342eff 100644 --- a/packages/cli/src/ui/contexts/BackgroundTaskViewContext.tsx +++ b/packages/cli/src/ui/contexts/BackgroundTaskViewContext.tsx @@ -29,7 +29,11 @@ const debugLogger = createDebugLogger('BG_TASK_VIEW'); // ─── Types ────────────────────────────────────────────────── -export type BackgroundDialogMode = 'closed' | 'list' | 'detail' | 'detail-from-panel'; +export type BackgroundDialogMode = + | 'closed' + | 'list' + | 'detail' + | 'detail-from-panel'; export interface BackgroundTaskViewState { /** @@ -288,7 +292,15 @@ export function BackgroundTaskViewProvider({ livePanelFocused, livePanelSelectedIndex, }), - [entries, selectedIndex, dialogMode, dialogOpen, pillFocused, livePanelFocused, livePanelSelectedIndex], + [ + entries, + selectedIndex, + dialogMode, + dialogOpen, + pillFocused, + livePanelFocused, + livePanelSelectedIndex, + ], ); const actions: BackgroundTaskViewActions = useMemo( diff --git a/packages/core/src/agents/runtime/agent-context.test.ts b/packages/core/src/agents/runtime/agent-context.test.ts index f1b713f6a73..fabefd9dc84 100644 --- a/packages/core/src/agents/runtime/agent-context.test.ts +++ b/packages/core/src/agents/runtime/agent-context.test.ts @@ -6,6 +6,7 @@ import { describe, expect, it } from 'vitest'; import { + getCurrentAgentDepth, getCurrentAgentId, getRuntimeContentGenerator, runWithAgentContext, @@ -161,3 +162,54 @@ describe('agent-context (merging)', () => { }); }); }); + +describe('agent-context (depth) — #3731 Phase 3', () => { + it('returns 0 outside any frame', () => { + expect(getCurrentAgentDepth()).toBe(0); + }); + + it('top-level subagent has depth 0', async () => { + await runWithAgentContext('top', async () => { + expect(getCurrentAgentDepth()).toBe(0); + }); + }); + + it('auto-increments per nesting: top=0, child=1, grandchild=2', async () => { + await runWithAgentContext('top', async () => { + expect(getCurrentAgentDepth()).toBe(0); + await runWithAgentContext('child', async () => { + expect(getCurrentAgentDepth()).toBe(1); + await runWithAgentContext('grandchild', async () => { + expect(getCurrentAgentDepth()).toBe(2); + }); + expect(getCurrentAgentDepth()).toBe(1); + }); + expect(getCurrentAgentDepth()).toBe(0); + }); + expect(getCurrentAgentDepth()).toBe(0); + }); + + it('sibling subagents at the same nesting level both see the same depth', async () => { + await runWithAgentContext('parent', async () => { + await runWithAgentContext('siblingA', async () => { + expect(getCurrentAgentDepth()).toBe(1); + }); + await runWithAgentContext('siblingB', async () => { + expect(getCurrentAgentDepth()).toBe(1); + }); + }); + }); + + it('callers do not pass depth — it is computed from parent frame only', async () => { + // Defensive: confirm `runWithAgentContext`'s signature still takes + // only (agentId, fn). Phase 3 depth tracking must remain a + // caller-invisible internal concern. + await runWithAgentContext('outer', async () => { + const before = getCurrentAgentDepth(); + // No way to pass depth in — the helper computes it. + await runWithAgentContext('inner', async () => { + expect(getCurrentAgentDepth()).toBe(before + 1); + }); + }); + }); +}); diff --git a/packages/core/src/agents/runtime/agent-context.ts b/packages/core/src/agents/runtime/agent-context.ts index 285e47430ff..ef0636bbaef 100644 --- a/packages/core/src/agents/runtime/agent-context.ts +++ b/packages/core/src/agents/runtime/agent-context.ts @@ -32,6 +32,13 @@ export interface RuntimeContentGeneratorView { interface AgentContext { readonly agentId?: string; readonly runtimeView?: RuntimeContentGeneratorView; + /** + * Nesting depth — 0 for a top-level subagent (called from a user's + * top-level interaction), +1 per nested `runWithAgentContext` frame. + * Auto-incremented; callers do not pass it. Read via + * {@link getCurrentAgentDepth} for telemetry (#3731 Phase 3). + */ + readonly depth?: number; } const storage = new AsyncLocalStorage(); @@ -41,7 +48,11 @@ export function runWithAgentContext( fn: () => Promise, ): Promise { const current = storage.getStore() ?? {}; - return storage.run({ ...current, agentId }, fn); + // Auto-increment depth: top-level = 0, nested = parent+1. No caller has + // to know about it; telemetry reads it back via getCurrentAgentDepth + // (#3731 Phase 3 subagent spans). + const depth = (current.depth ?? -1) + 1; + return storage.run({ ...current, agentId, depth }, fn); } export function runWithRuntimeContentGenerator( @@ -56,6 +67,23 @@ export function getCurrentAgentId(): string | null { return storage.getStore()?.agentId ?? null; } +/** + * Returns the depth of the current agent context frame. 0 means we're + * inside a top-level subagent (or no subagent at all — but in that case + * the caller won't typically need this). Used by telemetry to populate + * `qwen-code.subagent.depth` on subagent spans. + * + * @remarks Returns 0 for two semantically distinct states: (a) no agent + * frame exists, and (b) a top-level frame exists with `depth=0`. Callers + * that need to discriminate MUST first check {@link getCurrentAgentId} — + * it returns `null` only in state (a). See `runWithSubagentSpan` in + * `tools/agent/agent.ts` for the canonical disambiguation pattern. + * Review wenshao @ #4410 (DeepSeek bot 3290820381). + */ +export function getCurrentAgentDepth(): number { + return storage.getStore()?.depth ?? 0; +} + export function getRuntimeContentGenerator(): | RuntimeContentGeneratorView | undefined { diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 8ef41eaef83..36d671f8285 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -68,3 +68,10 @@ export const SPAN_TOOL_EXECUTION = 'qwen-code.tool.execution'; export const SPAN_TOOL_BLOCKED_ON_USER = 'qwen-code.tool.blocked_on_user'; /** Wraps each pre/post-tool-use hook fire site for per-hook latency / decision tracking. */ export const SPAN_HOOK = 'qwen-code.hook'; +/** + * Wraps a single subagent invocation. Parents the LLM/tool/hook spans the + * subagent emits, so concurrent subagents (parallel AGENT tool calls) get + * isolated subtrees instead of interleaving under the parent interaction + * (#3731 Phase 3). + */ +export const SPAN_SUBAGENT = 'qwen-code.subagent'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index 6ad5cb13c34..179a3787c11 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -150,6 +150,9 @@ export { endToolBlockedOnUserSpan, startHookSpan, endHookSpan, + startSubagentSpan, + endSubagentSpan, + runInSubagentSpanContext, getActiveInteractionSpan, truncateSpanError, } from './session-tracing.js'; @@ -163,6 +166,10 @@ export type { HookEvent, StartHookSpanOptions, HookSpanMetadata, + SubagentInvocationKind, + SubagentStatus, + StartSubagentSpanOptions, + SubagentSpanMetadata, } from './session-tracing.js'; export { addUserPromptAttributes, diff --git a/packages/core/src/telemetry/log-to-span-processor.test.ts b/packages/core/src/telemetry/log-to-span-processor.test.ts index 73a98dca6a6..9cab4964408 100644 --- a/packages/core/src/telemetry/log-to-span-processor.test.ts +++ b/packages/core/src/telemetry/log-to-span-processor.test.ts @@ -17,11 +17,16 @@ import type { ReadableLogRecord } from '@opentelemetry/sdk-logs'; import type { SpanExporter } from '@opentelemetry/sdk-trace-base'; let mockCurrentSessionId: string | undefined = undefined; +let mockIsInNativeSubagentSpan = false; vi.mock('./session-context.js', () => ({ getCurrentSessionId: () => mockCurrentSessionId, })); +vi.mock('./session-tracing.js', () => ({ + isInNativeSubagentSpan: () => mockIsInNativeSubagentSpan, +})); + interface ExportedSpan { name: string; kind: number; @@ -752,6 +757,64 @@ describe('LogToSpanProcessor', () => { ); }); + describe('bridge skip-list (#3731 Phase 3)', () => { + it('skips qwen-code.subagent_execution when native subagent span is active', async () => { + mockIsInNativeSubagentSpan = true; + const logRecord = { + body: 'subagent started', + hrTime: [2000, 0] as [number, number], + attributes: { + 'event.name': 'qwen-code.subagent_execution', + subagent_name: 'Explore', + status: 'started', + }, + } as unknown as ReadableLogRecord; + + processor.onEmit(logRecord); + await processor.forceFlush(); + + expect(exportedSpans).toHaveLength(0); + mockIsInNativeSubagentSpan = false; + }); + + it('bridges subagent_execution when no native span is active (e.g. runForkedAgent)', async () => { + mockIsInNativeSubagentSpan = false; + const logRecord = { + body: 'forked agent started', + hrTime: [2500, 0] as [number, number], + attributes: { + 'event.name': 'qwen-code.subagent_execution', + subagent_name: 'dreamAgent', + status: 'started', + }, + } as unknown as ReadableLogRecord; + + processor.onEmit(logRecord); + await processor.forceFlush(); + + expect(exportedSpans).toHaveLength(1); + expect(exportedSpans[0].name).toBe('qwen-code.subagent_execution'); + }); + + it('still bridges other events normally (e.g. qwen-code.tool_call)', async () => { + const logRecord = { + body: 'tool call', + hrTime: [3000, 0] as [number, number], + attributes: { + 'event.name': 'qwen-code.tool_call', + tool_name: 'read_file', + }, + } as unknown as ReadableLogRecord; + + processor.onEmit(logRecord); + await processor.forceFlush(); + + // Sanity check: skip list is narrow — non-listed events still bridge. + expect(exportedSpans).toHaveLength(1); + expect(exportedSpans[0].name).toBe('qwen-code.tool_call'); + }); + }); + describe('export failure diagnostics', () => { function makeFailingProcessor(error: Error | undefined) { const failingExporter = { diff --git a/packages/core/src/telemetry/log-to-span-processor.ts b/packages/core/src/telemetry/log-to-span-processor.ts index 28490ddfcce..5987e99639b 100644 --- a/packages/core/src/telemetry/log-to-span-processor.ts +++ b/packages/core/src/telemetry/log-to-span-processor.ts @@ -22,13 +22,23 @@ import { resourceFromAttributes, } from '@opentelemetry/resources'; -import { SERVICE_NAME } from './constants.js'; +import { EVENT_SUBAGENT_EXECUTION, SERVICE_NAME } from './constants.js'; import { deriveTraceId, randomHexString, randomSpanId, } from './trace-id-utils.js'; import { getCurrentSessionId } from './session-context.js'; +import { isInNativeSubagentSpan } from './session-tracing.js'; + +/** + * LogRecord event names that have native span coverage when emitted + * inside a `runInSubagentSpanContext` body. The bridge is only skipped + * when the ALS confirms a native subagent span is active — paths that + * emit the same event WITHOUT a native span (e.g. `runForkedAgent`) + * still get a bridge span so trace-tree observability is preserved. + */ +const BRIDGE_SKIP_EVENT_NAMES = new Set([EVENT_SUBAGENT_EXECUTION]); const EXPORT_TIMEOUT_MS = 30_000; const DEFAULT_MAX_BUFFER_SIZE = 10_000; @@ -138,6 +148,17 @@ export class LogToSpanProcessor implements LogRecordProcessor { return; } + // Skip bridge only when a native subagent span is active in the ALS. + // Paths without native coverage (e.g. runForkedAgent) still get bridged. + const eventName = logRecord.attributes?.['event.name']; + if ( + typeof eventName === 'string' && + BRIDGE_SKIP_EVENT_NAMES.has(eventName) && + isInNativeSubagentSpan() + ) { + return; + } + const name = deriveSpanName(logRecord); const startTime = logRecord.hrTime; diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index c0119982010..7cadcfa1d08 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -31,6 +31,13 @@ interface MockSpanRecord { statuses: Array<{ code: number; message?: string }>; ended: boolean; parentContext?: unknown; + /** True iff `startSpan` was called with `{ root: true }` (linked-root path). */ + root?: boolean; + /** Span links captured from the `startSpan` opts. */ + links?: Array<{ + context: { spanId: string; traceId: string }; + attributes?: Record; + }>; } const mockSpans: MockSpanRecord[] = []; @@ -43,7 +50,15 @@ vi.mock('@opentelemetry/api', async () => { function createMockSpan( name: string, - opts?: { kind?: number; attributes?: Record }, + opts?: { + kind?: number; + attributes?: Record; + root?: boolean; + links?: Array<{ + context: { spanId: string; traceId: string }; + attributes?: Record; + }>; + }, parentCtx?: unknown, ): MockSpanRecord & { spanContext: () => { spanId: string; traceId: string; traceFlags: number }; @@ -59,6 +74,8 @@ vi.mock('@opentelemetry/api', async () => { statuses: [], ended: false, parentContext: parentCtx, + root: opts?.root, + links: opts?.links, }; mockSpans.push(record); const spanId = Math.random().toString(16).slice(2, 18).padEnd(16, '0'); @@ -136,6 +153,9 @@ import { endToolBlockedOnUserSpan, startHookSpan, endHookSpan, + startSubagentSpan, + endSubagentSpan, + runInSubagentSpanContext, getActiveInteractionSpan, clearSessionTracingForTesting, runTTLSweepForTesting, @@ -1192,6 +1212,32 @@ describe('session-tracing', () => { mockState.throwOnSetAttributes = false; endToolSpan(toolSpan, { success: true }); }); + + it('endSubagentSpan: end() runs and activeSpans is cleared when setAttributes throws', () => { + const span = startSubagentSpan({ + agentId: 'Explore-err', + subagentName: 'Explore', + invocationKind: 'foreground', + isBuiltIn: true, + depth: 0, + sessionId: 'session-uuid', + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + + mockState.throwOnSetAttributes = true; + endSubagentSpan(span, { status: 'completed' }); + + // The attribute write threw, but the span must still be ended so the + // WeakRef registry doesn't leak it. Mirrors the endLLMRequestSpan / + // endToolSpan resilience tests. #4410 review. + expect(record.ended).toBe(true); + + // No leak: spanCtx was removed from activeSpans, so a second call + // short-circuits and records no recovery status. + mockState.throwOnSetAttributes = false; + endSubagentSpan(span, { status: 'completed' }); + expect(record.statuses).toHaveLength(0); + }); }); describe('TTL safety net (#4321 review)', () => { @@ -1304,4 +1350,533 @@ describe('session-tracing', () => { expect(truncated).not.toMatch(/[\uD800-\uDBFF](?![\uDC00-\uDFFF])/); }); }); + + describe('subagent spans (#3731 Phase 3)', () => { + const baseOpts = { + agentId: 'Explore-abc123', + subagentName: 'Explore', + isBuiltIn: true, + depth: 0, + sessionId: 'session-uuid', + } as const; + + it('foreground invocation creates a child span (no root flag, no links)', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent'); + + expect(record).toBeDefined(); + expect(record!.root).toBeUndefined(); + expect(record!.links).toBeUndefined(); + // Dual-emit: spec + vendor keys for id and name. + expect(record!.attributes['gen_ai.agent.id']).toBe('Explore-abc123'); + expect(record!.attributes['gen_ai.agent.name']).toBe('Explore'); + expect(record!.attributes['qwen-code.subagent.id']).toBe( + 'Explore-abc123', + ); + expect(record!.attributes['qwen-code.subagent.name']).toBe('Explore'); + // Required spec attrs. + expect(record!.attributes['gen_ai.operation.name']).toBe('invoke_agent'); + expect(record!.attributes['gen_ai.provider.name']).toBe('qwen-code'); + expect(record!.attributes['gen_ai.conversation.id']).toBe('session-uuid'); + // Vendor concept attrs. + expect(record!.attributes['qwen-code.subagent.invocation_kind']).toBe( + 'foreground', + ); + expect(record!.attributes['qwen-code.subagent.is_built_in']).toBe(true); + expect(record!.attributes['qwen-code.subagent.depth']).toBe(0); + + endSubagentSpan(span, { status: 'completed' }); + }); + + it('fork invocation creates a linked-root span (root: true + Link to invoker)', () => { + const fakeInvokerSpanContext = { + spanId: 'invoker-span-id1', + traceId: 'invoker-trace-id-00000000000000', + traceFlags: 1, + }; + + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'fork', + invokerSpanContext: + fakeInvokerSpanContext as unknown as import('@opentelemetry/api').SpanContext, + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent'); + + expect(record!.root).toBe(true); + expect(record!.links).toBeDefined(); + expect(record!.links).toHaveLength(1); + expect(record!.links![0].context.spanId).toBe('invoker-span-id1'); + expect(record!.links![0].attributes?.['qwen-code.link.kind']).toBe( + 'invoker', + ); + expect(record!.attributes['qwen-code.subagent.invocation_kind']).toBe( + 'fork', + ); + + endSubagentSpan(span, { status: 'completed' }); + }); + + it('background invocation is also linked-root', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'background', + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent'); + expect(record!.root).toBe(true); + // No links because invokerSpanContext was omitted — still root. + expect(record!.attributes['qwen-code.subagent.invocation_kind']).toBe( + 'background', + ); + endSubagentSpan(span, { status: 'completed' }); + }); + + it('captures optional attrs: parentAgentId, invokingRequestId, modelOverride', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + parentAgentId: 'parent-agent-456', + invokingRequestId: 'req-789', + modelOverride: 'qwen-coder-7b', + depth: 2, + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + expect(record.attributes['qwen-code.subagent.parent_agent_id']).toBe( + 'parent-agent-456', + ); + expect(record.attributes['qwen-code.subagent.invoking_request_id']).toBe( + 'req-789', + ); + expect(record.attributes['gen_ai.request.model']).toBe('qwen-coder-7b'); + expect(record.attributes['qwen-code.subagent.depth']).toBe(2); + endSubagentSpan(span, { status: 'completed' }); + }); + + it('endSubagentSpan: completed → SpanStatus OK + duration recorded', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + endSubagentSpan(span, { status: 'completed' }); + + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + expect(record.ended).toBe(true); + expect(record.statuses).toContainEqual({ code: SpanStatusCode.OK }); + expect(record.attributes['qwen-code.subagent.status']).toBe('completed'); + expect( + record.attributes['qwen-code.subagent.duration_ms'] as number, + ).toBeGreaterThanOrEqual(0); + }); + + it('endSubagentSpan: failed → SpanStatus ERROR + exception.message + error.type', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + endSubagentSpan(span, { + status: 'failed', + error: 'something broke', + errorType: 'TypeError', + }); + + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + expect(record.statuses[0].code).toBe(SpanStatusCode.ERROR); + expect(record.statuses[0].message).toBe('something broke'); + expect(record.attributes['exception.message']).toBe('something broke'); + expect(record.attributes['error.type']).toBe('TypeError'); + expect(record.attributes['qwen-code.subagent.status']).toBe('failed'); + }); + + it('endSubagentSpan: failed without explicit error → generic "subagent failed" SpanStatus message', () => { + // Coverage for the fallback in endSubagentSpan's ERROR branch: + // `metadata.error ? truncateSpanError(metadata.error) : 'subagent failed'`. + // Every prior failure test passes an explicit error; this verifies + // the generic fallback so a regression that drops it would be + // caught. wenshao @ #4410 DeepSeek 3293036600. + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + endSubagentSpan(span, { status: 'failed' }); + + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + expect(record.statuses[0].code).toBe(SpanStatusCode.ERROR); + expect(record.statuses[0].message).toBe('subagent failed'); + expect(record.attributes['exception.message']).toBeUndefined(); + expect(record.attributes['error.type']).toBeUndefined(); + }); + + it.each(['cancelled', 'aborted'] as const)( + 'endSubagentSpan: %s → SpanStatus UNSET (Phase 2 cancellation convention)', + (status) => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + endSubagentSpan(span, { status }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + // No SpanStatus calls means UNSET stays UNSET. + expect(record.statuses).toHaveLength(0); + expect(record.attributes['qwen-code.subagent.status']).toBe(status); + }, + ); + + it('endSubagentSpan is idempotent (second call is a no-op)', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + endSubagentSpan(span, { status: 'completed' }); + endSubagentSpan(span, { status: 'failed', error: 'should not record' }); + + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + // Only the first end ran — status is still OK, not ERROR. + expect(record.statuses).toEqual([{ code: SpanStatusCode.OK }]); + expect(record.attributes['qwen-code.subagent.status']).toBe('completed'); + }); + + it('runInSubagentSpanContext wraps fn in context.with', async () => { + // Our mocked context.with just runs fn (line 119). The behavioral + // assertion is "fn was called and its result returned"; the parent- + // context behavior is covered by the integration test in + // agent.test.ts where real OTel context propagation matters. + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const result = await runInSubagentSpanContext(span, async () => 42); + expect(result).toBe(42); + endSubagentSpan(span, { status: 'completed' }); + }); + + it('returns NOOP_SPAN when SDK is uninitialized', () => { + mockState.sdkInitialized = false; + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + // NOOP_SPAN has all-zero traceId/spanId per OTel convention. + expect(span.spanContext().traceId).toBe('0'.repeat(32)); + // No mockSpans entry was created (NOOP returns before tracer.startSpan). + expect( + mockSpans.find((s) => s.name === 'qwen-code.subagent'), + ).toBeUndefined(); + // endSubagentSpan on NOOP_SPAN is a safe no-op. + endSubagentSpan(span, { status: 'completed' }); + }); + + it('error message is truncated via truncateSpanError', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const oversized = 'a'.repeat(2000); + endSubagentSpan(span, { status: 'failed', error: oversized }); + + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + const recorded = record.attributes['exception.message'] as string; + expect(recorded.length).toBeLessThan(oversized.length); + expect(recorded.endsWith('…[truncated]')).toBe(true); + }); + + it('TTL: fork subagent at 30 min stays alive (4h window)', () => { + startSubagentSpan({ ...baseOpts, invocationKind: 'fork' }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + + // 31 min — past default TTL, well within fork's 4h. + runTTLSweepForTesting(Date.now() + 31 * 60 * 1000); + expect(record.ended).toBe(false); + + // 4h + 1 min — past fork's 4h TTL. + runTTLSweepForTesting(Date.now() + (4 * 60 + 1) * 60 * 1000); + expect(record.ended).toBe(true); + expect(record.attributes['qwen-code.span.ttl_expired']).toBe(true); + expect(record.attributes['qwen-code.subagent.status']).toBe('aborted'); + expect(record.attributes['qwen-code.subagent.terminate_reason']).toBe( + 'ttl_swept', + ); + // TTL sweep stamps the subagent-namespaced duration_ms key so + // dashboards querying that namespace include swept spans (the + // generic qwen-code.span.duration_ms is asserted above). + // wenshao @ #4410 DeepSeek 3292560017. + expect( + record.attributes['qwen-code.subagent.duration_ms'] as number, + ).toBeGreaterThan(0); + }); + + it('TTL: background subagent at 30 min stays alive (4h window)', () => { + // Mirror of the fork test — wenshao @ #4410 DeepSeek 3291876056. + // Catches the regression where someone trims + // LONG_TTL_SUBAGENT_KINDS and drops `'background'` silently. + startSubagentSpan({ ...baseOpts, invocationKind: 'background' }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + + runTTLSweepForTesting(Date.now() + 31 * 60 * 1000); + expect(record.ended).toBe(false); + + runTTLSweepForTesting(Date.now() + (4 * 60 + 1) * 60 * 1000); + expect(record.ended).toBe(true); + expect(record.attributes['qwen-code.subagent.status']).toBe('aborted'); + expect(record.attributes['qwen-code.subagent.terminate_reason']).toBe( + 'ttl_swept', + ); + }); + + it('TTL: foreground subagent at 31 min IS swept (default 30 min TTL)', () => { + const span = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const record = mockSpans.find((s) => s.name === 'qwen-code.subagent')!; + + runTTLSweepForTesting(Date.now() + 31 * 60 * 1000); + expect(record.ended).toBe(true); + expect(record.attributes['qwen-code.span.ttl_expired']).toBe(true); + + // Defensive: endSubagentSpan after TTL is a no-op (already ended). + endSubagentSpan(span, { status: 'completed' }); + }); + + describe('child span parenting (#4410 DeepSeek 3290820352)', () => { + // Regression: foreground subagent's child LLM/tool/hook spans were + // parenting to the OUTER interaction span instead of the subagent + // span because `resolveParentContext` always prefers + // `interactionContext.getStore()` over the active OTel span. The + // fix introduces `subagentContext` ALS, which child startXSpan + // calls now check before falling back to interactionContext. + it('startLLMRequestSpan inside runInSubagentSpanContext parents under the subagent span', async () => { + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + const subagentSpan = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const subagentRecord = mockSpans.find( + (s) => s.name === 'qwen-code.subagent', + )!; + + await runInSubagentSpanContext(subagentSpan, async () => { + startLLMRequestSpan('qwen3-coder-plus', 'prompt-1'); + }); + + const llmRecord = mockSpans.find( + (s) => s.name === 'qwen-code.llm_request', + ); + expect(llmRecord).toBeDefined(); + // mock trace.setSpan stamps __parentSpan onto the context object. + const parentSpan = ( + llmRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + expect(parentSpan).toBeDefined(); + // The LLM span MUST parent to the subagent span, NOT the + // interaction span. + expect(parentSpan).toBe(subagentRecord); + // Regression guard for the `llm_request.context` tri-state: + // subagent-parented LLM calls MUST stamp 'subagent' (not + // 'interaction') so dashboards classify them correctly. + // wenshao @ #4410 DeepSeek 3293036596. + expect(llmRecord!.attributes['llm_request.context']).toBe('subagent'); + endSubagentSpan(subagentSpan, { status: 'completed' }); + endInteractionSpan('ok'); + }); + + it('startToolSpan inside runInSubagentSpanContext parents under the subagent span', async () => { + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + const subagentSpan = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const subagentRecord = mockSpans.find( + (s) => s.name === 'qwen-code.subagent', + )!; + + await runInSubagentSpanContext(subagentSpan, async () => { + startToolSpan('read_file'); + }); + + const toolRecord = mockSpans.find((s) => s.name === 'qwen-code.tool'); + expect(toolRecord).toBeDefined(); + const parentSpan = ( + toolRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + expect(parentSpan).toBe(subagentRecord); + endSubagentSpan(subagentSpan, { status: 'completed' }); + endInteractionSpan('ok'); + }); + + it('startHookSpan inside runInSubagentSpanContext (no inner tool) parents under the subagent span', async () => { + // Regression: startHookSpan reads tool > subagent > interaction. + // The AGENT tool's own toolContext was leaking into the subagent + // body and mis-parenting SubagentStart/Stop hooks. Fix at + // runInSubagentSpanContext clears toolContext for the body's + // duration. wenshao @ #4410 DeepSeek 3291876051 / 3291876055. + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + const subagentSpan = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + const subagentRecord = mockSpans.find( + (s) => s.name === 'qwen-code.subagent', + )!; + + await runInSubagentSpanContext(subagentSpan, async () => { + startHookSpan({ + hookEvent: 'PreToolUse', + toolName: 'read_file', + }); + }); + + const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook'); + expect(hookRecord).toBeDefined(); + const parentSpan = ( + hookRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + expect(parentSpan).toBe(subagentRecord); + endSubagentSpan(subagentSpan, { status: 'completed' }); + endInteractionSpan('ok'); + }); + + it('startHookSpan OUTSIDE runInSubagentSpanContext but inside a tool context parents under the tool span (documented bg SubagentStart asymmetry)', async () => { + // Regression guard for the documented bg-vs-fg SubagentStart + // parenting asymmetry (see design doc Edge Cases table). The + // background path fires SubagentStart BEFORE wrapping in + // runInSubagentSpanContext, so it sees the outer AGENT tool's + // toolContext and parents to the tool span — not the subagent. + // If a future refactor changes this (or implements the deferred + // fix), this test trips. wenshao @ #4410 DeepSeek 3293174101. + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + // Simulate the outer AGENT tool context active. + const agentToolSpan = startToolSpan('agent'); + const agentToolRecord = mockSpans.find( + (s) => s.name === 'qwen-code.tool', + )!; + // Open a subagent span as if a bg invocation will eventually + // wrap its body. Note we do NOT call runInSubagentSpanContext — + // mirroring the bg path where SubagentStart fires BEFORE the + // wrapper. + const subagentSpan = startSubagentSpan({ + ...baseOpts, + invocationKind: 'background', + }); + + await runInToolSpanContext(agentToolSpan, async () => { + // Hook fires here, inside the AGENT tool's toolContext but + // OUTSIDE runInSubagentSpanContext. + startHookSpan({ + hookEvent: 'PreToolUse', + toolName: 'subagent', + }); + }); + + const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook'); + expect(hookRecord).toBeDefined(); + const parentSpan = ( + hookRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + // Locks in the asymmetry: parent is the AGENT tool, NOT the + // subagent span (even though the subagent span exists in + // activeSpans). Documented in design doc Edge Cases. + expect(parentSpan).toBe(agentToolRecord); + endSubagentSpan(subagentSpan, { status: 'completed' }); + endToolSpan(agentToolSpan); + endInteractionSpan('ok'); + }); + + it('nested subagent: innermost subagent shadows outer for child parenting', async () => { + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + const outerSubagent = startSubagentSpan({ + ...baseOpts, + agentId: 'outer', + subagentName: 'outer-agent', + invocationKind: 'foreground', + }); + const innerSubagent = startSubagentSpan({ + ...baseOpts, + agentId: 'inner', + subagentName: 'inner-agent', + invocationKind: 'foreground', + }); + const innerRecord = mockSpans.find( + (s) => + s.name === 'qwen-code.subagent' && + s.attributes['qwen-code.subagent.id'] === 'inner', + )!; + + await runInSubagentSpanContext(outerSubagent, async () => { + await runInSubagentSpanContext(innerSubagent, async () => { + startLLMRequestSpan('qwen3-coder-plus', 'prompt-1'); + }); + }); + + const llmRecord = mockSpans.find( + (s) => s.name === 'qwen-code.llm_request', + ); + const parentSpan = ( + llmRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + expect(parentSpan).toBe(innerRecord); + endSubagentSpan(innerSubagent, { status: 'completed' }); + endSubagentSpan(outerSubagent, { status: 'completed' }); + endInteractionSpan('ok'); + }); + + it('after runInSubagentSpanContext exits, child spans go back to interactionContext', async () => { + const config = createMockConfig(); + startInteractionSpan(config, { + messageType: 'userQuery', + promptId: 'prompt-1', + model: 'test-model', + }); + const interactionRecord = mockSpans.find( + (s) => s.name === 'qwen-code.interaction', + )!; + const subagentSpan = startSubagentSpan({ + ...baseOpts, + invocationKind: 'foreground', + }); + + await runInSubagentSpanContext(subagentSpan, async () => {}); + // Now outside the subagent ALS frame. + startLLMRequestSpan('qwen3-coder-plus', 'prompt-1'); + + const llmRecord = mockSpans.find( + (s) => s.name === 'qwen-code.llm_request', + ); + const parentSpan = ( + llmRecord!.parentContext as { __parentSpan?: unknown } | undefined + )?.__parentSpan; + // Parented under interaction span, NOT subagent (ALS frame exited). + expect(parentSpan).toBe(interactionRecord); + endSubagentSpan(subagentSpan, { status: 'completed' }); + endInteractionSpan('ok'); + }); + }); + }); }); diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index 118192bea91..6f2190d5575 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -20,6 +20,7 @@ import { SPAN_HOOK, SPAN_INTERACTION, SPAN_LLM_REQUEST, + SPAN_SUBAGENT, SPAN_TOOL, SPAN_TOOL_BLOCKED_ON_USER, SPAN_TOOL_EXECUTION, @@ -103,11 +104,12 @@ interface SpanContext { | 'llm_request' | 'tool' | 'tool.execution' - // Phase 2 forward-declarations (no start*/end* helpers wired yet — - // see docs/design/workflow-tracing-gaps.md). Listed here so Phase 2 - // can add helpers without touching this type. | 'tool.blocked_on_user' - | 'hook'; + | 'hook' + // Phase 3: single subagent invocation. Hosts the LLM/tool/hook subtree + // emitted by the subagent so concurrent subagents don't interleave + // (#3731 Phase 3; see docs/design/telemetry-subagent-spans-design.md). + | 'subagent'; } /** @@ -151,6 +153,22 @@ const NOOP_SPAN = trace.wrapSpanContext({ const interactionContext = new AsyncLocalStorage(); const toolContext = new AsyncLocalStorage(); +/** + * ALS for the active `qwen-code.subagent` span. Child LLM/tool/hook spans + * created inside a subagent body read this BEFORE interactionContext so + * they parent under the subagent (not the outer interaction). Without + * this, foreground subagent spans are empty shells: `resolveParentContext` + * picks `interactionContext.getStore()` whenever it is non-null — which is + * always true during foreground execution — and re-parents every child + * span back to the interaction, bypassing the subagent span entirely. + * Review wenshao @ #4410. + */ +const subagentContext = new AsyncLocalStorage(); + +export function isInNativeSubagentSpan(): boolean { + const ctx = subagentContext.getStore(); + return ctx !== undefined && !ctx.ended; +} const activeSpans = new Map>(); const strongSpans = new Map(); @@ -158,70 +176,126 @@ const strongSpans = new Map(); let interactionSequence = 0; let lastInteractionCtx: SpanContext | undefined; let cleanupIntervalStarted = false; -const SPAN_TTL_MS = 30 * 60 * 1000; +const SPAN_TTL_MS_DEFAULT = 30 * 60 * 1000; // 30 min — user walk-away +const SPAN_TTL_MS_LONG = 4 * 60 * 60 * 1000; // 4 h — long fire-and-forget subagent + +/** + * Invocation kinds that legitimately run for hours and need the long TTL. + * New kinds added to `SubagentInvocationKind` silently fall through to + * the 30-min default (Set.has() returns false) — widen this Set only + * after confirming the new kind legitimately needs 4h+ TTL. + */ +const LONG_TTL_SUBAGENT_KINDS = new Set([ + 'fork', + 'background', +]); + +/** + * TTL per span type. Default is 30 min — picked for `tool.blocked_on_user` + * (user think-time). Subagent fork/background invocations can legitimately + * run hours (large analysis, slow builds, deep research), so they need a + * wider safety-net window (#3731 Phase 3). Foreground subagents stay at + * the default TTL — those are bound to the user-facing request and should + * never legitimately exceed the default window. + * + * KNOWN LIMITATION (deferred): only the subagent span itself gets the long + * TTL. Child LLM/tool/hook spans emitted inside a 2-hour background agent + * still use the 30-min default, so the trace can show a gap (early child + * spans swept at 30 min, later child spans present). Fixing this needs + * either ALS propagation of the "long TTL bucket" into resolveParentContext + * or a TTL-inheritance walk at sweep time — both warrant a follow-up PR. + * See wenshao @ #4410 review. + */ +function ttlFor(ctx: SpanContext): number { + if (ctx.type === 'subagent') { + const kind = ctx.attributes['qwen-code.subagent.invocation_kind']; + if ( + typeof kind === 'string' && + LONG_TTL_SUBAGENT_KINDS.has(kind as SubagentInvocationKind) + ) { + return SPAN_TTL_MS_LONG; + } + } + return SPAN_TTL_MS_DEFAULT; +} function sweepStaleSpans(now: number): void { - const cutoff = now - SPAN_TTL_MS; for (const [spanId, weakRef] of activeSpans) { const ctx = weakRef.deref(); if (ctx === undefined) { activeSpans.delete(spanId); strongSpans.delete(spanId); - } else if (ctx.startTime < cutoff) { - if (!ctx.ended) { - ctx.ended = true; - // Mark the span so backends can distinguish "abandoned and - // garbage-collected by the TTL safety net" from "deliberately - // ended without setting status / attrs" (#4321 review). - const ageMs = now - ctx.startTime; - const toolName = ctx.attributes['tool.name']; - const callId = ctx.attributes['tool.call_id']; - // setAttributes and span.end() are wrapped separately so a - // setAttributes throw can't prevent the span from being ended - // (#4321 review-3 wenshao Suggestion). For blocked_on_user - // spans, also stamp the canonical decision/source taxonomy so - // dashboards filtering by `decision: 'aborted'` count - // walk-aways consistently with explicit user aborts. - try { - ctx.span.setAttributes({ - 'qwen-code.span.ttl_expired': true, - 'qwen-code.span.duration_ms': ageMs, - ...(ctx.type === 'tool.blocked_on_user' - ? { - decision: 'aborted', - source: 'system', - } - : {}), - }); - } catch (error) { - // OTel errors must not prevent span.end() from running, but - // they're worth surfacing — dropping the sentinel attrs makes - // a TTL-aborted span look identical to a deliberately-UNSET - // one in dashboards (#4321 review-7 silent-failure-hunter). - debugLogger.warn( - `Failed to stamp TTL attrs on stale span ${spanId}: ${error instanceof Error ? error.message : String(error)}`, - ); - } - // Include tool name + call_id so the log is actionable in - // production without a trace-backend lookup (review-3). - const ctxLabel = - toolName && callId - ? `${ctx.type} (tool.name=${toolName}, tool.call_id=${callId})` - : ctx.type; + continue; + } + if (now - ctx.startTime < ttlFor(ctx)) continue; + + if (!ctx.ended) { + ctx.ended = true; + // Mark the span so backends can distinguish "abandoned and + // garbage-collected by the TTL safety net" from "deliberately + // ended without setting status / attrs" (#4321 review). + const ageMs = now - ctx.startTime; + const toolName = ctx.attributes['tool.name']; + const callId = ctx.attributes['tool.call_id']; + // setAttributes and span.end() are wrapped separately so a + // setAttributes throw can't prevent the span from being ended + // (#4321 review-3 wenshao Suggestion). Type-specific stamps: + // - blocked_on_user: canonical decision/source so dashboards + // counting `decision: 'aborted'` cover walk-aways. + // - subagent: status='aborted' + terminate_reason='ttl_swept' + // so subagent dashboards see ttl-victims as distinct from + // user-cancelled / failed (#3731 Phase 3). + try { + ctx.span.setAttributes({ + 'qwen-code.span.ttl_expired': true, + 'qwen-code.span.duration_ms': ageMs, + ...(ctx.type === 'tool.blocked_on_user' + ? { + decision: 'aborted', + source: 'system', + } + : {}), + ...(ctx.type === 'subagent' + ? { + 'qwen-code.subagent.status': 'aborted', + 'qwen-code.subagent.terminate_reason': 'ttl_swept', + // Mirror the subagent-specific duration_ms key that + // endSubagentSpan stamps so dashboards querying that + // namespace see TTL-swept spans too (they currently + // only get the generic qwen-code.span.duration_ms + // above). wenshao @ #4410. + 'qwen-code.subagent.duration_ms': ageMs, + } + : {}), + }); + } catch (error) { + // OTel errors must not prevent span.end() from running, but + // they're worth surfacing — dropping the sentinel attrs makes + // a TTL-aborted span look identical to a deliberately-UNSET + // one in dashboards (#4321 review-7 silent-failure-hunter). debugLogger.warn( - `Stale ${ctxLabel} span ended by TTL safety net (age=${ageMs}ms, spanId=${spanId})`, + `Failed to stamp TTL attrs on stale span ${spanId}: ${error instanceof Error ? error.message : String(error)}`, + ); + } + // Include tool name + call_id so the log is actionable in + // production without a trace-backend lookup (review-3). + const ctxLabel = + toolName && callId + ? `${ctx.type} (tool.name=${toolName}, tool.call_id=${callId})` + : ctx.type; + debugLogger.warn( + `Stale ${ctxLabel} span ended by TTL safety net (age=${ageMs}ms, spanId=${spanId})`, + ); + try { + ctx.span.end(); + } catch (error) { + debugLogger.warn( + `Failed to end stale span ${spanId}: ${error instanceof Error ? error.message : String(error)}`, ); - try { - ctx.span.end(); - } catch (error) { - debugLogger.warn( - `Failed to end stale span ${spanId}: ${error instanceof Error ? error.message : String(error)}`, - ); - } } - activeSpans.delete(spanId); - strongSpans.delete(spanId); } + activeSpans.delete(spanId); + strongSpans.delete(spanId); } } @@ -318,7 +392,13 @@ export function endInteractionSpan( metadata?: EndInteractionOptions, ): void { const spanCtx = interactionContext.getStore() ?? lastInteractionCtx; - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endInteractionSpan: span ${getSpanId(spanCtx.span)} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; lastInteractionCtx = undefined; @@ -352,16 +432,25 @@ export function startLLMRequestSpan(model: string, promptId: string): Span { return NOOP_SPAN; } - const parentCtx = interactionContext.getStore(); + // Prefer subagentContext over interactionContext so LLM spans inside a + // foreground subagent nest under the subagent span instead of escaping + // back to the outer interaction. wenshao @ #4410. + const parentCtx = subagentContext.getStore() ?? interactionContext.getStore(); // resolveParentContext() also re-parents to the active OTel span when // present, so a side-query LLM call nested inside a tool span still // attaches to the tool span instead of skipping back to the session root. const ctx = resolveParentContext(parentCtx); + // Tri-state so subagent-parented LLM calls don't get mis-classified as + // "interaction" in dashboards. wenshao @ #4410. const attributes: Attributes = { 'qwen-code.model': model, 'qwen-code.prompt_id': promptId, - 'llm_request.context': parentCtx ? 'interaction' : 'standalone', + 'llm_request.context': subagentContext.getStore() + ? 'subagent' + : interactionContext.getStore() + ? 'interaction' + : 'standalone', // Dual-emit OTel GenAI semantic convention (Stable). Private name // (qwen-code.model) remains authoritative; gen_ai.* is a compat layer // for spec-aware backends. See docs/design/telemetry-llm-request-timing-design.md (D8). @@ -393,7 +482,13 @@ export function endLLMRequestSpan( ): void { const spanId = getSpanId(span); const spanCtx = activeSpans.get(spanId)?.deref(); - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endLLMRequestSpan: span ${spanId} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; @@ -501,7 +596,9 @@ export function startToolSpan( return NOOP_SPAN; } - const parentCtx = interactionContext.getStore(); + // Prefer subagentContext over interactionContext (see startLLMRequestSpan + // for rationale; wenshao @ #4410). + const parentCtx = subagentContext.getStore() ?? interactionContext.getStore(); // Same fallback as startLLMRequestSpan: prefer active OTel span for // tools-inside-tools cases before falling back to the session root. const ctx = resolveParentContext(parentCtx); @@ -556,7 +653,13 @@ export function runInToolSpanContext(span: Span, fn: () => T): T { export function endToolSpan(span: Span, metadata?: ToolSpanMetadata): void { const spanId = getSpanId(span); const spanCtx = activeSpans.get(spanId)?.deref(); - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endToolSpan: span ${spanId} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; @@ -656,7 +759,13 @@ export function endToolExecutionSpan( ): void { const spanId = getSpanId(span); const spanCtx = activeSpans.get(spanId)?.deref(); - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endToolExecutionSpan: span ${spanId} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; @@ -790,7 +899,13 @@ export function endToolBlockedOnUserSpan( ): void { const spanId = getSpanId(span); const spanCtx = activeSpans.get(spanId)?.deref(); - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endToolBlockedOnUserSpan: span ${spanId} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; @@ -855,9 +970,14 @@ export function startHookSpan(opts: StartHookSpanOptions): Span { // Hooks fire from inside `runInToolSpanContext` so toolContext is the // natural parent. resolveParentContext also covers the rare case where a // hook span is started outside any tool (defensive — keeps the trace tree - // correlated with the session). + // correlated with the session). subagentContext sits between tool and + // interaction so hooks fired inside a subagent but outside any tool + // still nest under the subagent. wenshao @ #4410. const parentCtx = - toolContext.getStore() ?? interactionContext.getStore() ?? undefined; + toolContext.getStore() ?? + subagentContext.getStore() ?? + interactionContext.getStore() ?? + undefined; const ctx = resolveParentContext(parentCtx); const attributes: Attributes = { @@ -896,7 +1016,13 @@ export function startHookSpan(opts: StartHookSpanOptions): Span { export function endHookSpan(span: Span, metadata?: HookSpanMetadata): void { const spanId = getSpanId(span); const spanCtx = activeSpans.get(spanId)?.deref(); - if (!spanCtx || spanCtx.ended) return; + if (!spanCtx) return; + if (spanCtx.ended) { + debugLogger.debug( + `endHookSpan: span ${spanId} already ended (possible TTL sweep race)`, + ); + return; + } spanCtx.ended = true; @@ -943,6 +1069,292 @@ export function endHookSpan(span: Span, metadata?: HookSpanMetadata): void { strongSpans.delete(spanId); } +// --- Subagent Spans (#3731 Phase 3) --- + +export type SubagentInvocationKind = 'foreground' | 'fork' | 'background'; + +export type SubagentStatus = 'completed' | 'failed' | 'cancelled' | 'aborted'; + +export interface StartSubagentSpanOptions { + /** Unique identifier for this subagent invocation (e.g. `Explore-abc123`). */ + agentId: string; + /** Human-readable subagent type (e.g. `Explore`, `code-reviewer`, `fork`). */ + subagentName: string; + invocationKind: SubagentInvocationKind; + isBuiltIn: boolean; + /** Parent agent's id, when this subagent is nested inside another. */ + parentAgentId?: string; + /** 0 for top-level subagent, +1 per nesting. */ + depth: number; + /** Parent's request id (for cross-trace correlation with parent prompt). */ + invokingRequestId?: string; + /** Session id — set as both `gen_ai.conversation.id` and vendor key. */ + sessionId: string; + /** Model override, if this subagent runs on a different model than parent. */ + modelOverride?: string; + /** + * For `fork` / `background` invocations: span context of the invoking + * span (the parent AGENT tool span). Used as the `Link` source so the + * new-traceId root can be navigated back to the invoker. Ignored for + * `foreground` (inherits via context.active()). + */ + invokerSpanContext?: import('@opentelemetry/api').SpanContext; +} + +export interface SubagentSpanMetadata { + status: SubagentStatus; + /** Free-form reason (e.g. `task_complete`, `max_iterations`, `user_abort`, `ttl_swept`). */ + terminateReason?: string; + /** Whether the subagent produced any result text. Bounded boolean (no payload). */ + resultSummaryPresent?: boolean; + /** Truncated via {@link truncateSpanError} before write. */ + error?: string; + /** Error class name (e.g. `Error`, `AbortError`). */ + errorType?: string; +} + +/** + * Open a subagent span. + * + * - `foreground` invocations become children of the currently-active span + * (typically the AGENT tool span), inheriting its traceId. + * - `fork` / `background` invocations become linked-root spans — new traceId, + * with an OTel {@link Link} pointing at `invokerSpanContext`. The OTel + * spec explicitly recommends Link for "long running asynchronous data + * processing operation that was initiated by [a] fast incoming request" + * (`https://opentelemetry.io/docs/specs/otel/overview/#links-between-spans`). + * Fire-and-forget subagents run for minutes-to-hours and would otherwise + * inflate the parent trace's duration / span count beyond several + * backends' caps (e.g. LangSmith's 25k-run cap per trace). + * + * Dual-emits the OTel GenAI spec attrs (`gen_ai.agent.id`, `gen_ai.agent.name`, + * `gen_ai.conversation.id`) alongside vendor `qwen-code.subagent.*` keys. + * Spec is in Development status — dual-emit lets dashboards transition once + * the spec stabilises; drop the vendor key in a follow-up. + */ +export function startSubagentSpan(opts: StartSubagentSpanOptions): Span { + if (!isTelemetrySdkInitialized()) return NOOP_SPAN; + + ensureCleanupInterval(); + + const attributes: Attributes = { + // Spec-aligned (OTel GenAI Agent Spans, Development status). + 'gen_ai.operation.name': 'invoke_agent', + 'gen_ai.provider.name': SERVICE_NAME, + 'gen_ai.agent.id': opts.agentId, + 'gen_ai.agent.name': opts.subagentName, + 'gen_ai.conversation.id': opts.sessionId, + + // Vendor (qwen-code-specific). Dual-emit id/name so dashboards already + // querying spec keys still work. + 'qwen-code.subagent.id': opts.agentId, + 'qwen-code.subagent.name': opts.subagentName, + 'qwen-code.subagent.invocation_kind': opts.invocationKind, + 'qwen-code.subagent.is_built_in': opts.isBuiltIn, + 'qwen-code.subagent.depth': opts.depth, + }; + + if (opts.modelOverride !== undefined) { + attributes['gen_ai.request.model'] = opts.modelOverride; + } + if (opts.parentAgentId !== undefined) { + attributes['qwen-code.subagent.parent_agent_id'] = opts.parentAgentId; + } + if (opts.invokingRequestId !== undefined) { + attributes['qwen-code.subagent.invoking_request_id'] = + opts.invokingRequestId; + } + + const tracer = getTracer(); + + let span: Span; + if (opts.invocationKind === 'foreground') { + // Child of current active span — caller's tool span via context.active(). + span = tracer.startSpan(SPAN_SUBAGENT, { + kind: SpanKind.INTERNAL, + attributes, + }); + } else { + // fork / background: linked root span. `root: true` forces a new traceId + // ignoring any active context; Link points back to the invoker so + // operators can navigate cross-trace. + span = tracer.startSpan(SPAN_SUBAGENT, { + kind: SpanKind.INTERNAL, + attributes, + root: true, + links: opts.invokerSpanContext + ? [ + { + context: opts.invokerSpanContext, + attributes: { 'qwen-code.link.kind': 'invoker' }, + }, + ] + : undefined, + }); + } + + const spanId = getSpanId(span); + const spanContextObj: SpanContext = { + span, + startTime: Date.now(), + attributes: attributes as Record, + type: 'subagent', + }; + activeSpans.set(spanId, new WeakRef(spanContextObj)); + strongSpans.set(spanId, spanContextObj); + return span; +} + +/** + * Run `fn` with `span` set as the active OTel span. Child LLM / tool / + * hook spans created inside `fn` will see `span` as parent via + * `context.active()` and inherit its traceId. Required for fork / + * background paths so child spans don't escape into the ambient context + * after the caller's AgentTool.execute has already returned. + * + * **Side effects (intentional, callers should be aware):** + * + * - Enters `subagentContext` ALS for the body's duration so + * `startLLMRequestSpan` / `startToolSpan` / `startHookSpan` prefer + * this subagent over the outer interaction as the parent. + * - **Clears `toolContext`** for the body's duration. Any code that + * reads `toolContext` inside the subagent body BEFORE the first + * inner tool call will see `undefined`. The subagent's own inner + * tools re-set `toolContext` via `runInToolSpanContext`, so + * inner-tool parenting remains correct. This is required so hooks + * fired inside a subagent body (e.g. SubagentStart) don't + * incorrectly parent under the outer AGENT tool span (#4410). + * + * Mirrors opencode's `withRunSpan` pattern. + */ +export function runInSubagentSpanContext( + span: Span, + fn: () => Promise, +): Promise { + // Skip the context wrapping when telemetry is off / span is untracked + // (startSubagentSpan returns NOOP_SPAN, which is never added to + // activeSpans). Mirrors runInToolSpanContext's pattern — avoids paying + // an AsyncLocalStorage.run() per invocation just to wrap a noop span. + // Review wenshao @ #4410. + const spanId = getSpanId(span); + const spanCtx = activeSpans.get(spanId)?.deref(); + if (!spanCtx) return fn(); + // Enter subagentContext so child startLLMRequestSpan/startToolSpan/ + // startHookSpan calls inside the body parent under this subagent + // instead of escaping back to the outer interactionContext. + // wenshao @ #4410. + // + // Also clear `toolContext` for the body's duration. `startHookSpan`'s + // parent priority is `tool > subagent > interaction`, and the AGENT + // tool's own toolContext is still in scope here — without clearing it, + // hooks fired inside the subagent body (e.g. SubagentStart, before any + // inner tool call) would parent to the outer AGENT tool span instead + // of the subagent. The subagent's own inner tools will re-set + // toolContext via runInToolSpanContext, so inner-tool parenting stays + // correct. wenshao @ #4410. + const otelCtxWithSpan = trace.setSpan(otelContext.active(), span); + return subagentContext.run(spanCtx, () => + toolContext.run(undefined, () => otelContext.with(otelCtxWithSpan, fn)), + ); +} + +/** + * Finalize a subagent span. Status mapping: + * - `completed` → SpanStatus OK + * - `failed` → SpanStatus ERROR, sets `exception.message` + `error.type` + * - `cancelled` / `aborted` → SpanStatus UNSET (matches Phase 2 cancellation) + * + * Idempotent: second call on the same span is a no-op. + */ +export function endSubagentSpan( + span: Span, + metadata: SubagentSpanMetadata, +): void { + const spanId = getSpanId(span); + const spanCtx = activeSpans.get(spanId)?.deref(); + // Surface the silent-skip case so a TTL-sweep race that loses the real + // terminal state is observable in production. Without this, a fork that + // legitimately finishes a few seconds past 4h has its `'completed'` + // outcome silently overwritten by the sweep's `'aborted'/'ttl_swept'` + // stamp with no log trail. Review wenshao @ #4410. + // + // Gate on `isTelemetrySdkInitialized()` so the warn doesn't fire on + // every subagent invocation when telemetry is OFF: in that case + // `startSubagentSpan` returns NOOP_SPAN which was never registered in + // `activeSpans`, so `!spanCtx` is the normal teardown — not a race. + // Review wenshao @ #4410 + own silent-failure + // hunter follow-up. + if (!spanCtx) { + if (isTelemetrySdkInitialized()) { + debugLogger.warn( + `endSubagentSpan: span ${spanId} not found in activeSpans (already swept?) — intended status=${metadata.status}, reason=${metadata.terminateReason ?? 'none'}`, + ); + } + return; + } + if (spanCtx.ended) { + debugLogger.warn( + `endSubagentSpan: span ${spanId} already ended — intended status=${metadata.status}, reason=${metadata.terminateReason ?? 'none'} (possible TTL sweep race)`, + ); + return; + } + + spanCtx.ended = true; + + try { + const duration = Date.now() - spanCtx.startTime; + const endAttributes: Attributes = { + duration_ms: duration, + 'qwen-code.subagent.duration_ms': duration, + 'qwen-code.subagent.status': metadata.status, + }; + if (metadata.terminateReason !== undefined) { + endAttributes['qwen-code.subagent.terminate_reason'] = + metadata.terminateReason; + } + if (metadata.resultSummaryPresent !== undefined) { + endAttributes['qwen-code.subagent.result_summary_present'] = + metadata.resultSummaryPresent; + } + if (metadata.error !== undefined) { + const truncated = truncateSpanError(metadata.error); + endAttributes['exception.message'] = truncated; + } + if (metadata.errorType !== undefined) { + endAttributes['error.type'] = metadata.errorType; + } + + spanCtx.span.setAttributes(endAttributes); + + if (metadata.status === 'completed') { + spanCtx.span.setStatus({ code: SpanStatusCode.OK }); + } else if (metadata.status === 'failed') { + spanCtx.span.setStatus({ + code: SpanStatusCode.ERROR, + message: metadata.error + ? truncateSpanError(metadata.error) + : 'subagent failed', + }); + } + // cancelled / aborted → leave SpanStatus UNSET (Phase 2 convention). + } catch (error) { + debugLogger.warn( + `Failed to update subagent span attributes/status: ${error instanceof Error ? error.message : String(error)}`, + ); + } + + try { + spanCtx.span.end(); + } catch (error) { + debugLogger.warn( + `Failed to end subagent span: ${error instanceof Error ? error.message : String(error)}`, + ); + } + + activeSpans.delete(spanId); + strongSpans.delete(spanId); +} + // --- Interaction Span Attribute Access --- export function getActiveInteractionSpan(): Span | undefined { @@ -958,6 +1370,10 @@ export function clearSessionTracingForTesting(): void { strongSpans.clear(); interactionContext.enterWith(undefined); toolContext.enterWith(undefined); + // subagentContext is checked BEFORE interactionContext in startXSpan, so + // a leaked subagent ALS frame would silently re-parent every subsequent + // test's spans. wenshao @ #4410. + subagentContext.enterWith(undefined); interactionSequence = 0; lastInteractionCtx = undefined; clearDetailedSpanState(); diff --git a/packages/core/src/tools/agent/agent.test.ts b/packages/core/src/tools/agent/agent.test.ts index a66c03a1dcf..cb582e701f6 100644 --- a/packages/core/src/tools/agent/agent.test.ts +++ b/packages/core/src/tools/agent/agent.test.ts @@ -63,6 +63,31 @@ function escapeRegExp(value: string): string { vi.mock('../../subagents/subagent-manager.js'); vi.mock('../../agents/runtime/agent-headless.js'); +// Spies for the subagent-span layer so tests can assert what status taxonomy +// was published. The real runInSubagentSpanContext sets up OTel context-with, +// which is irrelevant here — we just need the body to run. Review wenshao +// @ #4410. +const mockStartSubagentSpan = vi.fn(); +const mockEndSubagentSpan = vi.fn(); + +vi.mock('../../telemetry/index.js', async (importOriginal) => { + const orig = + await importOriginal(); + return { + ...orig, + startSubagentSpan: (opts: unknown) => { + mockStartSubagentSpan(opts); + // Minimal stand-in — endSubagentSpan is mocked too, so no method + // on this object is ever invoked. + return {} as ReturnType; + }, + endSubagentSpan: (span: unknown, metadata: unknown) => { + mockEndSubagentSpan(span, metadata); + }, + runInSubagentSpanContext: (_span: unknown, fn: () => Promise) => fn(), + }; +}); + const MockedSubagentManager = vi.mocked(SubagentManager); const MockedContextState = vi.mocked(ContextState); @@ -732,6 +757,252 @@ describe('AgentTool', () => { expect(description).toBe('Search files'); }); + + describe('qwen-code.subagent span outcome (#4410 wenshao)', () => { + beforeEach(() => { + mockStartSubagentSpan.mockClear(); + mockEndSubagentSpan.mockClear(); + }); + + async function runForegroundOnce(): Promise { + const params: AgentParams = { + description: 'Search files', + prompt: 'Find all TypeScript files', + subagent_type: 'file-search', + }; + const invocation = ( + agentTool as AgentToolWithProtectedMethods + ).createInvocation(params); + await invocation.execute(); + } + + function lastEndMeta(): { + status?: string; + terminateReason?: string; + resultSummaryPresent?: boolean; + error?: string; + errorType?: string; + } { + const calls = mockEndSubagentSpan.mock.calls; + return calls[calls.length - 1][1] as { + status?: string; + terminateReason?: string; + resultSummaryPresent?: boolean; + error?: string; + errorType?: string; + }; + } + + function lastStartSpec(): { + depth?: number; + parentAgentId?: string; + } { + const calls = mockStartSubagentSpan.mock.calls; + return calls[calls.length - 1][0] as { + depth?: number; + parentAgentId?: string; + }; + } + + it('GOAL terminateMode → status="completed" + resultSummaryPresent', async () => { + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.GOAL, + ); + await runForegroundOnce(); + expect(mockEndSubagentSpan).toHaveBeenCalledTimes(1); + const meta = lastEndMeta(); + expect(meta.status).toBe('completed'); + expect(meta.resultSummaryPresent).toBe(true); + }); + + it('ERROR terminateMode → status="failed" + terminateReason="error"', async () => { + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.ERROR, + ); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.terminateReason).toBe('error'); + }); + + it('MAX_TURNS terminateMode → status="failed" + error/errorType populated', async () => { + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.MAX_TURNS, + ); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.terminateReason).toBe('max_turns'); + // Same shape as the ERROR test above so a regression in the + // error-stamping for non-throwing failure paths is caught here + // too. wenshao @ #4410 DeepSeek 3292521241. + expect(meta.error).toBe('subagent terminated with mode: MAX_TURNS'); + expect(meta.errorType).toBe('MAX_TURNS'); + }); + + it('CANCELLED terminateMode → status="cancelled"', async () => { + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.CANCELLED, + ); + await runForegroundOnce(); + // No external signal abort → "subagent_cancelled" branch (terminate + // mode came from inside the subagent itself). + const meta = lastEndMeta(); + expect(meta.status).toBe('cancelled'); + expect(meta.terminateReason).toBe('subagent_cancelled'); + }); + + it('SHUTDOWN terminateMode → status="cancelled" + terminateReason="subagent_shutdown"', async () => { + // SHUTDOWN is graceful arena/team-session-end, not failure. + // wenshao @ #4410 DeepSeek 3291876034. + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.SHUTDOWN, + ); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('cancelled'); + expect(meta.terminateReason).toBe('subagent_shutdown'); + }); + + it('ERROR terminateMode populates error + errorType for OTel exception attrs', async () => { + // Non-throwing failure paths (ERROR/MAX_TURNS/TIMEOUT) must + // populate error/errorType so endSubagentSpan sets the standard + // OTel exception attributes — generic 'subagent failed' was + // hiding the reason from dashboards. wenshao @ #4410 DeepSeek + // 3291876053. + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.ERROR, + ); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.error).toBe('subagent terminated with mode: ERROR'); + expect(meta.errorType).toBe('ERROR'); + }); + + it('subagent.execute throws → status="failed" + errorType=Error', async () => { + vi.mocked(mockAgent.execute).mockRejectedValue( + new Error('catastrophic boom'), + ); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.error).toBe('catastrophic boom'); + expect(meta.errorType).toBe('Error'); + expect(meta.terminateReason).toBe('exception'); + }); + + it('non-Error throw → errorType="NonErrorThrown"', async () => { + vi.mocked(mockAgent.execute).mockRejectedValue('plain string'); + await runForegroundOnce(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.error).toBe('plain string'); + expect(meta.errorType).toBe('NonErrorThrown'); + }); + + it('endSubagentSpan is always called exactly once per invocation', async () => { + // Lifecycle invariant: the wrapper's finally block fires once + // for every runWithSubagentSpan call regardless of the body's + // path. Default mockAgent here uses GOAL termination → + // runSubagentWithHooks calls recordSpanOutcome internally. + await runForegroundOnce(); + expect(mockEndSubagentSpan).toHaveBeenCalledTimes(1); + }); + + it('fallback: body that skips recordOutcome → status="failed" + wiring-bug terminateReason', async () => { + // Defensive fallback in runWithSubagentSpan's finally — fires + // when the body returns without calling recordOutcome. Today + // no production path hits this (runSubagentWithHooks always + // records), so we have to STUB out runSubagentWithHooks to + // exercise the branch. wenshao @ #4410 DeepSeek 3292521244. + const params: AgentParams = { + description: 'Search files', + prompt: 'Find all TypeScript files', + subagent_type: 'file-search', + }; + const invocation = ( + agentTool as AgentToolWithProtectedMethods + ).createInvocation(params); + // Replace runSubagentWithHooks on this instance so it returns + // without calling recordSpanOutcome. + ( + invocation as unknown as { runSubagentWithHooks: () => Promise } + ).runSubagentWithHooks = vi.fn().mockResolvedValue(undefined); + await invocation.execute(); + const meta = lastEndMeta(); + expect(meta.status).toBe('failed'); + expect(meta.terminateReason).toBe( + 'wiring_bug_record_outcome_not_called', + ); + expect(meta.error).toBe('recordOutcome was never called (wiring bug)'); + }); + + it('startSubagentSpan receives depth=0 for top-level foreground (no parent ALS frame)', async () => { + await runForegroundOnce(); + expect(mockStartSubagentSpan).toHaveBeenCalledTimes(1); + const spec = lastStartSpec(); + expect(spec.depth).toBe(0); + expect(spec.parentAgentId).toBeUndefined(); + }); + + it('startSubagentSpan receives depth=parentDepth+1 when invoked inside an outer agent frame', async () => { + await runWithAgentContext('outer-parent', async () => { + await runForegroundOnce(); + }); + // Outer ALS frame at depth=0 → subagent itself records depth=1. + // This regression-guards wenshao's depth-off-by-one fix at #4410. + const spec = lastStartSpec(); + expect(spec.depth).toBe(1); + expect(spec.parentAgentId).toBe('outer-parent'); + }); + + it('CANCELLED terminateMode + aborted signal → status="cancelled" + terminateReason="signal_aborted"', async () => { + // The signalAborted=true branch in deriveSubagentOutcomeMetadata — + // user-initiated stop (Ctrl-C / task_stop) must classify as + // signal_aborted, not subagent_cancelled. wenshao @ #4410. + vi.mocked(mockAgent.getTerminateMode).mockReturnValue( + AgentTerminateMode.CANCELLED, + ); + const params: AgentParams = { + description: 'Search files', + prompt: 'Find all TypeScript files', + subagent_type: 'file-search', + }; + const invocation = ( + agentTool as AgentToolWithProtectedMethods + ).createInvocation(params); + const controller = new AbortController(); + controller.abort(); + await invocation.execute(controller.signal); + const meta = lastEndMeta(); + expect(meta.status).toBe('cancelled'); + expect(meta.terminateReason).toBe('signal_aborted'); + }); + + it('throw + aborted signal → status="aborted" + terminateReason="signal_aborted"', async () => { + // The signalAborted=true branch in deriveSubagentExceptionMetadata. + // A throw under an already-aborted signal is user-cancellation, + // not a programmer error — must classify as aborted, not failed. + vi.mocked(mockAgent.execute).mockRejectedValue( + new Error('boom mid-cancel'), + ); + const params: AgentParams = { + description: 'Search files', + prompt: 'Find all TypeScript files', + subagent_type: 'file-search', + }; + const invocation = ( + agentTool as AgentToolWithProtectedMethods + ).createInvocation(params); + const controller = new AbortController(); + controller.abort(); + await invocation.execute(controller.signal); + const meta = lastEndMeta(); + expect(meta.status).toBe('aborted'); + expect(meta.terminateReason).toBe('signal_aborted'); + }); + }); }); describe('Fork dispatch (subagent_type omitted)', () => { diff --git a/packages/core/src/tools/agent/agent.ts b/packages/core/src/tools/agent/agent.ts index 3a63a350a41..a67d287c134 100644 --- a/packages/core/src/tools/agent/agent.ts +++ b/packages/core/src/tools/agent/agent.ts @@ -51,9 +51,18 @@ import { import { FileDiscoveryService } from '../../services/fileDiscoveryService.js'; import { WorkspaceContext } from '../../utils/workspaceContext.js'; import { + getCurrentAgentDepth, getCurrentAgentId, runWithAgentContext, } from '../../agents/runtime/agent-context.js'; +import { trace, context as otelContext } from '@opentelemetry/api'; +import { + endSubagentSpan, + runInSubagentSpanContext, + startSubagentSpan, + type SubagentInvocationKind, + type SubagentSpanMetadata, +} from '../../telemetry/index.js'; import { AgentEventEmitter, AgentEventType, @@ -679,6 +688,79 @@ assistant: "I'm going to use the ${ToolNames.AGENT} tool to launch the greeting- } } +/** + * Callback the body of `runWithSubagentSpan` invokes to publish its terminal + * state. Without this, both `runSubagentWithHooks` and `bgBody` swallow their + * own errors before returning, leaving the wrapper's catch block dead and + * every span ending as `status='completed'` regardless of actual outcome. + * Review wenshao @ #4410. + */ +type SubagentOutcomeSink = (metadata: SubagentSpanMetadata) => void; + +/** + * Map `AgentTerminateMode` + signal/error state to the span's status taxonomy. + * Mirrors the foreground/background display logic: GOAL → success, CANCELLED + * (or signal abort) → user-initiated stop, everything else → failure. + */ +function deriveSubagentOutcomeMetadata(opts: { + terminateMode: AgentTerminateMode; + signalAborted: boolean; + resultSummaryPresent: boolean; +}): SubagentSpanMetadata { + const { terminateMode, signalAborted, resultSummaryPresent } = opts; + if (signalAborted || terminateMode === AgentTerminateMode.CANCELLED) { + return { + status: 'cancelled', + terminateReason: signalAborted ? 'signal_aborted' : 'subagent_cancelled', + resultSummaryPresent, + }; + } + // SHUTDOWN is a graceful arena/team-session-end, not a failure — group it + // with cancellations so dashboards don't count it against subagent error + // rate. Review wenshao @ #4410. + if (terminateMode === AgentTerminateMode.SHUTDOWN) { + return { + status: 'cancelled', + terminateReason: 'subagent_shutdown', + resultSummaryPresent, + }; + } + if (terminateMode === AgentTerminateMode.GOAL) { + return { status: 'completed', resultSummaryPresent }; + } + // Non-throwing failure paths (ERROR / MAX_TURNS / TIMEOUT) — populate + // `error`/`errorType` so endSubagentSpan sets standard OTel exception + // attributes instead of a generic `'subagent failed'` placeholder. + // Otherwise dashboards relying on `exception.message`/`error.type` see + // no signal for these (reachable) outcomes. wenshao @ #4410. + return { + status: 'failed', + terminateReason: String(terminateMode).toLowerCase(), + error: `subagent terminated with mode: ${terminateMode}`, + errorType: terminateMode, + resultSummaryPresent, + }; +} + +function deriveSubagentExceptionMetadata( + error: unknown, + signalAborted: boolean, +): SubagentSpanMetadata { + return { + status: signalAborted ? 'aborted' : 'failed', + error: error instanceof Error ? error.message : String(error), + errorType: + error instanceof Error ? error.constructor.name : 'NonErrorThrown', + terminateReason: signalAborted ? 'signal_aborted' : 'exception', + // Exception path always lacks a subagent-produced summary (we never got + // through getFinalText()). Setting this explicitly keeps attribute + // shape symmetric with the success-path derive so dashboards filtering + // on result_summary_present don't silently exclude failed runs. + // Review wenshao @ #4410. + resultSummaryPresent: false, + }; +} + class AgentToolInvocation extends BaseToolInvocation { readonly eventEmitter: AgentEventEmitter = new AgentEventEmitter(); private currentDisplay: AgentResultDisplay | null = null; @@ -1142,6 +1224,153 @@ class AgentToolInvocation extends BaseToolInvocation { return undefined; } + /** + * Wrap a subagent body in `qwen-code.subagent` span lifecycle. + * + * Single entry point for the 3 invocation paths (foreground named, fork, + * background). Captures the invoker span context (for fork/background's + * `Link`), reads parent agent id + depth from the AgentContext ALS, opens + * the span with appropriate parent strategy, runs `body` inside + * `runInSubagentSpanContext` so child LLM/tool/hook spans correctly + * inherit the subagent's traceId, then closes the span with the right + * status taxonomy. + * + * The span's lifecycle is **decoupled from this method's return** — for + * fire-and-forget paths (fork, background), the caller `void`s the + * returned promise; the span only closes when the body actually finishes + * (or the 4h TTL safety net fires). See `telemetry-subagent-spans-design.md`. + * + * **Rejection-handling contract for void'd callers:** the body is expected + * to never reject — both `runSubagentWithHooks` and `bgBody` have their + * own try/catch and publish outcomes via `recordOutcome`. This wrapper's + * own `catch` is a defensive fallback for synchronous setup throws. + * Callers using `void` must NOT remove the body's try/catch under the + * assumption that this wrapper covers it: a rejection escaping the + * `void` boundary becomes an unhandled-promise event (terminates the + * process on Node ≥ 15 in default mode). If a new void'd call site is + * added, wrap it in `.catch(...)` defensively. wenshao @ #4410. + * + * #3731 Phase 3. + */ + private async runWithSubagentSpan( + spec: { + agentId: string; + subagentName: string; + invocationKind: SubagentInvocationKind; + isBuiltIn: boolean; + modelOverride?: string; + }, + signal: AbortSignal | undefined, + body: (recordOutcome: SubagentOutcomeSink) => Promise, + ): Promise { + const invokerSpanContext = + spec.invocationKind === 'foreground' + ? undefined + : trace.getSpan(otelContext.active())?.spanContext(); + // Capture parent identity BEFORE we enter the child's runWithAgentContext + // frame inside `body`. The parent's depth is `getCurrentAgentDepth()` (0 + // outside any frame, N inside frame at depth N); the subagent itself + // lives one level deeper, hence the +1 — but only when a parent frame + // exists. Without a parent the subagent is top-level (depth 0). The + // `getCurrentAgentId() !== null` test discriminates "no frame" from + // "frame at depth 0", which `getCurrentAgentDepth()` alone cannot. + // Review wenshao @ #4410. + const parentAgentId = getCurrentAgentId(); + const span = startSubagentSpan({ + ...spec, + parentAgentId: parentAgentId ?? undefined, + depth: parentAgentId !== null ? getCurrentAgentDepth() + 1 : 0, + invokingRequestId: this.callId, + sessionId: this.config.getSessionId(), + invokerSpanContext, + }); + + // The body catches its own errors (runSubagentWithHooks / bgBody both + // swallow exceptions internally, mapping them to display state / + // registry calls), so this wrapper's `catch` is unreachable for the + // happy-flow lifecycle. To still surface real terminal state on the + // span, body opts in by calling `recordOutcome(metadata)` before it + // resolves. If the body forgets, the wrapper does NOT default to + // `completed`: the `finally` below defaults to `failed` plus a + // `wiring_bug_record_outcome_not_called` terminateReason sentinel, so + // the wiring bug surfaces proactively in dashboards instead of being + // silently masked as a success. + // The throw-derived fallbacks below only fire if the body somehow + // rejects (synchronous setup throw or a bug). + let recordedMetadata: SubagentSpanMetadata | undefined; + // First-write-wins. The previous review noticed runSubagentWithHooks + // and bgBody can call this twice (success path + inner catch chains), + // and last-write would silently turn a real `completed` into the + // catch's `failed` when an UpdateDisplay throws mid-success. Pinning + // the first call protects the publish-first ordering. Review wenshao + // @ #4410. + const recordOutcome: SubagentOutcomeSink = (m) => { + recordedMetadata ??= m; + }; + try { + return await runInSubagentSpanContext(span, () => body(recordOutcome)); + } catch (error) { + // ??= so a body that already published its real terminal state + // (e.g. recordOutcome('completed')) is not clobbered by a late + // cleanup throw — a downstream `restoreParentPM()` failure should + // not retroactively turn a successful subagent run into a failure. + // Review wenshao @ #4410. + recordedMetadata ??= deriveSubagentExceptionMetadata( + error, + signal?.aborted ?? false, + ); + throw error; + } finally { + // No `recordOutcome` call AND no throw → body resolved normally + // without opting in. Default to FAILED (not completed) so a + // future wiring bug surfaces proactively in dashboards instead + // of silently masking every failure as a success. Production + // logs alone don't catch this (debug-level), but a real + // `status=failed` will. Review wenshao @ #4410. + if (!recordedMetadata) { + debugLogger.warn( + `runWithSubagentSpan: body did not call recordOutcome for ${spec.subagentName}/${spec.agentId} — defaulting span status to failed (wiring bug)`, + ); + } + endSubagentSpan( + span, + recordedMetadata ?? { + status: 'failed', + error: 'recordOutcome was never called (wiring bug)', + // Distinct sentinel so dashboards can separate genuine + // failures from wiring defects. wenshao @ #4410. + terminateReason: 'wiring_bug_record_outcome_not_called', + }, + ); + } + } + + /** + * Build the spec object passed to `runWithSubagentSpan`. The 3 call + * sites differ only in `invocationKind`; this helper de-duplicates the + * other fields so renaming `subagentName` (or adding a new spec field) + * is a one-place change. wenshao @ #4410. + */ + private buildSubagentSpanSpec( + hookOpts: { agentId: string; agentType: string }, + subagentConfig: SubagentConfig, + invocationKind: SubagentInvocationKind, + ): { + agentId: string; + subagentName: string; + invocationKind: SubagentInvocationKind; + isBuiltIn: boolean; + modelOverride?: string; + } { + return { + agentId: hookOpts.agentId, + subagentName: hookOpts.agentType, + invocationKind, + isBuiltIn: subagentConfig.level === 'builtin', + modelOverride: subagentConfig.model, + }; + } + /** * Runs a subagent with start/stop hook lifecycle, updating the display * as execution progresses. @@ -1155,6 +1384,13 @@ class AgentToolInvocation extends BaseToolInvocation { resolvedMode: PermissionMode; signal?: AbortSignal; updateOutput?: (output: ToolResultDisplay) => void; + /** + * Optional sink the qwen-code.subagent span wrapper passes in so this + * method can report its actual terminal state (the outer try/catch + * swallows errors, so the wrapper cannot derive it from a throw). + * Review wenshao @ #4410. + */ + recordSpanOutcome?: SubagentOutcomeSink; }, ): Promise { const { agentId, agentType, resolvedMode, signal, updateOutput } = opts; @@ -1196,14 +1432,34 @@ class AgentToolInvocation extends BaseToolInvocation { } // Get the results + const subagentRawText = subagent.getFinalText(); const finalText = appendStopHookBlockingCapWarning( - subagent.getFinalText(), + subagentRawText, stopHookWarning, ); const terminateMode = subagent.getTerminateMode(); const success = terminateMode === AgentTerminateMode.GOAL; const executionSummary = subagent.getExecutionSummary(); + // Publish span outcome BEFORE side-effectful UI/registry calls — if + // updateDisplay throws, the subagent's real terminal state must + // still reach telemetry instead of being clobbered by the catch + // branch's exception derivation. Review wenshao @ #4410. + // + // `resultSummaryPresent` checks the RAW subagent text (not finalText + // with stop-hook warning) so a subagent that produced no result but + // hit a stop-hook block doesn't false-positive as having a summary. + // Matches the bgBody pattern. wenshao @ #4410. + opts.recordSpanOutcome?.( + deriveSubagentOutcomeMetadata({ + terminateMode, + signalAborted: signal?.aborted ?? false, + resultSummaryPresent: Boolean( + subagentRawText && subagentRawText.length > 0, + ), + }), + ); + if (signal?.aborted) { this.updateDisplay( { @@ -1226,6 +1482,11 @@ class AgentToolInvocation extends BaseToolInvocation { } return stopHookWarning; } catch (error) { + // Same ordering rule as the success path: publish first so any + // downstream updateDisplay throw can't lose telemetry. + opts.recordSpanOutcome?.( + deriveSubagentExceptionMetadata(error, signal?.aborted ?? false), + ); const errorMessage = error instanceof Error ? error.message : String(error); debugLogger.error( @@ -1992,7 +2253,7 @@ class AgentToolInvocation extends BaseToolInvocation { // guard in execute() fires if the fork child's model calls `agent` // again — otherwise background forks bypass the ALS marker and can // spawn nested implicit forks. - const bgBody = async () => { + const bgBody = async (recordSpanOutcome: SubagentOutcomeSink) => { try { await bgSubagent.execute(contextState, bgAbortController.signal); @@ -2013,13 +2274,29 @@ class AgentToolInvocation extends BaseToolInvocation { // MAX_TURNS, TIMEOUT, and SHUTDOWN are surfaced as failures so // the parent model (and the UI) don't treat incomplete runs as // completed. + // + // Snapshot the span-relevant terminal state and PUBLISH IT + // FIRST — if the worktree cleanup / registry update / patch + // throws, telemetry must still see the subagent's actual + // outcome (review wenshao @ #4410). const terminateMode = bgSubagent.getTerminateMode(); + const subagentRawText = bgSubagent.getFinalText(); + recordSpanOutcome( + deriveSubagentOutcomeMetadata({ + terminateMode, + signalAborted: bgAbortController.signal.aborted, + resultSummaryPresent: Boolean( + subagentRawText && subagentRawText.length > 0, + ), + }), + ); + const wtSuffix = formatWorktreeSuffix( await cleanupWorktreeIsolation(), ); const finalText = appendStopHookBlockingCapWarning( - bgSubagent.getFinalText(), + subagentRawText, stopHookWarning, ) + wtSuffix; const completionStats = getCompletionStats(); @@ -2030,7 +2307,15 @@ class AgentToolInvocation extends BaseToolInvocation { lastUpdatedAt: new Date().toISOString(), lastError: undefined, }); - } else if (terminateMode === AgentTerminateMode.CANCELLED) { + } else if ( + terminateMode === AgentTerminateMode.CANCELLED || + terminateMode === AgentTerminateMode.SHUTDOWN + ) { + // SHUTDOWN is grouped with CANCELLED in the span taxonomy + // (deriveSubagentOutcomeMetadata); align the registry side + // so dashboards don't see span=cancelled / registry=failed + // mismatch on graceful arena/team-session shutdown. + // wenshao @ #4410. registry.finalizeCancelled( hookOpts.agentId, finalText, @@ -2055,6 +2340,13 @@ class AgentToolInvocation extends BaseToolInvocation { }); } } catch (error) { + // Publish first — same reason as the success path. + recordSpanOutcome( + deriveSubagentExceptionMetadata( + error, + bgAbortController.signal.aborted, + ), + ); const baseErrorMsg = error instanceof Error ? error.message : String(error); debugLogger.error( @@ -2122,10 +2414,43 @@ class AgentToolInvocation extends BaseToolInvocation { }; // Wrap in the agent-identity frame so nested `agent` tool calls // from this subagent's model record this agent's id as their - // `parentAgentId` in the sidecar meta. + // `parentAgentId` in the sidecar meta. Also wrap in + // qwen-code.subagent span (#3731 Phase 3) — background is + // fire-and-forget, so the span gets a new traceId + `Link` to the + // invoking AGENT tool span. `invocationKind` distinguishes the + // implicit fork (no subagent_type) from a named background agent; + // both are long-lived enough to qualify for the 4h TTL safety net. const framedBgBody = () => - runWithAgentContext(hookOpts.agentId, bgBody); - void (isFork ? runInForkContext(framedBgBody) : framedBgBody()); + this.runWithSubagentSpan( + this.buildSubagentSpanSpec( + hookOpts, + subagentConfig, + isFork ? 'fork' : 'background', + ), + // bg uses the per-agent abort controller, not the parent turn + // signal — `task_stop` aborts the bg controller alone (silent + // failure: a task_stop'd bg agent was being reported as 'failed' + // because the wrapper saw an unaborted parent signal). + bgAbortController.signal, + (recordOutcome) => + runWithAgentContext(hookOpts.agentId, () => + bgBody(recordOutcome), + ), + ); + // Defensive `.catch`: bgBody is supposed to handle its own + // errors, but runWithSubagentSpan's `endSubagentSpan` finally + // call could theoretically throw if OTel internals break. + // Without this, such a throw becomes an unhandled rejection + // (Node ≥15 default = process termination). Review wenshao @ + // #4410 + silent-failure-hunter. + const bgPromise = isFork + ? runInForkContext(framedBgBody) + : framedBgBody(); + bgPromise.catch((err) => + debugLogger.warn( + `[Agent] background subagent ${hookOpts.agentId} body raised unexpected rejection: ${err instanceof Error ? err.message : String(err)}`, + ), + ); this.updateDisplay({ status: 'background' as const }, updateOutput); return { @@ -2170,24 +2495,52 @@ class AgentToolInvocation extends BaseToolInvocation { // do this in their finally blocks. Without it, every AgentTool / // SkillTool the fork's model instantiates from this registry leaks // its change-listener on shared SubagentManager / SkillManager. + // Wrap fork body in qwen-code.subagent span (#3731 Phase 3). Forks + // are fire-and-forget — span gets a NEW traceId + `Link` back to the + // invoking tool span. Spec recommends Link for "long running + // asynchronous data processing operations" (OTel trace spec). Span + // lifetime is decoupled from this AgentTool.execute return; the 4h + // TTL safety net catches genuinely abandoned forks. const runFramedFork = () => - runWithAgentContext(hookOpts.agentId, async () => { - try { - await this.runSubagentWithHooks(subagent, contextState, hookOpts); - } finally { - cleanupOwnedMonitorNotifications(); - void agentConfig - .getToolRegistry() - .stop() - .catch(() => {}); - // Restore parent PM's dangerous allow rules if this AUTO - // override stripped them. Fork-async path: restore fires - // when the fork body terminates, not when the outer - // execute() returns the FORK_PLACEHOLDER_RESULT. - restoreParentPM(); - } - }); - void runInForkContext(runFramedFork); + this.runWithSubagentSpan( + this.buildSubagentSpanSpec(hookOpts, subagentConfig, 'fork'), + // Forks are fire-and-forget. The parent turn's signal is the + // wrong abort source for span classification here — if the + // parent turn happens to be cancelled at the same instant the + // fork throws an unrelated internal error, the catch fallback + // would otherwise misclassify it as 'aborted'. Pass undefined + // so the fallback classifies as 'failed' (review wenshao @ + // #4410). The fork's actual abort wiring still flows through + // runSubagentWithHooks → recordOutcome, which is the + // load-bearing path. + undefined, + (recordSpanOutcome) => + runWithAgentContext(hookOpts.agentId, async () => { + try { + await this.runSubagentWithHooks(subagent, contextState, { + ...hookOpts, + recordSpanOutcome, + }); + } finally { + cleanupOwnedMonitorNotifications(); + void agentConfig + .getToolRegistry() + .stop() + .catch(() => {}); + // Restore parent PM's dangerous allow rules if this AUTO + // override stripped them. Fork-async path: restore fires + // when the fork body terminates, not when the outer + // execute() returns the FORK_PLACEHOLDER_RESULT. + restoreParentPM(); + } + }), + ); + // Defensive `.catch` — same reason as the bg path above. + runInForkContext(runFramedFork).catch((err) => + debugLogger.warn( + `[Agent] fork subagent ${hookOpts.agentId} body raised unexpected rejection: ${err instanceof Error ? err.message : String(err)}`, + ), + ); return { llmContent: [{ text: FORK_PLACEHOLDER_RESULT }], returnDisplay: this.currentDisplay!, @@ -2208,9 +2561,20 @@ class AgentToolInvocation extends BaseToolInvocation { } const fgHookOpts = { ...hookOpts, signal: fgAbortController.signal }; + // Wrap in qwen-code.subagent span (#3731 Phase 3). Foreground + // invocations are child spans of the AGENT tool's `qwen-code.tool` + // span, inheriting its traceId so the trace tree stays unified. const runFramed = () => - runWithAgentContext(hookOpts.agentId, () => - this.runSubagentWithHooks(subagent, contextState, fgHookOpts), + this.runWithSubagentSpan( + this.buildSubagentSpanSpec(hookOpts, subagentConfig, 'foreground'), + fgAbortController.signal, + (recordSpanOutcome) => + runWithAgentContext(hookOpts.agentId, () => + this.runSubagentWithHooks(subagent, contextState, { + ...fgHookOpts, + recordSpanOutcome, + }), + ), ); // Register in BackgroundTaskRegistry with isBackgrounded:false so the