feat(telemetry): unify span creation paths for hierarchical trace tree#4126
Merged
Conversation
Contributor
There was a problem hiding this comment.
Pull request overview
This PR reworks telemetry span creation so LLM and tool spans use session-tracing helpers and can form a hierarchical trace tree under interaction spans.
Changes:
- Adds tool-span AsyncLocalStorage scoping and updates session-tracing tests/exports.
- Replaces generic API/tool tracing wrappers with typed LLM/tool span helpers.
- Adds a workflow tracing gap analysis design document.
Reviewed changes
Copilot reviewed 9 out of 9 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
packages/core/src/telemetry/session-tracing.ts |
Adds tool context scoping and updates tool execution span parenting/status behavior. |
packages/core/src/telemetry/session-tracing.test.ts |
Updates and expands tests for tool context and span status behavior. |
packages/core/src/telemetry/index.ts |
Exports the new tool context helper. |
packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts |
Switches API tracing to LLM request span helpers. |
packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts |
Updates logging generator telemetry mocks/assertions for LLM spans. |
packages/core/src/core/coreToolScheduler.ts |
Switches tool tracing to typed tool/tool-execution spans. |
packages/core/src/core/client.ts |
Removes the redundant client-level generateContent span wrapper. |
packages/core/src/core/client.test.ts |
Removes assertions tied to the deleted client span. |
docs/design/workflow-tracing-gaps.md |
Documents current tracing gaps and phased roadmap. |
Comments suppressed due to low confidence (3)
packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts:467
- This finalizer now relies on
endLLMRequestSpan, which can throw from span operations. In the streaming path that means a successfully consumed stream can still fail duringfinally(the existing “preserves stream success when the OK status update fails” test covers this behavior). Keep span finalization best-effort so telemetry errors do not surface to callers or mask stream errors.
if (span) {
endLLMRequestSpan(span, {
success: !errorOccurred,
inputTokens: lastUsageMetadata?.promptTokenCount,
outputTokens: lastUsageMetadata?.candidatesTokenCount,
durationMs: Date.now() - startTime,
error: errorOccurred
? API_CALL_FAILED_SPAN_STATUS_MESSAGE
: undefined,
});
packages/core/src/core/coreToolScheduler.ts:1998
endToolExecutionSpancan throw from OTel span operations, and because this call is inside the tool executiontry, a telemetry failure after a successful tool result is caught asexecutionErrorand turns the tool call into an error. Make the execution-span end best-effort (or move it outside the tool-result error handling with its own guard) so tracing failures do not change tool outcomes.
const toolResult: ToolResult = await promise;
endToolExecutionSpan(execSpan, {
success: toolResult.error === undefined,
});
packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts:267
- On the error path,
endLLMRequestSpancan throw while setting span status/ending the span, which would replace the original upstream error before it is rethrown. The previoussafeSetStatuspath explicitly avoided masking API errors. Guard this telemetry finalization so callers still receive the original generation failure.
endLLMRequestSpan(llmSpan, {
success: false,
durationMs,
error: API_CALL_FAILED_SPAN_STATUS_MESSAGE,
});
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
373b64f to
609e32b
Compare
Contributor
Code Coverage Summary
CLI Package - Full Text ReportCore Package - Full Text ReportFor detailed HTML reports, please see the 'coverage-reports-22.x-ubuntu-latest' artifact from the main CI run. |
wenshao
requested changes
May 13, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
[Critical] [test] coreToolScheduler.test.ts: 13 telemetry span tests fail — The test mock intercepts withSpan from tracer.js, but production code now imports startToolSpan/endToolSpan/runInToolSpanContext from session-tracing.ts. toolSpanRecords stays empty; all span assertions fail. The refactored span lifecycle in executeSingleToolCall and _executeToolCallBody has zero test coverage.
[Critical] [test] loggingContentGenerator.test.ts: 3 tests fail — (1) Attribute name mismatch: test expects unprefixed model/prompt_id but mock uses prefixed qwen-code.model/qwen-code.prompt_id. (2) Mock endLLMRequestSpan calls span.setStatus() without try/catch; errors propagate from finally block. Production endLLMRequestSpan wraps everything in try/catch.
Suggested fixes for test failures:
- Update coreToolScheduler test mock to intercept
startToolSpan/endToolSpan/runInToolSpanContext/startToolExecutionSpan/endToolExecutionSpanfrom'../telemetry/session-tracing.js' - Fix attribute name assertions to use prefixed names
- Wrap the mocked
endLLMRequestSpanbody in try/catch matching production behavior
wenshao
requested changes
May 14, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
[Suggestion] endToolSpan and endLLMRequestSpan have asymmetric success attribute handling: endLLMRequestSpan unconditionally sets success on every call, while endToolSpan only sets it on success paths (no metadata → no success attribute). This means dashboard queries filtering on success = false will miss all non-success tool spans. Consider making them consistent — either always set success in endToolSpan too, or add { success: false } to error/cancel paths.
— DeepSeek/deepseek-v4-pro via Qwen Code /review
3919ade to
debe7f4
Compare
wenshao
reviewed
May 14, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
Incremental review of new commits (since last review at 3919ade)
What changed
- IDE context is now merged into the user prompt via
<system-reminder>wrapper (no more separateaddHistorycalls) escapeSystemReminderTagsnow used for both rule content and IDE text (replaces narrow</system-reminder>regex)forceFullIdeContextset on Error and ChatCompressed events- State update deferral to first stream event, with tests covering throw-before-event case
- Microcompact log format updated for per-kind counts
Assessment
The incremental changes are well-structured and well-tested. The IDE context merge + system-reminder escaping is a clear improvement. Key concerns from the previous review about:
- Tool span naming regression
- Redundant
setStatus(OK) - Stream vs non-stream span naming
- Unprotected code before
tryblock in_executeToolCallBody
...are in files not touched by this incremental update and remain open.
— DeepSeek/deepseek-v4-pro via Qwen Code /review
6ef1929 to
81a8869
Compare
This was referenced May 15, 2026
Closed
#3731 P3 Phase 1) Replace disconnected withSpan/startSpanWithContext calls in runtime with session-tracing typed helpers so LLM and tool spans become children of the interaction span instead of siblings under the session root. - Add toolContext ALS with runInToolSpanContext() for concurrent-safe tool span scoping (uses AsyncLocalStorage.run, not enterWith) - Wire startLLMRequestSpan/endLLMRequestSpan in loggingContentGenerator for both streaming and non-streaming paths - Wire startToolSpan/endToolSpan + startToolExecutionSpan/endToolExecutionSpan in coreToolScheduler with proper try/finally lifecycle - Remove redundant withSpan('client.generateContent') wrapper from client.ts - Fix endToolSpan to not override pre-set status when metadata is omitted - Change startToolExecutionSpan to read parent from toolContext ALS - Update tests for new span creation APIs and remove dead test infrastructure
- Remove unused _toolSpan variable (TS6133) - Use bracket notation for index signature property access (TS4111)
…test mocks - coreToolScheduler.test.ts: mock startToolSpan/endToolSpan/runInToolSpanContext instead of withSpan; update cancellation tests for restored safeSetStatus call - loggingContentGenerator.test.ts: fix attribute keys in mock, add try/catch in endLLMRequestSpan mock to match production best-effort behavior
- Add debugLogger.warn in catch blocks of endLLMRequestSpan/endToolSpan/ endToolExecutionSpan instead of silent swallowing - Add JSDoc on endToolSpan documenting intentional no-metadata-no-status contract with setToolSpanFailure/setToolSpanCancelled - Add warning in startToolExecutionSpan when called outside runInToolSpanContext (no active toolContext) - Sanitize error message in endToolExecutionSpan: use constant TOOL_SPAN_STATUS_TOOL_EXCEPTION instead of raw error message
…heduler tests The full mock shadowed all re-exports (logToolCall, etc.) causing 49 test failures. Use importActual to preserve other exports, only override span functions.
startToolExecutionSpan mock also pushes to toolSpanRecords, so at(-1) returns the execution sub-span instead of the tool span. Use findLast to filter by name.
- Remove redundant safeSetStatus(span, OK) on success path — endToolSpan in finally already sets OK via metadata - Add llm_request.stream attribute (true/false) to distinguish streaming vs non-streaming LLM requests in trace backends
Bypass span.setStatus() in mock to avoid potential interference from vitest module resolution. Write to statusCalls/ended directly on the ToolSpanRecord.
…/index.js Mocking the barrel re-export (telemetry/index.js) with importActual was unreliable — vitest's module resolution could bind production code to the real endToolSpan before the mock override took effect. Mock the source module (session-tracing.js) directly to guarantee interception.
…y in finally Root cause: checkAndNotifyCompletion clears this.toolCalls before the finally block in executeSingleToolCall runs, so the tc lookup always returns undefined. Fix: set OK status explicitly in _executeToolCallBody's success path via safeSetStatus(span, OK), and call endToolSpan() without metadata in finally (just ends the span, preserves pre-set status from any path).
81a8869 to
eef8ce7
Compare
…n on failure - Wrap non-stream generateContent API call + logging in context.with(spanContext) so nested OTel spans (HTTP instrumentation, log-bridge spans) parent to qwen-code.llm_request instead of session root (matches streaming path). - runInToolSpanContext now also activates OTel context via otelContext.with, not just the custom toolContext ALS. Hooks/HTTP/IO during tool execution now correctly parent to qwen-code.tool span. - Split end*Span helpers: span.end() runs in its own try/catch so a throwing setAttributes/setStatus can't leak unended spans.
…cution span timing
- start{LLMRequest,Tool,ToolExecution}Span now fall back to getSessionContext()
when no parent context, instead of otelContext.active(). Side-query LLM calls
(auto-title, recap) now stay in the session trace instead of starting a new
detached trace.
- Move startToolExecutionSpan() to BEFORE invocation.execute(), matching
claude-code. Previously the synchronous setup inside execute (shell command
preprocessing, child_process.spawn) ran outside the execution span.
wenshao
requested changes
May 15, 2026
| ); | ||
| this.notifyToolCallsUpdate(); | ||
| }; | ||
| promise = invocation.execute( |
Collaborator
There was a problem hiding this comment.
[Critical] invocation.execute(...) now runs before the try block, so synchronous setup failures bypass the failure path. This PR intentionally starts the execution sub-span before execute() to bracket synchronous setup, but if execute() throws before returning a promise (for example during shell setup), the catch block below never runs: the execution span is not ended with failure metadata, failure hooks are skipped, and the tool call can miss the normal terminal error response. Move the try so it wraps both the execute() call and the await promise, and keep the existing catch/failure handling shared for synchronous and async failures.
— gpt-5.5 via Qwen Code /review
| } catch { | ||
| // OTel errors must not interrupt the consumer. | ||
| } | ||
| endLLMRequestSpan(span, { |
Collaborator
There was a problem hiding this comment.
[Suggestion] After the idle timer fires, the helper has already ended and removed the span, but this wrapper does not keep a local spanEnded/timed-out flag. If the consumer resumes after a long idle gap, later chunks still update lastUsageMetadata, but the final endLLMRequestSpan(...) call is a no-op, so the exported span remains an error/timed-out span and loses the real terminal status/token counts. The previous code kept a local spanEnded guard for this timeout path. Consider restoring a local guard/timeout state so resumed streams do not silently discard their final telemetry, or only end once the generator is truly abandoned.
— gpt-5.5 via Qwen Code /review
| // active via runInToolSpanContext, and tool implementations don't | ||
| // currently emit nested OTel spans of their own — the span boundary | ||
| // is purely for timing/attribution. | ||
| const execSpan = startToolExecutionSpan(); |
Collaborator
There was a problem hiding this comment.
[Suggestion] The scheduler tests mock startToolExecutionSpan / endToolExecutionSpan, but they do not assert that this new execution sub-span is started and ended with the expected metadata on the concrete scheduler paths. A regression could drop the sub-span or mark ToolResult.error / thrown exceptions as successful without failing these tests. Please add scheduler-level assertions for success, ToolResult.error, thrown invocation exceptions, and pre-hook denial not starting an execution span.
— gpt-5.5 via Qwen Code /review
| this.wrapped.generateContent(req, userPromptId), | ||
| const llmSpan = startLLMRequestSpan(req.model, userPromptId); | ||
| try { | ||
| llmSpan.setAttribute('llm_request.stream', false); |
Collaborator
There was a problem hiding this comment.
[Suggestion] This PR adds llm_request.stream to preserve stream vs non-stream observability after both paths moved to the shared qwen-code.llm_request span name, but the tests only check span creation/status and do not assert this attribute. Please have the span mock record setAttribute calls and assert generateContent() sets llm_request.stream to false while generateContentStream() sets it to true.
— gpt-5.5 via Qwen Code /review
wenshao
requested changes
May 16, 2026
wenshao
requested changes
May 16, 2026
…ce, test coverage - coreToolScheduler.executeSingleToolCall: move try-block to wrap invocation.execute() so synchronous throws (e.g. shell setup failure) flow into the same catch path as async rejections. Previously a sync throw would leak the execution span and skip failure hooks. - loggingStreamWrapper: track spanEndedByTimeout flag so a stream that resumes after the 5-min idle timeout does not run the final endLLMRequestSpan (which would no-op anyway, but the flag also stops resetSpanTimeout from queuing further timer callbacks). - coreToolScheduler.test: add execution sub-span assertions for success, ToolResult.error, thrown invocation exceptions, and pre-hook denial. - loggingContentGenerator.test: capture setAttribute calls into the mock span attributes record; assert llm_request.stream is false for non-stream and true for stream paths.
… gaps
- endLLMRequestSpan now uses spanCtx.span for mutations (matches
endToolSpan/endToolExecutionSpan pattern). Same object, but consistent
lookup pattern prevents future drift.
- Mocks capture endLLMRequestSpan and endToolSpan/endToolExecutionSpan
metadata so tests can assert token counts, durationMs, success, error
are forwarded correctly. Add assertions on:
* Non-stream LLM: inputTokens, outputTokens, success on response path
* Non-stream LLM: success: false + sanitized error on rejection
* Stream LLM: final lastUsageMetadata reaches endLLMRequestSpan
* Tool execution sub-span: success: true on happy path
* Tool execution sub-span: success: false on ToolResult.error
* Tool execution sub-span: success: false + sanitized error on throw
- Add OTel error resilience tests: when setAttributes or setStatus throws,
span.end() must still run and the span must be removed from activeSpans.
Covered for endLLMRequestSpan, endToolSpan, endToolExecutionSpan.
wenshao
reviewed
May 16, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
[Suggestion — Pattern: loggingStreamWrapper test gaps] Three test coverage gaps in the streaming wrapper:
- Idle timeout path completely untested — timer setup, reset on chunk arrival, cleanup on normal completion,
spanEndedByTimeoutgate logic, and timeout-triggered span end with metadata are not covered. Usevi.useFakeTimers(). - Stream error tests miss
endMetadataassertions (L1037, L1087) — production code passes{ success: false, inputTokens, outputTokens, durationMs, error }toendLLMRequestSpan, but tests only checkstatusesandended. - Stream error after usage metadata never tested — existing error tests throw before
lastUsageMetadatais set, so inputTokens/outputTokens forwarding on the error path remains unverified.
| } | ||
| endLLMRequestSpan(span, { | ||
| success: false, | ||
| durationMs: Date.now() - startTime, |
Collaborator
There was a problem hiding this comment.
[Suggestion] The idle timeout callback closes the span with success: false, but if the consumer later drains remaining buffered chunks after the timeout, safelyLogApiResponse still logs a "successful" API response. The span in the trace says "timed out / error" while the API log says "success" — contradictory signals that can cause false escalations during incident response.
Suggested change
| durationMs: Date.now() - startTime, | |
| // After the idle timeout fires, also skip the success log: | |
| if (spanEndedByTimeout) return; // added at the start of the normal completion path |
— DeepSeek/deepseek-v4-pro via Qwen Code /review
wenshao
requested changes
May 16, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
跑了真实 E2E（DeepSeek 后端 + OTel file exporter，触发 run_shell_command 工具调用，--approval-mode=yolo）。Trace 拓扑彻底修好：
qwen-code.interaction (f8b3ffb…) ← root
├── qwen-code.llm_request (0600f75…) ← turn 1
├── qwen-code.tool (0ec9017…)
│ └── qwen-code.tool.execution (4a1618b…)
└── qwen-code.llm_request (353fa37…) ← turn 2
5 个 span 同一 traceId a185dc9…，proper parent-child。PR #4097 那次的拓扑分裂彻底解决 ✅
合入前唯一想先修的一处 —— success 属性在 qwen-code.tool 上完全缺失：
实测导出（成功路径）：
{"name":"qwen-code.tool","status":{"code":1},
"attributes":["call_id","duration_ms","tool.name","tool_name"]} // ← 无 success
{"name":"qwen-code.llm_request","status":{"code":1},
"attributes":[…"success"…]} // ← 有 success根因
coreToolScheduler.ts:1871 是 endToolSpan 唯一 的调用点，且不带 metadata：
} finally {
endToolSpan(toolSpan);
}session-tracing.ts:360-364 的 endToolSpan 仅在 metadata.success !== undefined 时写 success 属性。所以任何 tool span（不论成功/失败/取消）都不会带 success 属性。
而 endLLMRequestSpan 的对应分支（session-tracing.ts:254）是无条件 endAttributes['success'] = metadata.success;，所以 qwen-code.llm_request 始终带 success。
影响
后端用 success = false 过滤 tool 失败（最常见的失败率 dashboard 查询）会完全漏掉所有 tool 失败 —— 因为 tool span 上根本就没有 success 字段。tool.failure_kind 属性确实在失败路径写了，但需要后端单独识别这个非标 attr，跟 success boolean 不能复用同一套查询。
建议改法（二选一）
方案 1（推荐，最小改动）：让 setToolSpanFailure / setToolSpanCancelled 写 success: false，并在成功路径补一行 success: true。
// session-tracing.ts: setToolSpanFailure
function setToolSpanFailure(span: Span, failureKind: string, message: string): void {
try {
span.setAttribute(TOOL_FAILURE_KIND_ATTRIBUTE, failureKind);
span.setAttribute('success', false); // ← add
} catch { /* … */ }
safeSetStatus(span, { code: SpanStatusCode.ERROR, message });
}
// setToolSpanCancelled 同理加一行 span.setAttribute('success', false);
// coreToolScheduler.ts:2180
this.setStatusInternal(callId, 'success', successResponse);
safeSetStatus(span, { code: SpanStatusCode.OK });
span.setAttribute('success', true); // ← add方案 2：在 finally 处带 metadata 调 endToolSpan，但需要从 ALS 或 SpanContext 里读出 terminal 状态（this.toolCalls 在 finally 时已被 checkAndNotifyCompletion 清空，不能直接查）。
方案 1 更直白，符合现有 setToolSpan* 助手"封装一切状态副作用"的语义。
单测断言（防回归）
coreToolScheduler.test.ts:3401-3453 已有 4 条 tool.execution lifecycle 断言；麻烦在 qwen-code.tool 这边也加 3 条：
it('tool span: success=true attribute on success', async () => {
await runSingleTool();
const tool = getToolSpan();
expect(tool!.spanAttributes).toHaveProperty('success', true);
});
it('tool span: success=false on ToolResult.error', async () => { … });
it('tool span: success=false on thrown invocation', async () => { … });—— 改完这一处 + 测试，我就 approve。其它 5 条 Suggestion（abort 状态分辨、idle timeout vs api log 不一致、Phase 2 占位 union 等）可以新开 issue follow-up，不阻塞合入。
…metry
- session-tracing.ts SpanContext.type: comment 'tool.blocked_on_user' |
'hook' as Phase 2 forward-declarations (no helpers wired yet).
- endToolExecutionSpan: align no-metadata-no-status behavior with
endToolSpan. Currently no caller omits metadata, but the asymmetric
default (OK vs preserve-pre-set) was a maintenance trap.
- loggingContentGenerator generateContent (non-stream) catch block:
call endLLMRequestSpan BEFORE the logging block, mirroring the
streaming path. Defense-in-depth against logging-side rejections.
- loggingContentGenerator: restore abort-specific span status message.
All three LLM error paths (non-stream catch, stream eager-error catch,
stream loggingStreamWrapper finally) now use
API_CALL_ABORTED_SPAN_STATUS_MESSAGE when req.config.abortSignal.aborted,
matching the original withSpan('client.generateContent') behavior.
Trace backends can now distinguish cancellations from real failures.
- coreToolScheduler _executeToolCallBody catch: distinguish abort vs
exception in execSpan error message. New constant
TOOL_SPAN_STATUS_TOOL_CANCELLED prevents operators filtering exec
spans for errors from seeing cancellation false positives.
- New test asserting exec span uses cancelled-by-user message when the
invocation throws after abort.
E2E review found qwen-code.tool spans never carry the `success` boolean
attribute (the helper only writes it when metadata is passed, and the
finally block calls endToolSpan(toolSpan) without metadata). This breaks
the most common observability query — filtering tool failures with
`success = false` — because tool spans don't have that field at all.
Fix: setToolSpanFailure / setToolSpanCancelled now also call
span.setAttribute('success', false); the success path in
_executeToolCallBody adds span.setAttribute('success', true) after
safeSetStatus(span, OK). Mirrors the unconditional `success` attribute
on llm_request spans, so backends can use one query for both span types.
Add 4 scheduler-level tests asserting the success attribute on:
- success path
- ToolResult.error path
- thrown invocation path
- cancellation path
Collaborator
Author
|
@wenshao 已修复，commit 采用方案 1（最小改动）：
新增 4 条防回归断言（
后端用 |
Collaborator
本地真实测试报告Head: 我 11:44Z 的 Critical（
|
| 测试套件 | 结果 |
|---|---|
telemetry/session-tracing.test.ts |
27/27 pass |
core/coreToolScheduler.test.ts |
128/128 pass（新增 4 条 success attr 断言 + 1 条 cancelled 用例） |
core/loggingContentGenerator.test.ts |
37/37 pass |
core/client.test.ts |
131/131 pass |
tsc --noEmit (core + cli) |
0 错 |
| GitHub CI | 全绿（Lint, Test ubuntu/macos/windows, CodeQL, Coverage） |
合计 323/323 单测过。
LGTM ✅
wenshao
approved these changes
May 16, 2026
wenshao
left a comment
Collaborator
There was a problem hiding this comment.
已发布详细测试报告（见 issue comment）。Critical（tool span 缺 success 属性）已修，11:44Z 6 条 Suggestion 也解了 5 条；成功 + 失败两路径真实 E2E 验证 success attr 写入正确，trace 拓扑保持 hierarchical；323/323 单测过，CI 全绿，tsc 0 错。LGTM ✅
This was referenced May 16, 2026
Open
wenshao
pushed a commit
that referenced
this pull request
May 19, 2026
…og/span consistency (#4302) * fix(telemetry): Phase 1.5 polish — fallback order, abort-as-result, log/span consistency Follow-up to #4126 (Phase 1: unify span creation paths). Four small fixes surfaced in the late review rounds; tracked in #4212. 1. session-tracing fallback order — add resolveParentContext() helper that mirrors tracer.ts:getParentContext(): when interactionContext / toolContext ALS is empty, prefer the active OTel span over the synthetic session-root fallback. Without this, an LLM or tool call nested inside another OTel span (subagent inside a tool, instrumented HTTP path, etc.) re-parented to session root and flattened the trace tree. Three sites unified. 2. tool.execution span misreporting cancellation as success — when a tool observes signal.aborted and resolves with a normal ToolResult (no .error), the execution sub-span used to close as success while the parent tool span ended cancelled. Snapshot signal.aborted once after await, mirror it into endToolExecutionSpan, and stamp a sanitized error reason (Tool execution cancelled by user / Tool execution failed) so trace backends can distinguish the two without cross-referencing the parent. 3. loggingContentGenerator test mock missing API_CALL_ABORTED_SPAN_STATUS_MESSAGE — production code imports it; Vitest returned undefined and quietly masked the abort branch in tests. 4. Stream idle timeout vs api_response success log — when the 5-min idle timeout closes the LLM span as failed, skip the post-loop safelyLogApiResponse / safelyLogOpenAIInteraction / addModelOutputAttributes so telemetry doesn't carry a "success" api_response log alongside a timed-out span. Closes #4212. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): address #4302 review — catch-path gating, exec span cancelled status, sync tags Four follow-ups from the #4302 review on top of the Phase 1.5 polish: 1. loggingContentGenerator.ts catch block — gate safelyLogApiError + safelyLogOpenAIInteraction on !spanEndedByTimeout. The success path was gated in the original PR but the error path wasn't, so a downstream throw after idle timeout would still emit api_error alongside a timed-out span — the same contradictory-telemetry pair the timeout fix targets. 2. endToolExecutionSpan now accepts a `cancelled` discriminator. Without it, success: false unconditionally sets SpanStatusCode.ERROR while the parent tool span uses setToolSpanCancelled (UNSET) — child shows ERROR, parent shows cancelled, trace backends filtering for errors false-positive on user cancels. Cancelled exec spans now keep status UNSET like the parent while still recording success: false / error reason attributes. 3. coreToolScheduler.ts catch block now snapshots signal.aborted into a local `aborted` constant and passes it through endToolExecutionSpan + the if-branch — same idiom as the success path (#4212), eliminating the divergent style. 4. SYNC tags on tracer.ts:getParentContext and session-tracing.ts: resolveParentContext so future drift between the two parent-resolution paths surfaces in grep before it flattens the trace tree. Tests: - session-tracing.test.ts — endToolExecutionSpan cancelled: true keeps status UNSET; sanity check that the non-cancelled path still maps success: false to ERROR. - coreToolScheduler.test.ts — extends the live-output cancellation test and the catch-after-abort test to assert cancelled: true; updates the success/failed-result tests to expect cancelled: false; adds a cancelled-stays-falsy-on-real-exception test. - loggingContentGenerator.test.ts — new test that fires the idle timeout then throws downstream and verifies neither logApiError nor logInteraction fires. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code)
6 tasks
doudouOUC
added a commit
that referenced
this pull request
May 21, 2026
…4321) * feat(telemetry): Phase 2 — tool.blocked_on_user + hook spans Adds two OTel span types under the existing hierarchical session-tracing infrastructure (#3731 Phase 2; depends on Phase 1 #4126 and Phase 1.5 #4302): 1. `qwen-code.tool.blocked_on_user` — brackets the time a tool spends in awaiting_approval waiting for the user. Child of the tool span. Records decision (proceed_once / proceed_always / cancel / aborted / auto_approved) and source (cli / ide / hook / auto / system). Status stays UNSET — waiting is neither OK nor ERROR. 2. `qwen-code.hook` — wraps each pre/post-hook fire site so a slow hook can be told from a slow tool. Records hook_event (PreToolUse / PostToolUse / PostToolUseFailure), tool_name, shouldProceed, shouldStop, blockType, hasAdditionalContext. Status stays UNSET on intentional blocking decisions; ERROR only when the hook itself throws. To make blocked_on_user a child of the tool span, the tool span lifecycle moved from `executeSingleToolCall` to `_schedule`'s validating-loop — covering validating → awaiting_approval → executing in one span. Two new private Maps on CoreToolScheduler hold span refs across method boundaries (callId-keyed). Centralized cleanup via `finalizeToolSpan` / `finalizeBlockedSpan` private helpers ensures every terminal status path also ends the corresponding span. Eight terminal sites now finalize the tool span: signal.aborted at loop entry, hard deny, plan-mode block, non-interactive deny, permission-hook deny, background-agent deny, _schedule catch, executeSingleToolCall finally. Five blocked_on_user end sites: handleConfirmationResponse cancel and proceed branches, autoApproveCompatiblePendingTools, _schedule catch under signal.aborted, and the global-error catch. ModifyWithEditor stays inside one blocked_on_user span until the final proceed/cancel — the duration_ms reflects total user think-time including editor side trips. Six hook fire sites are wrapped: firePreToolUseHook, firePostToolUseHook, and four safelyFirePostToolUseFailureHook variants (success-path interrupt, toolResult.error path, catch-path interrupt, catch-path real exception). fireNotificationHook is intentionally NOT wrapped — it's fire-and-forget and the duration is meaningless. Mirrors claude-code's session-tracing pattern but deliberately diverges on one point: every end-helper takes the span object explicitly via `getSpanId(span)` lookup instead of `findLast`-by-type. Under concurrent tool calls, claude-code's findLast can end the wrong blocked span; passing the ref directly is concurrency-safe. Tests: - session-tracing.test.ts: 11 new tests covering parent resolution (explicit parent for blocked_on_user, ALS-based for hook), idempotent end, NOOP behavior, error-status mapping, and a concurrency regression test (two parallel blocked spans ended in reverse order). - coreToolScheduler.test.ts: mock extended with the four new helpers and two new metadata fields. New tests cover the tool span outliving a pre-hook deny path, blocked_on_user ending with cancel via the awaiting_approval flow, hook span recording shouldProceed=false / blockType='denied' on pre-hook block and shouldStop=true / blockType='stop' on post-hook stop, and a leak guard that asserts every recorded lifecycle span is ended after a successful tool call. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): address #4321 review — Copilot inline + code-reviewer + silent-failure-hunter Eight discrete fixes plus two new tests, all surfaced in the Phase 2 review rounds. Grouped here because they touch the same handful of code paths. Copilot inline (#4321 PR): 1. startToolSpan attrs naming: drop redundant `tool_name` (helper already sets `'tool.name'` from the first arg) and rename `call_id` to the namespaced `'tool.call_id'`. Two sites: `_schedule` validating-loop start, and the defensive fallback in executeSingleToolCall. Without this, traces emit non-namespaced `tool_name` / `call_id` attributes that consumers grepping for `tool.call_id` miss. 2. PreToolUse hook span: propagate the actual `preHookResult.blockType` ('denied' / 'ask' / 'stop') instead of collapsing every block to 'denied'. Also record `hasAdditionalContext` for parity with the PostToolUse / failure-hook spans. 3. blocked_on_user `source` detection: use `config.getIdeMode()` (best- effort) so IDE-driven decisions don't all show up as `'cli'`. Centralized in a new `getBlockedSource()` helper. silent-failure-hunter / code-reviewer: 4. Hook span error-tracking is dead code. firePreToolUseHook / firePostToolUseHook / safelyFirePostToolUseFailureHook all swallow throws internally — every `catch (e) { endMeta = { error, ... }; throw e }` block in the scheduler was unreachable. Simplify all 6 sites to `try { ... } finally { endHookSpan(...) }`. The default `endMeta = { success: false }` keeps the span sensible if a future hook impl decides to throw. 5. handleConfirmationResponse had no error handling. modifyWithEditor / _applyInlineModify / attemptExecutionOfScheduledCalls can throw and would otherwise leak both the tool span and the blocked_on_user span until the 30-min TTL fires. Wrap the body in a try/catch that finalizes both spans on rethrow. Extracted the body to `_handleConfirmationResponseInner` for clarity. 6. Add `'error'` to the `ToolBlockedDecision` union for system-error closes, so dashboards counting `decision: 'cancel'` don't get polluted by thrown exceptions. 7. _schedule's outer catch was labelling its non-aborted close as `'cancel'`. Switch to `'error'` (uses #6). 8. signal.aborted vs explicit user Cancel: when both are true, the old code reported `'aborted'/'system'` even though the user actually clicked Cancel. Reverse the precedence so `outcome === Cancel` wins, with `getBlockedSource()` for the source. Tests: - T1: extend the existing ProceedAlways auto-approve test to assert the two siblings' blocked spans end with `decision: 'auto_approved'`, `source: 'auto'`, while the first tool ends as `'proceed_always'`/cli. - T2: existing cancel-during-confirmation test now also asserts exactly one blocked span is recorded for the lifecycle — the same invariant ModifyWithEditor's intentional preservation across editor side trips must not break. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): close autoApprove blocked-span leak + cover three new behaviors Two follow-ups from the post-#6767469b2 review pass on PR #4321: 1. autoApproveCompatiblePendingTools error path was logging-only and leaving the sibling tool's blocked_on_user span open until the 30-min TTL fires. Symmetric with the success branch's finalizeBlockedSpan('auto_approved', 'auto'), the catch now finalizes with ('error', 'system') so the trace deterministically explains why the sibling didn't auto-approve. 2. Three behaviors introduced by 6767469 had no test coverage: - decision='error' from _schedule's outer catch when getConfirmationDetails throws (asserts tool span ends, no blocked span ever opens since the throw happens pre-awaiting_approval). - source='ide' when getBlockedSource() honors getIdeMode (Cancel path with getIdeMode: () => true). - Explicit Cancel takes precedence over a concurrent signal.aborted in the decision label — the bug the precedence flip was meant to fix is now regression-tested. Extracted a small `buildApprovalScheduler` helper for the two awaiting_approval-flow tests; the throw-on-confirmation test reuses StructuredErrorOnConfirmationTool. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): revert autoApprove catch finalizeBlockedSpan (#4321 codex P3) The previous commit 32f94d3 added a `finalizeBlockedSpan(callId, 'error', 'system')` to the autoApproveCompatiblePendingTools catch in the name of "symmetry with the success branch". Codex review pointed out the bug: that catch fires when evaluatePermissionFlow throws for a SIBLING tool, but the sibling itself is still in `awaiting_approval` — the user can still respond. By closing the blocked span at the catch, the eventual handleConfirmationResponse → finalizeBlockedSpan call becomes a no-op (Map.delete already cleared it), and the user's actual decision / source attributes are lost from the trace. Revert that line. The previous behavior was correct: log the error, leave the span open, let the user's eventual decision close it correctly. If the user never responds, the 30-min TTL in session-tracing.ts cleans up the orphan span — same fallback that already covered every other "user walks away" scenario. The "leak" the original change was trying to fix was a phantom: the span IS finalized once the user (or the abort signal) drives the tool to a terminal state. The TTL is just the safety net. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): split tool.failure_kind labels + cover proceed_once decision Two #4321 review comments from wenshao, both Critical: 1. `TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED` was being emitted for FIVE distinct non-PreToolUse-hook deny paths in `_schedule`: - finalPermission === 'deny' (hard deny) - plan-mode block - non-interactive deny - permission_request hook deny - background-agent deny Dashboards filtering by `failure_kind = 'pre_hook_blocked'` were silently picking up all of these, undermining the attribute. Add distinct constants + status messages for each path. The original PRE_HOOK_BLOCKED label is now used at exactly one site — the actual PreToolUse hook deny in `_executeToolCallBody`. 2. `decision: 'proceed_once'` was untested. Existing tests covered 'cancel' and 'proceed_always' (auto-approve) but not the most common user interaction. Add a test that schedules an approval-required tool, confirms with ProceedOnce, and asserts the blocked span ends with `decision: 'proceed_once'`, `source: 'cli'`. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): address #4321 wenshao Critical + bot summary nits Three review items folded into one follow-up: 1. wenshao Critical (`coreToolScheduler.ts:1851`) — `ModifyWithEditor` path silently returned when `getPreferredEditor()` was undefined, leaking blocked + tool spans on user-walks-away. Add a `debugLogger.warn` so the silent failure is at least visible in debug telemetry. Deliberately do NOT finalize spans here, matching the Codex P3 / autoApprove decision: ModifyWithEditor stays inside one awaiting period, the user can still recover via Cancel/Proceed which closes the spans correctly, and the 30-min TTL is the safety net for give-up scenarios. Finalizing prematurely would make the user's eventual decision a no-op (Map already cleared) and lose the actual decision/source attributes. 2. Bot summary Medium (`session-tracing.ts:557-562`) — add a `debugLogger.debug` when `startToolBlockedOnUserSpan` falls back to `resolveParentContext` because the tool span isn't in `activeSpans` anymore. Helps diagnose unexpected ordering during development. 3. Bot summary Low (`constants.ts`) — JSDoc the two new span name constants. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * refactor(telemetry): extract withHookSpan helper + drop dead finalizeToolSpan param Two #4321 review Suggestions from wenshao: 1. The 6 hook fire sites (PreToolUse, PostToolUse, 4× PostToolUseFailure) each repeated the same try/finally + endMeta init + endHookSpan pattern. Future hook span protocol changes had to be made in lockstep. Extract a private generic helper: withHookSpan<T>(opts, fn, toEndMeta): Promise<T> Each fire site collapses from ~12 lines of try/finally scaffolding to ~3 lines passing in the fire callback + endMeta builder. The `let postHookResult!:` definite-assignment hack at the PostToolUse site is gone because the helper returns the awaited result directly. 2. `finalizeToolSpan(callId, metadata?)` had a dead `metadata` parameter — every caller pre-sets the span status via `setToolSpan{Failure,Cancelled}` and called `finalizeToolSpan` with no argument. Removed the parameter. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): hook span error tracking + TTL cleanup safety + call_id back-compat Three #4321 review threads from wenshao (#4321 codex P3-equivalent + two structural concerns): 1. **[Critical] Hook spans reported success on swallowed hook failures.** firePreToolUseHook / firePostToolUseHook / firePostToolUseFailureHook (and the safelyFire wrapper in coreToolScheduler) all catch transport / dispatch errors internally and return safe defaults. Before this fix, withHookSpan's `toEndMeta` ran on the safe default and recorded `success: true` — a crashing hook was indistinguishable from one that allowed execution. Add a `hookError?: string` field to the three result types, populate it in each catch, and have all 6 toEndMeta callbacks return `{ success: false, error: hookError }` when present. Existing "graceful error" tests updated to expect the new field. 2. **[Suggestion] ensureCleanupInterval not kicked from new helpers.** The 30-min TTL cleanup safety net for leaked spans only starts when `startInteractionSpan` is first called. Sub-agent or side-query code paths that call `startToolBlockedOnUserSpan` / `startHookSpan` without an interaction span first never trigger cleanup. Both helpers now call the (idempotent) `ensureCleanupInterval()` early. 3. **[Suggestion] `call_id` → `'tool.call_id'` rename is breaking for downstream consumers.** Phase 1's `startToolSpan(name, { tool_name, call_id })` shipped non-namespaced attribute keys. My Phase 2 #4321 review-fix dropped both. Dual-emit `call_id` (legacy alias) + `'tool.call_id'` for one release cycle so existing dashboards / alerts don't silently return zero. Comment notes the legacy key is removed in the next release. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): close hookError plumbing gaps from final pre-merge audit Final-pass review surfaced two gaps in the hookError contract added in eafe688: 1. **Real bug (silent-failure-hunter HIGH)**: The three fire helpers (firePreToolUseHook / firePostToolUseHook / firePostToolUseFailureHook) populate `hookError` only in their catch blocks. But the `if (!response.success || !response.output)` short-circuit at lines 121 / 220 / 299 silently dropped `response.error` from the runner layer (URL validation failures, fn exceptions, prompt-runner crashes). Hooks that never even threw — just had a failing runner — surfaced as "successful allow" in telemetry. Forward `response.error?.message` into hookError on the short-circuit path so the operator sees the actual cause. 2. **Defensive default in withHookSpan**: the initial `endMeta = { success: false }` produced UNSET status (no `error` field, so endHookSpan skips the setStatus(ERROR) branch). Today the only path that hits this default is "fn() throws before toEndMeta", which is unreachable because all hook helpers catch internally — but the contract should still map to ERROR if the invariant ever changes. Default now carries an explanatory error string. Test: new `coreToolScheduler.test.ts` case where messageBus.request resolves with success:false + a real Error; asserts the PreToolUse hook span's `hookMetadata.error` is the runner's message (instead of being silently absent). 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * test(telemetry): cover #4321 rethrow path + 2 of the new failure_kind labels Two test gaps surfaced by wenshao [Suggestion] threads: 1. **handleConfirmationResponse outer catch was untested.** The defensive recovery path that finalizes both spans on originalOnConfirm / modifyWithEditor / attemptExecution throws had no coverage. New test calls handleConfirmationResponse directly with a throwing onConfirm, asserts: - blocked span ends with `decision: 'error'`, `source: 'system'` - tool span carries `tool.failure_kind: 'tool_exception'` - the original error is rethrown to the caller 2. **5 new permission-flow failure_kind labels had zero coverage.** Add representative tests for the two highest-volume paths: - `permission_denied` — PM hard-deny via a tool whose getDefaultPermission returns 'deny' - `non_interactive_denied` — `isInteractive: () => false` scheduling an edit-tool that needs confirmation The other three (plan_mode_blocked / permission_hook_denied / background_agent_denied) are covered transitively via the existing pre_hook_blocked + plan-mode tests; if they regress, the same code path's existing assertions would notice. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 4 wenshao Critical/Suggestion findings on PR #4321 Inline review findings: - coreToolScheduler.ts: signal.abort drains scheduler-local toolSpans/blockedSpans Maps via deferred setTimeout(0) — bridges the gap between session-tracing's 30-min TTL (which ends underlying spans but cannot reach the Maps) and walk-away-during-awaiting_approval. The drain is deferred so explicit Cancel via handleConfirmationResponse and mid-execution setToolSpanCancelled paths still win the race and set canonical labels. - coreToolScheduler.test.ts: regression test for permission_hook_denied (firePermissionRequestHook deny branch at _schedule:1683) and background_agent_denied (getShouldAvoidPermissionPrompts auto-deny at _schedule:1697). Both branches were untested — silently dropping setToolSpanFailure on either would lose attribution. - coreToolScheduler.ts: defensive-fallback span in executeSingleToolCall uses canonicalToolName(toolName) so dashboards grouping by span name don't see two entries for migrated/MCP tools whose canonical and raw names differ. Review-body finding: - session-tracing.ts: TTL safety net stamps qwen-code.span.ttl_expired + qwen-code.span.duration_ms attributes and emits a debug log before ending stale spans. Operators can now distinguish "abandoned and garbage-collected by the safety net" from "deliberately ended without status/attrs". Refactored cleanup loop into sweepStaleSpans(now) and exposed runTTLSweepForTesting for unit coverage. Tests: +3 scheduler tests (~220 LOC), +2 session-tracing tests (~36 LOC). 247/247 in affected files. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 7 DeepSeek /review findings on PR #4321 Adopted ([Critical]): - coreToolScheduler.ts: ModifyWithEditor `!editorType` path now sets `qwen-code.tool.modify_with_editor_unavailable: true` on the live tool span so operators can detect the silent-bail-out state in production traces without enabling debug logging. - coreToolScheduler.test.ts: regression test for plan_mode_blocked failure_kind path (ApprovalMode.PLAN + non-read-only confirmation tool). - coreToolScheduler.test.ts: regression test for the pre-aborted signal early-exit in `_schedule` — asserts setToolSpanCancelled (UNSET status) without entering execution. Adopted ([Suggestion]): - coreToolScheduler.ts: `withHookSpan` now `catch`-es and surfaces the actual thrown message instead of the hardcoded `'hook fn threw before toEndMeta'` sentinel. Currently unreachable (hook helpers swallow internally) but defensive against contract drift. - coreToolScheduler.ts: re-add `tool_name` (non-namespaced) as a legacy alias on both startToolSpan call sites, mirroring the `call_id` / `tool.call_id` dual-emit window so pre-Phase-2 dashboards filtering on `tool_name` don't silently stop matching during the rollout. - coreToolScheduler.test.ts: regression test for the `_schedule`-driven aborted decision label on the blocked_on_user span (companion to the existing tool-span drain test). - coreToolScheduler.ts: PreToolUse / PostToolUse `toEndMeta` now include `shouldProceed: true` / `shouldStop: false` when `hookError` is set, mirroring the runtime's allow-on-hook-failure semantics. Pushed back (separate PR-level reply): - "sibling failure prematurely closes confirmed tool span" — not reachable: `_executeToolCallBody` swallows execution errors so the only paths into `handleConfirmationResponse`'s catch are `originalOnConfirm` / `modifyWithEditor` / `_applyInlineModify`, none of which run after `attemptExecutionOfScheduledCalls` started any sibling. - "PostToolUseFailure hook spans not asserted" — broader scope, defer. - "finalizeToolSpan accept required metadata" — invariant-redesign, out of scope for this PR. Tests: +3 scheduler tests; 250/250 green in affected files (coreToolScheduler 154 + session-tracing 49 + toolHookTriggers 47). 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 3 wenshao /review findings on PR #4321 - coreToolScheduler.ts: handleConfirmationResponse outer catch now branches on signal.aborted — a throw caused by the abort signal (e.g. ModifyWithEditor child interrupted by Ctrl+C) lands as decision:'aborted'/UNSET status instead of 'error'/tool_exception, matching the sister catch in `_schedule` and keeping dashboard abort-vs-error counts honest (Critical-shaped Suggestion). - coreToolScheduler.ts: drop the per-batch abort listener at the end of `_schedule` when no batch entries remain in toolSpans / blockedSpans. Prevents Node's MaxListenersExceededWarning in long-lived sessions where the same AbortSignal sees many _schedule batches without a real abort. Listeners that still cover awaiting_approval entries stay attached — the user's eventual decision closes the spans, and the listener becomes a no-op when it later fires (or auto-removes via `{ once: true }` on real abort). - coreToolScheduler.test.ts: 2 regression tests for PostToolUseFailure hook span variants — `is_interrupt:true` on user-abort vs `is_interrupt:false` on real-exception. Operators rely on this flag to separate user-initiated cancellations from system errors in dashboards; a copy-paste regression flipping the value across the 4 PostToolUseFailure call sites was previously invisible. Tests: 252/252 across affected files (coreToolScheduler 156 + session-tracing 49 + toolHookTriggers 47). 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 7 wenshao /review round-3 findings on PR #4321 Adopted ([Critical]): - coreToolScheduler.ts: full per-batch abort listener cleanup. Replaced the closure-local Set + end-of-_schedule cleanup with a class-level callIdToBatch Map keyed off a shared BatchAbortState. The listener is now released by `finalizeToolSpan` → `releaseBatchListenerIfDrained` whenever the last live batch entry drains, regardless of whether finalize happens synchronously inside _schedule, later via handleConfirmationResponse, or via executeSingleToolCall. Closes the awaiting_approval-batches-leak-listeners gap from the previous partial fix. - coreToolScheduler.ts: re-check signal.aborted in the _schedule for-loop after `evaluatePermissionFlow`/`getConfirmationDetails`/ `firePermissionRequestHook` and BEFORE setting awaiting_approval + starting the blocked span. Without this, a signal that aborts during one of those awaits opens a blocked span on an already-aborted signal whose drainSpansForBatch may have already fired, leaving the new entry permanently orphaned. - session-tracing.ts: introduce truncateSpanError(s) (1KB cap) and apply it to every endXSpan site that writes metadata.error to span attributes / status messages (LLM, tool, tool execution, hook). Hook server responses, raw exception stacks, or hostile inputs can be unbounded; some OTel backends drop the entire span when any field exceeds their limit. Adopted ([Suggestion]): - coreToolScheduler.ts: per-callId try/catch inside drainSpansForBatch. One bad finalize no longer skips the rest of the batch; failures are logged via debugLogger.warn instead of bubbling up as an unhandled timer-callback exception. - session-tracing.ts: TTL sweep robustness — wraps setAttributes and span.end() in separate try/catch blocks so a setAttributes throw can't leak the OTel span; stamps `decision: 'aborted'`/ `source: 'system'` on TTL-expired blocked_on_user spans so dashboards filtering by decision count walk-aways consistently with explicit user aborts; includes tool.name + tool.call_id in the warn log so it's actionable in production without a trace-backend lookup. - coreToolScheduler.ts: extract the 4 byte-identical PostToolUseFailure toEndMeta lambdas into a single `postToolUseFailureEndMeta` member. Future protocol changes only need to touch one place. - coreToolScheduler.test.ts: 3 new tests * outer-catch aborted branch — pre-aborted signal + throwing onConfirm asserts decision='aborted'/source='system' and failure_kind='cancelled'. * ModifyWithEditor !editorType — uses a getModifyContext-shimmed MockEditTool to enter the modifiable branch and asserts qwen-code.tool.modify_with_editor_unavailable=true. * per-batch listener removed when batch drains synchronously — asserts AbortSignal listenerCount and `callIdToBatch` size. Pushed back (deferred): - "firePermissionRequestHook in withHookSpan + hookError field" — same as previous deferral. Touches the public PermissionRequestHookResult type re-exported from packages/core/src/index.ts; declined per the guardrail on public-API changes. Tests: 255/255 across affected files (coreToolScheduler 159 + session-tracing 49 + toolHookTriggers 47). 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): polish 2 wenshao /review round-4 nits on PR #4321 - session-tracing.ts: rename `SPAN_ERROR_MAX_BYTES` → `SPAN_ERROR_MAX_CHARS` and update the JSDoc to be honest that `truncateSpanError` truncates by UTF-16 code units rather than bytes. CJK/emoji-heavy errors land in the ~2-3KB UTF-8 range under the same code-unit cap, but that's still well under all major OTel backends' per-attribute limits (Jaeger/Honeycomb ~64KB, OTLP default ~32KB), so we keep the simpler char-count bound rather than paying the encoder cost on every endXSpan. - coreToolScheduler.ts: move the `withHookSpan` JSDoc block to sit directly above the method. The previous order had two consecutive JSDoc blocks separated by `postToolUseFailureEndMeta`, which orphaned the `withHookSpan` doc — IDE hover tooltips would surface the wrong documentation. Tests: 208/208 in affected files; tsc --noEmit clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 4 wenshao /review round-5 findings on PR #4321 Adopted ([Suggestion]): - coreToolScheduler.ts: `setToolSpanFailure` now applies `truncateSpanError` to the status message at this single ingress point. Many of its 10+ call sites pass raw `error.message` which can be unbounded — the same backend-drop risk that drove `truncateSpanError` for the endXSpan attribute writes. Static- constant callers see no change since their messages are well under the 1024-char cap. Required exporting `truncateSpanError` from `session-tracing.ts` and re-exporting from `telemetry/index.ts`. - coreToolScheduler.ts: in `_schedule`, after the for-loop runs to completion, drop the abort listener if `batchState.callIds.size === 0`. Closes the all-error-batch leak path: if every newToolCall had `status !== 'validating'` (e.g., invalid params, tool not registered, queue full), no `finalizeToolSpan` ever fires for the batch and `releaseBatchListenerIfDrained` is never invoked. Without this drop, one dead listener accumulates per all-error batch. - coreToolScheduler.ts: `handleConfirmationResponse` outer catch now emits a `debugLogger.warn` before rethrowing. Without it, if the caller (CLI confirmation UI layer) doesn't log the rejection, the error disappears from application logs entirely — operators grepping by callId would see nothing despite the trace backend showing `failure_kind: tool_exception`. - session-tracing.test.ts: 4 new tests * `truncateSpanError` returns short strings unchanged * `truncateSpanError` truncates over 1024 chars + appends sentinel * `truncateSpanError` boundary at exactly 1024 chars * TTL sweep stamps `decision: 'aborted'` + `source: 'system'` on blocked_on_user spans (covers the branch added in review-3 round) Pushed back ([Suggestion]): - "TTL sweep can't reach scheduler-local Maps" — accurate but the fix is non-trivial: a parallel scheduler-side TTL sweep duplicates the session-tracing sweep's bookkeeping, and the practical impact is bounded (Maps die with the scheduler instance, which is per-session in CLI mode). The bigger leak (listener accumulation on shared signals) is already covered by `releaseBatchListenerIfDrained`. Marking as out-of-scope architectural follow-up. Tests: 259/259 across affected files (coreToolScheduler 159 + session-tracing 53 + toolHookTriggers 47). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 1 wenshao /review round-6 finding on PR #4321 - coreToolScheduler.test.ts: convert the `truncateSpanError` mock from an inline identity function to `vi.fn(identity)` so individual tests can substitute a sentinel return. Added regression test `setToolSpanFailure forwards the truncateSpanError result to the span status (#4321)` that overrides the spy with `<<TRUNCATED-SENTINEL>>`, drives the scheduler through the pre-hook deny path, and asserts the span's ERROR status message equals the sentinel — locks the integration so a regression dropping the `truncateSpanError(message)` call inside `setToolSpanFailure` is caught at the scheduler boundary rather than only at the utility's unit test. Tests: 213/213 across `coreToolScheduler.test.ts` (160) + `session-tracing.test.ts` (53). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): close 4 silent-failure + test-gap findings from final review on PR #4321 Comprehensive self-review (code-reviewer + silent-failure-hunter + type-design-analyzer + pr-test-analyzer agents) after 6 rounds of bot feedback turned up 4 remaining actionable items. Addressed: [silent-failure-hunter HIGH-1] toolHookTriggers.ts: when the hook runner returns `{ success: false }` (or missing output) with no `error.message`, the 3 fire helpers used to silently return the safe default — `{ shouldProceed: true }` / `{ shouldStop: false }` / `{}` — producing a hook span that reads `success: true` and looked like a clean allow in dashboards. Now synthesizes a sentinel hookError describing the contract violation so the span records the failure. Three existing test cases updated to assert the new sentinel-bearing shape. [silent-failure-hunter HIGH-2] coreToolScheduler.ts: synchronous throws in `_executeToolCallBody`'s prelude (addToolInputAttributes, getMessageBus, startToolExecutionSpan, etc.) propagated up to `executeSingleToolCall`'s `finally` without ever hitting setToolSpan*, so the tool span ended UNSET with no failure_kind AND the tool call stayed in 'executing' forever (checkAndNotifyCompletion never sees terminal state, scheduler hangs). Added a catch in executeSingleToolCall that pre-sets failure status + an error response before the finally finalizes — guards every prelude path the body's own try/catch doesn't cover. [silent-failure-hunter MEDIUM-3] session-tracing.ts: the empty catch on `sweepStaleSpans` `setAttributes` lost the `ttl_expired` + `decision: 'aborted'` sentinel attrs silently if setAttributes ever threw. Now matches the sibling `span.end()` catch and surfaces via `debugLogger.warn` — TTL-leaked blocked spans stay distinguishable from deliberately-UNSET ones in dashboards. [pr-test-analyzer Gap1, severity 7] coreToolScheduler.test.ts: the `signal.aborted` re-check at `_schedule:1834` (round-3 fix that prevents opening a blocked span on an already-aborted signal between the for-loop's await points and the awaiting_approval transition) had no regression test. Added one that uses a tool whose `getConfirmationDetails` aborts the signal before returning — top of loop check passes, getConfirmationDetails resolves and aborts, re-check fires the cancel path. Asserts `tool.failure_kind === 'cancelled'` AND that NO blocked_on_user span was ever started. Tests: 261/261 across affected files (coreToolScheduler 161 + session-tracing 53 + toolHookTriggers 47). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 3 wenshao /review round-8 findings on PR #4321 All three from the same /review run; all valid (the Critical is a real bug in the SF-H2 fix from review-7 that this commit fixes). [Critical] coreToolScheduler.ts:2407 — the `c.status === 'executing'` guard on the prelude-throw catch was wrong. Prelude throws happen BEFORE the `scheduled → executing` transition in `_executeToolCallBody` (getMessageBus is called at line 2460, scheduled→executing flips at line 2522). The `find(... 'executing')` skipped the setStatusInternal, so the toolCall stayed in `scheduled` forever and checkAndNotifyCompletion never fired — exactly the stall the SF-H2 fix was supposed to prevent. Drop the guard; setStatusInternal already no-ops on terminal states (success/error/cancelled) so the unconditional call covers both scheduled-prelude and executing-body paths. Added regression test that makes getMessageBus throw and asserts onAllToolCallsComplete fires with status='error'. [Suggestion] session-tracing.ts:222 — truncateSpanError used `slice(0, 1024)` on UTF-16 code units, which splits surrogate pairs when an emoji (e.g. 🚀) or rare CJK character sits at the boundary. The result was a lone high surrogate followed by `'…[truncated]'` — strict OTLP/gRPC collectors reject batches with invalid UTF-8 (a lone high surrogate encodes to an invalid byte sequence). Back up one code unit when the cut lands on a high surrogate. Added regression test that constructs the boundary case (1023 'a' + 🚀 + padding) and asserts the truncated string is valid UTF-16. [Suggestion] toolHookTriggers.ts:133/240/319 — switched `||` to `??` in the 3 hookError sentinel sites. `||` treats empty string as falsy so a runner returning `{ error: { message: "" } }` triggered the sentinel instead of preserving the (unhelpful but distinct) empty message — a runner contract violation that's worth distinguishing from a missing-message case. `??` synthesizes only when the message is truly absent (undefined / null). Tests: 263/263 across affected files (coreToolScheduler 162 + session-tracing 54 + toolHookTriggers 47). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * fix(telemetry): adopt 3 wenshao /review round-9 findings on PR #4321 [Critical] coreToolScheduler.ts — `handleConfirmationResponse`'s catch was misattributing sister-tool prelude throws to the confirmed tool's span. The catch wrapped `_handleConfirmationResponseInner`, which called `attemptExecutionOfScheduledCalls` at its tail. If the user proceeds tool A with ProceedAlways, `autoApproveCompatiblePendingTools` transitions sister tools B/C to `scheduled`, and B has a prelude throw, the SF-H2 catch in `executeSingleToolCall` re-throws → the throw propagates up through `attemptExecutionOfScheduledCalls` → into the outer catch keyed on A.callId, where `setToolSpanFailure(A.span, TOOL_EXCEPTION, B.error.message)` corrupts A's span and `finalizeToolSpan(A.callId)` ends A's span prematurely. A's actual result later disappears from telemetry. Fix: move `attemptExecutionOfScheduledCalls` out of `_handleConfirmationResponseInner` and into `handleConfirmationResponse` after the try/catch. The catch now covers only confirmation logic; each tool's `executeSingleToolCall` already handles its own span lifecycle via its own catch. [Suggestion] toolHookTriggers.ts — reverted the round-8 `??` change back to `||`. Downstream consumers in coreToolScheduler.ts gate on `r.hookError ? ...`, so an empty-string `hookError` preserved by `??` was silently dropped — the change defeated its own stated intent. Empty-string runner error messages carry no operator value; the sentinel ("hook runner returned ... without error detail") is more actionable, and `||` matches existing downstream truthiness semantics. [Suggestion] session-tracing.test.ts — replaced the vacuous `Buffer.from(truncated, 'utf16le')` assertion (which never throws because Node's Buffer copies raw 16-bit code units without validating surrogate pairs) with the suggested regex `/[\uD800-\uDBFF](?![\uDC00-\uDFFF])/` that actually checks for orphan high surrogates anywhere in the string. Tests: 263/263 across affected files (coreToolScheduler 162 + session-tracing 54 + toolHookTriggers 47). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) * test(telemetry): pin empty-string runner error sentinel behavior on PR #4321 [Suggestion] gpt-5.5 review-10: the round-9 `??` → `||` revert was correct, but the existing tests only covered the missing-error case (`success: false` with no `error` field). A future regression back to `??` would still pass those tests while reintroducing the silent-drop behavior the revert was guarding against. Add 3 explicit tests — one per fire helper (PreToolUse, PostToolUse, PostToolUseFailure) — that pass `{ error: { message: '' } }` and assert the sentinel hookError is synthesized (not the empty string). Pins the `||` semantics so any future `??` change fails the suite. Tests: 50/50 in toolHookTriggers.test.ts (47 → 50). `tsc --noEmit` clean. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code)
This was referenced May 21, 2026
Closed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Replaces disconnected
withSpan/startSpanWithContextcalls in runtime with session-tracing typed helpers, fixing the trace tree so LLM and tool spans become children of the interaction span instead of siblings under the session root.Before (flat — all spans are siblings):
After (hierarchical — proper parent-child):
Key changes
session-tracing.ts: AddtoolContextALS withrunInToolSpanContext()for concurrent-safe tool span scoping (usesAsyncLocalStorage.run, notenterWith); changestartToolExecutionSpanto read parent fromtoolContext; fixendToolSpanto not override pre-set status when metadata is omitted (documented via JSDoc); adddebugLogger.warnin allend*Spancatch blocks for OTel error visibility; warn whenstartToolExecutionSpancalled outsiderunInToolSpanContextloggingContentGenerator.ts: WirestartLLMRequestSpan/endLLMRequestSpanfor both streaming and non-streaming paths, replacingwithSpan/startSpanWithContext; integrate upstreamspanEndTimeoutidle mechanism withendLLMRequestSpanidempotency; addllm_request.streamattribute to distinguish streaming vs non-streamingcoreToolScheduler.ts: WirestartToolSpan/endToolSpan+startToolExecutionSpan/endToolExecutionSpanwithtry/finallylifecycle; extract_executeToolCallBodyfor clean span scoping; sanitize error inendToolExecutionSpan(use constant instead of raw message); set OK status in success path viasafeSetStatusclient.ts: Remove redundantwithSpan('client.generateContent')wrapper (LLM span now created in loggingContentGenerator); preserve abort error propagationsession-tracing.jsdirectly for reliable interception; addtoolContextALS scoping testsdocs/design/workflow-tracing-gaps.mdwith full gap analysis and Phase 1-3 roadmapPart of #3731 (P3 Deeper observability — Phase 1)
Phase 1 focuses on unifying span creation paths. Phase 2 (blocked_on_user + hook spans) and Phase 3 (subagent trace tree) tracked in the parent issue.
Phase 1.5 follow-ups → #4212
Non-blocking polish items from late review rounds (parent fallback order, exec span on abort-as-result, mock missing constant, idle timeout vs API log inconsistency) are tracked in #4212 — none of these affect the trace tree this PR fixes.
Test plan
npx vitest run packages/core/src/telemetry/session-tracing.test.ts— 23 tests passnpx vitest run packages/core/src/core/coreToolScheduler.test.ts— 119 tests passnpx vitest run packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts— 32 tests passnpx vitest run packages/core/src/core/client.test.ts— 104 tests passnpx tsc --noEmit— zero new type errorsE2E trace verification
rm -f /tmp/spans-test.jsonl QWEN_TELEMETRY_ENABLED=1 \ QWEN_TELEMETRY_OUTFILE=/tmp/spans-test.jsonl \ node packages/cli/dist/index.js --prompt "what is 2+2" --max-session-turns 1Verify parent-child relationships:
Actual output:
[ {"name":"qwen-code.llm_request","spanId":"a11e955e775f","parentSpanId":"1a88a402e766","status":2,"stream":false,"tool":null}, {"name":"qwen-code.llm_request","spanId":"b52fc1e4267d","parentSpanId":"1a88a402e766","status":1,"stream":true,"tool":null}, {"name":"qwen-code.interaction","spanId":"1a88a402e766","parentSpanId":"ROOT","status":1,"stream":null,"tool":null}, {"name":"qwen-code.llm_request","spanId":"e46925657044","parentSpanId":"1a88a402e766","status":1,"stream":true,"tool":null}, {"name":"qwen-code.tool.execution","spanId":"31c2ee6fb1f5","parentSpanId":"4709050c8523","status":1,"stream":null,"tool":null}, {"name":"qwen-code.tool","spanId":"4709050c8523","parentSpanId":"1a88a402e766","status":1,"stream":null,"tool":"read_file"}, {"name":"qwen-code.tool.execution","spanId":"7df917fb02cd","parentSpanId":"0ccbfe610d63","status":1,"stream":null,"tool":null}, {"name":"qwen-code.tool","spanId":"0ccbfe610d63","parentSpanId":"1a88a402e766","status":1,"stream":null,"tool":"read_file"}, {"name":"qwen-code.llm_request","spanId":"4c3ae4665b69","parentSpanId":"1a88a402e766","status":1,"stream":true,"tool":null} ]Expected trace tree (confirmed):
🤖 Generated with Qwen Code