mirror of
https://github.com/QwenLM/qwen-code.git
synced 2026-07-09 17:19:02 +00:00
* 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 by6767469b2had 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 commit32f94d348added 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 ineafe68820: 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 commit is contained in:
jinye
GitHub
parent
60d8ffae27
commit
b58fe19c3a
8 changed files with 3288 additions and 100 deletions
File diff suppressed because it is too large
Load diff
|
|
@ -95,8 +95,17 @@ import {
|
|||
runInToolSpanContext,
|
||||
startToolExecutionSpan,
|
||||
endToolExecutionSpan,
|
||||
startToolBlockedOnUserSpan,
|
||||
endToolBlockedOnUserSpan,
|
||||
startHookSpan,
|
||||
endHookSpan,
|
||||
addToolInputAttributes,
|
||||
addToolResultAttributes,
|
||||
truncateSpanError,
|
||||
type ToolBlockedDecision,
|
||||
type ToolBlockedSource,
|
||||
type StartHookSpanOptions,
|
||||
type HookSpanMetadata,
|
||||
} from '../telemetry/index.js';
|
||||
import { safeJsonStringify } from '../utils/safeJsonStringify.js';
|
||||
|
||||
|
|
@ -106,9 +115,26 @@ const TOOL_FAILURE_KIND_POST_HOOK_STOPPED = 'post_hook_stopped';
|
|||
const TOOL_FAILURE_KIND_TOOL_ERROR = 'tool_error';
|
||||
const TOOL_FAILURE_KIND_TOOL_EXCEPTION = 'tool_exception';
|
||||
const TOOL_FAILURE_KIND_CANCELLED = 'cancelled';
|
||||
// Approval-flow failure kinds — distinct from `pre_hook_blocked` (which
|
||||
// only applies to actual PreToolUse hook denials in `_executeToolCallBody`)
|
||||
// so dashboards can attribute denies to their real cause (#4321 review).
|
||||
const TOOL_FAILURE_KIND_PERMISSION_DENIED = 'permission_denied';
|
||||
const TOOL_FAILURE_KIND_PERMISSION_HOOK_DENIED = 'permission_hook_denied';
|
||||
const TOOL_FAILURE_KIND_PLAN_MODE_BLOCKED = 'plan_mode_blocked';
|
||||
const TOOL_FAILURE_KIND_NON_INTERACTIVE_DENIED = 'non_interactive_denied';
|
||||
const TOOL_FAILURE_KIND_BACKGROUND_AGENT_DENIED = 'background_agent_denied';
|
||||
|
||||
const TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED = 'Tool execution blocked by hook';
|
||||
const TOOL_SPAN_STATUS_POST_HOOK_STOPPED = 'Tool execution stopped by hook';
|
||||
const TOOL_SPAN_STATUS_PERMISSION_DENIED = 'Permission denied for tool';
|
||||
const TOOL_SPAN_STATUS_PERMISSION_HOOK_DENIED =
|
||||
'Permission denied by permission_request hook';
|
||||
const TOOL_SPAN_STATUS_PLAN_MODE_BLOCKED =
|
||||
'Plan mode blocked a non-read-only tool call';
|
||||
const TOOL_SPAN_STATUS_NON_INTERACTIVE_DENIED =
|
||||
'Non-interactive mode declined permission';
|
||||
const TOOL_SPAN_STATUS_BACKGROUND_AGENT_DENIED =
|
||||
'Background agent cannot prompt for confirmation';
|
||||
const TOOL_SPAN_STATUS_TOOL_ERROR = 'Tool execution failed';
|
||||
const TOOL_SPAN_STATUS_TOOL_EXCEPTION = 'Tool execution failed with exception';
|
||||
const TOOL_SPAN_STATUS_TOOL_CANCELLED = 'Tool execution cancelled by user';
|
||||
|
|
@ -146,9 +172,14 @@ function setToolSpanFailure(
|
|||
} catch {
|
||||
// OTel errors must not block the failure status update.
|
||||
}
|
||||
// Bound the status message size at this single ingress point so every
|
||||
// setToolSpanFailure caller is protected — multiple call sites pass
|
||||
// raw error.message which can be unbounded (#4321 review-5 wenshao
|
||||
// Suggestion). Static-constant callers see no change since their
|
||||
// messages are well under 1024 chars.
|
||||
safeSetStatus(span, {
|
||||
code: SpanStatusCode.ERROR,
|
||||
message,
|
||||
message: truncateSpanError(message),
|
||||
});
|
||||
}
|
||||
|
||||
|
|
@ -184,10 +215,11 @@ async function safelyFirePostToolUseFailureHook(
|
|||
permissionMode,
|
||||
);
|
||||
} catch (error) {
|
||||
const message = error instanceof Error ? error.message : String(error);
|
||||
debugLogger.warn(
|
||||
`PostToolUseFailure hook failed for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
|
||||
`PostToolUseFailure hook failed for ${toolName}: ${message}`,
|
||||
);
|
||||
return {};
|
||||
return { hookError: message };
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -695,6 +727,19 @@ interface ToolBatch {
|
|||
calls: ScheduledToolCall[];
|
||||
}
|
||||
|
||||
/**
|
||||
* State for the per-batch signal.abort listener registered in
|
||||
* `_schedule`. Shared by every callId in the batch so finalize hooks
|
||||
* can remove the listener once the last live entry drains, regardless
|
||||
* of whether finalization happens synchronously inside `_schedule`,
|
||||
* later via `handleConfirmationResponse`, or via `executeSingleToolCall`.
|
||||
*/
|
||||
interface BatchAbortState {
|
||||
signal: AbortSignal;
|
||||
onAbort: () => void;
|
||||
callIds: Set<string>;
|
||||
}
|
||||
|
||||
/**
|
||||
* Returns true if a scheduled tool call can safely execute concurrently
|
||||
* with other safe tools (no side effects, no shared mutable state).
|
||||
|
|
@ -753,6 +798,28 @@ export class CoreToolScheduler {
|
|||
private isFinalizingToolCalls = false;
|
||||
private isScheduling = false;
|
||||
private validationRetryCounts = new Map<string, number>();
|
||||
// Tool span lifecycle now spans validating → awaiting_approval → executing
|
||||
// → terminal, so we hold the span across method boundaries by callId.
|
||||
// Decoupling from ToolCall identity is intentional — setStatusInternal
|
||||
// rebuilds the ToolCall on every status change, so a field on the
|
||||
// discriminated union would require threading on every transition.
|
||||
private toolSpans = new Map<string, Span>();
|
||||
// blocked_on_user span — child of the corresponding tool span — covers the
|
||||
// awaiting_approval phase. ModifyWithEditor stays inside one span until
|
||||
// the user makes a final decision (#3731 Phase 2).
|
||||
//
|
||||
// Map drain on signal.abort: see drainSpansForBatch — without it,
|
||||
// entries leaked across awaiting-approval-then-abort would persist for
|
||||
// the scheduler's lifetime (the 30-min TTL ends the underlying spans
|
||||
// but cannot reach these scheduler-local Maps; #4321 review).
|
||||
private blockedSpans = new Map<string, Span>();
|
||||
// Per-batch abort-listener state. callIdToBatch maps each callId added
|
||||
// during a `_schedule` invocation to its shared BatchAbortState; when
|
||||
// `finalize{Tool,Blocked}Span` removes the last live callId of a
|
||||
// batch, we strip the abort listener off the signal so long-lived
|
||||
// sessions reusing the same AbortSignal don't accumulate listeners
|
||||
// and trip Node's MaxListenersExceededWarning (#4321 review-3).
|
||||
private callIdToBatch = new Map<string, BatchAbortState>();
|
||||
private requestQueue: Array<{
|
||||
request: ToolCallRequestInfo | ToolCallRequestInfo[];
|
||||
signal: AbortSignal;
|
||||
|
|
@ -1003,6 +1070,185 @@ export class CoreToolScheduler {
|
|||
);
|
||||
}
|
||||
|
||||
/**
|
||||
* End the tool span for `callId` (if any) and remove it from the map.
|
||||
* Centralizes terminal-state cleanup so every cancel/error/success path
|
||||
* goes through one place — easier to audit for leaks. Idempotent:
|
||||
* second call for the same callId is a no-op.
|
||||
*
|
||||
* No `metadata` parameter: every caller pre-sets span status via
|
||||
* `setToolSpan{Failure,Cancelled,Ok}` before this call (#4321 review).
|
||||
*/
|
||||
private finalizeToolSpan(callId: string): void {
|
||||
const span = this.toolSpans.get(callId);
|
||||
if (!span) return;
|
||||
this.toolSpans.delete(callId);
|
||||
endToolSpan(span);
|
||||
this.releaseBatchListenerIfDrained(callId);
|
||||
}
|
||||
|
||||
/**
|
||||
* End the blocked_on_user span for `callId` (if any) and remove it from
|
||||
* the map. Idempotent. ModifyWithEditor must NOT call this — the same
|
||||
* blocked span covers the entire awaiting period including editor side
|
||||
* trips.
|
||||
*/
|
||||
private finalizeBlockedSpan(
|
||||
callId: string,
|
||||
decision: ToolBlockedDecision,
|
||||
source: ToolBlockedSource,
|
||||
): void {
|
||||
const span = this.blockedSpans.get(callId);
|
||||
if (!span) return;
|
||||
this.blockedSpans.delete(callId);
|
||||
endToolBlockedOnUserSpan(span, { decision, source });
|
||||
// Don't release the batch listener here — the tool span often
|
||||
// outlives the blocked span (proceed → execute), so finalizeToolSpan
|
||||
// is the canonical drain point. The blocked span's release runs
|
||||
// through the same path on terminal states (cancel/error finalize
|
||||
// both spans together).
|
||||
}
|
||||
|
||||
/**
|
||||
* Hook called by finalizeToolSpan when a callId drains from the
|
||||
* scheduler-local maps. If this was the last live callId of its batch,
|
||||
* remove the abort listener so the AbortSignal doesn't accumulate
|
||||
* listeners across many `_schedule` calls in a long-lived session
|
||||
* (#4321 review-3 wenshao Critical).
|
||||
*/
|
||||
private releaseBatchListenerIfDrained(callId: string): void {
|
||||
const batch = this.callIdToBatch.get(callId);
|
||||
if (!batch) return;
|
||||
this.callIdToBatch.delete(callId);
|
||||
batch.callIds.delete(callId);
|
||||
|
||||
// Any other callId in the batch still in toolSpans/blockedSpans?
|
||||
// If yes, the listener still has work to do. If no, drop it.
|
||||
for (const id of batch.callIds) {
|
||||
if (this.toolSpans.has(id) || this.blockedSpans.has(id)) return;
|
||||
}
|
||||
batch.signal.removeEventListener('abort', batch.onAbort);
|
||||
}
|
||||
|
||||
/**
|
||||
* Best-effort attribution of the surface that resolved the blocked
|
||||
* decision. When IDE mode is on, confirmations are most often resolved
|
||||
* via the IDE diff flow (`openIdeDiffIfEnabled`) — but a CLI-fallback
|
||||
* confirmation in IDE mode is also reported as 'ide' here. Operators
|
||||
* can drill into the trace if they need finer-grained attribution.
|
||||
*/
|
||||
private getBlockedSource(): ToolBlockedSource {
|
||||
return this.config.getIdeMode?.() ? 'ide' : 'cli';
|
||||
}
|
||||
|
||||
/**
|
||||
* Drain any tool/blocked spans associated with `callIds` that are still
|
||||
* live in the scheduler-local maps. Called on signal.abort for spans
|
||||
* that no other code path will finalize (e.g. user walks away from
|
||||
* awaiting_approval and the session aborts).
|
||||
*
|
||||
* Deferred to a macrotask so existing finalize paths that await on the
|
||||
* SAME aborted signal — explicit user Cancel via
|
||||
* `handleConfirmationResponse`, mid-execution `setToolSpanCancelled`
|
||||
* inside `_executeToolCallBody` — win the race and set the canonical
|
||||
* decision/status before this safety-net drain runs. By the time the
|
||||
* timer fires, those paths have removed the entries from the Maps and
|
||||
* the drain is a no-op for the common cases. Only the genuine
|
||||
* walk-away-then-abort case survives to be drained here.
|
||||
*
|
||||
* Idempotent for callIds whose spans were already finalized by a normal
|
||||
* path — `finalizeBlockedSpan` / `finalizeToolSpan` are no-ops on
|
||||
* missing entries.
|
||||
*/
|
||||
private drainSpansForBatch(callIds: Iterable<string>): void {
|
||||
const ids = Array.from(callIds);
|
||||
setTimeout(() => {
|
||||
for (const callId of ids) {
|
||||
// Per-callId try/catch so one bad finalize doesn't silently skip
|
||||
// remaining entries — the timer callback would otherwise surface
|
||||
// an unhandled exception (#4321 review-3 wenshao Suggestion).
|
||||
try {
|
||||
if (this.blockedSpans.has(callId)) {
|
||||
this.finalizeBlockedSpan(callId, 'aborted', 'system');
|
||||
}
|
||||
const span = this.toolSpans.get(callId);
|
||||
if (span) {
|
||||
setToolSpanCancelled(span);
|
||||
this.finalizeToolSpan(callId);
|
||||
}
|
||||
} catch (e) {
|
||||
debugLogger.warn(
|
||||
`drainSpansForBatch: failed to drain ${callId}: ${e instanceof Error ? e.message : String(e)}`,
|
||||
);
|
||||
}
|
||||
}
|
||||
}, 0);
|
||||
}
|
||||
|
||||
/**
|
||||
* Shared toEndMeta callback for the 4 PostToolUseFailure hook fire
|
||||
* sites. Each was previously inlined as a byte-identical lambda; the
|
||||
* helper avoids drift between cancel-vs-error and abort-vs-non-abort
|
||||
* branches and keeps protocol changes (e.g. new metadata fields) in
|
||||
* one place (#4321 review-3 wenshao Suggestion).
|
||||
*/
|
||||
private postToolUseFailureEndMeta = (
|
||||
r: Awaited<ReturnType<typeof safelyFirePostToolUseFailureHook>>,
|
||||
): HookSpanMetadata =>
|
||||
r.hookError
|
||||
? { success: false, error: r.hookError }
|
||||
: {
|
||||
success: true,
|
||||
hasAdditionalContext: !!r.additionalContext,
|
||||
};
|
||||
|
||||
/**
|
||||
* Wrap a hook fire site with span lifecycle management. Centralizes the
|
||||
* try/finally pattern across the 6 hook fire sites (PreToolUse,
|
||||
* PostToolUse, 4× PostToolUseFailure) so future protocol changes
|
||||
* (e.g. new metadata fields) can be made in one place instead of in
|
||||
* lockstep across each site (#4321 review wenshao Suggestion).
|
||||
*
|
||||
* On the happy path `toEndMeta(result)` builds the metadata recorded on
|
||||
* the span. On a throw, the default `endMeta = { success: false }`
|
||||
* survives — today's hook helpers in `toolHookTriggers.ts` swallow
|
||||
* throws internally so this branch is unreachable, but the pattern
|
||||
* future-proofs the lifecycle if that contract changes.
|
||||
*/
|
||||
private async withHookSpan<T>(
|
||||
opts: StartHookSpanOptions,
|
||||
fn: () => Promise<T>,
|
||||
toEndMeta: (result: T) => HookSpanMetadata,
|
||||
): Promise<T> {
|
||||
const hookSpan = startHookSpan(opts);
|
||||
// Default endMeta carries an `error` so OTel maps the span to ERROR
|
||||
// status if `fn()` ever throws (today unreachable — hook helpers
|
||||
// catch internally — but kept as a defensive contract). Without
|
||||
// an `error` field, the span would record `success: false` as an
|
||||
// attribute but `code: UNSET` as status, which trace backends
|
||||
// filtering on ERROR would miss (#4321 review code-reviewer).
|
||||
let endMeta: HookSpanMetadata = { success: false };
|
||||
try {
|
||||
const result = await fn();
|
||||
endMeta = toEndMeta(result);
|
||||
return result;
|
||||
} catch (err) {
|
||||
// Capture the actual thrown message instead of a hardcoded
|
||||
// sentinel so the hook span surfaces the real failure for
|
||||
// operators (#4321 review DeepSeek Suggestion). This branch is
|
||||
// unreachable on the current hook-helper contract (each fire*
|
||||
// helper catches internally) but kept defensively in case the
|
||||
// contract evolves.
|
||||
endMeta = {
|
||||
success: false,
|
||||
error: err instanceof Error ? err.message : String(err),
|
||||
};
|
||||
throw err;
|
||||
} finally {
|
||||
endHookSpan(hookSpan, endMeta);
|
||||
}
|
||||
}
|
||||
|
||||
private buildInvocation(
|
||||
tool: AnyDeclarativeTool,
|
||||
args: object,
|
||||
|
|
@ -1306,6 +1552,21 @@ export class CoreToolScheduler {
|
|||
this.toolCalls = this.toolCalls.concat(newToolCalls);
|
||||
this.notifyToolCallsUpdate();
|
||||
|
||||
// Per-batch abort-listener state. Shared by every callId added in
|
||||
// this `_schedule` invocation. The listener drains scheduler-local
|
||||
// Maps on a real abort (walk-away-during-awaiting_approval), and is
|
||||
// automatically released by `releaseBatchListenerIfDrained` from
|
||||
// inside `finalizeToolSpan` when the batch's last live callId
|
||||
// drains — keeping listener growth bounded across long sessions
|
||||
// even when batches mix synchronous and awaiting_approval flows
|
||||
// (#4321 review-3 wenshao Critical).
|
||||
const batchState: BatchAbortState = {
|
||||
signal,
|
||||
onAbort: () => this.drainSpansForBatch(batchState.callIds),
|
||||
callIds: new Set<string>(),
|
||||
};
|
||||
signal.addEventListener('abort', batchState.onAbort, { once: true });
|
||||
|
||||
for (const toolCall of newToolCalls) {
|
||||
if (toolCall.status !== 'validating') {
|
||||
continue;
|
||||
|
|
@ -1314,6 +1575,28 @@ export class CoreToolScheduler {
|
|||
const { request: reqInfo, invocation } = toolCall;
|
||||
const canonicalName = canonicalToolName(reqInfo.name);
|
||||
|
||||
// Open the tool span as soon as the call is validated. This covers
|
||||
// validating → awaiting_approval → executing in one span (#3731
|
||||
// Phase 2). Every cancel/error path below — and the existing
|
||||
// success path in executeSingleToolCall — must call
|
||||
// finalizeToolSpan(callId, ...) to avoid leaking spans.
|
||||
// `tool.name` is set automatically by startToolSpan from the first
|
||||
// arg; only namespaced extras go in attrs. `call_id` (non-namespaced)
|
||||
// is dual-emitted for one release as a backwards-compat shim for
|
||||
// pre-Phase-2 dashboards/alerts that grep the old key — drop after
|
||||
// operators migrate (#4321 review). `tool_name` is dual-emitted on
|
||||
// the same migration window (review-2 DeepSeek Suggestion) so
|
||||
// pre-Phase-2 dashboards filtering on it don't silently stop
|
||||
// matching during the rollout.
|
||||
const toolSpan = startToolSpan(canonicalName, {
|
||||
'tool.call_id': reqInfo.callId,
|
||||
call_id: reqInfo.callId,
|
||||
tool_name: canonicalName,
|
||||
});
|
||||
this.toolSpans.set(reqInfo.callId, toolSpan);
|
||||
batchState.callIds.add(reqInfo.callId);
|
||||
this.callIdToBatch.set(reqInfo.callId, batchState);
|
||||
|
||||
try {
|
||||
if (signal.aborted) {
|
||||
this.setStatusInternal(
|
||||
|
|
@ -1321,6 +1604,8 @@ export class CoreToolScheduler {
|
|||
'cancelled',
|
||||
'Tool call cancelled by user.',
|
||||
);
|
||||
setToolSpanCancelled(toolSpan);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1378,6 +1663,12 @@ export class CoreToolScheduler {
|
|||
ToolErrorType.EXECUTION_DENIED,
|
||||
),
|
||||
);
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_PERMISSION_DENIED,
|
||||
TOOL_SPAN_STATUS_PERMISSION_DENIED,
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1493,6 +1784,12 @@ export class CoreToolScheduler {
|
|||
error: undefined,
|
||||
errorType: undefined,
|
||||
});
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_PLAN_MODE_BLOCKED,
|
||||
TOOL_SPAN_STATUS_PLAN_MODE_BLOCKED,
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1525,6 +1822,12 @@ export class CoreToolScheduler {
|
|||
ToolErrorType.EXECUTION_DENIED,
|
||||
),
|
||||
);
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_NON_INTERACTIVE_DENIED,
|
||||
TOOL_SPAN_STATUS_NON_INTERACTIVE_DENIED,
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1590,6 +1893,12 @@ export class CoreToolScheduler {
|
|||
ToolErrorType.EXECUTION_DENIED,
|
||||
),
|
||||
);
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_PERMISSION_HOOK_DENIED,
|
||||
TOOL_SPAN_STATUS_PERMISSION_HOOK_DENIED,
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
}
|
||||
continue;
|
||||
}
|
||||
|
|
@ -1608,6 +1917,32 @@ export class CoreToolScheduler {
|
|||
ToolErrorType.EXECUTION_DENIED,
|
||||
),
|
||||
);
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_BACKGROUND_AGENT_DENIED,
|
||||
TOOL_SPAN_STATUS_BACKGROUND_AGENT_DENIED,
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
// Re-check signal.aborted between the for-loop entry guard and
|
||||
// here: `evaluatePermissionFlow`, `getConfirmationDetails`, and
|
||||
// `firePermissionRequestHook` are all `await` points that can
|
||||
// resolve normally even after the signal aborted. Without this
|
||||
// re-check we'd open `awaiting_approval` + a blocked span on
|
||||
// an already-aborted signal — drainSpansForBatch (deferred via
|
||||
// setTimeout(0)) may have already fired by then, so the new
|
||||
// entries would never be drained (#4321 review-3 wenshao
|
||||
// Critical).
|
||||
if (signal.aborted) {
|
||||
this.setStatusInternal(
|
||||
reqInfo.callId,
|
||||
'cancelled',
|
||||
'Tool call cancelled by user.',
|
||||
);
|
||||
setToolSpanCancelled(toolSpan);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1643,6 +1978,17 @@ export class CoreToolScheduler {
|
|||
wrappedConfirmationDetails,
|
||||
);
|
||||
|
||||
// Open blocked_on_user span as a child of the tool span — covers
|
||||
// the entire awaiting_approval phase, including any
|
||||
// ModifyWithEditor side trip (#3731 Phase 2). Finalized in
|
||||
// handleConfirmationResponse / autoApproveCompatiblePendingTools
|
||||
// / the global-abort catch block above.
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan, {
|
||||
tool_name: canonicalName,
|
||||
call_id: reqInfo.callId,
|
||||
});
|
||||
this.blockedSpans.set(reqInfo.callId, blockedSpan);
|
||||
|
||||
// Fire permission_prompt notification hook
|
||||
if (hooksEnabled && messageBus) {
|
||||
fireNotificationHook(
|
||||
|
|
@ -1664,6 +2010,11 @@ export class CoreToolScheduler {
|
|||
'cancelled',
|
||||
'Tool call cancelled by user.',
|
||||
);
|
||||
// If this tool was waiting on the user, end the blocked span
|
||||
// as aborted before the tool span itself.
|
||||
this.finalizeBlockedSpan(reqInfo.callId, 'aborted', 'system');
|
||||
setToolSpanCancelled(toolSpan);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
|
@ -1685,10 +2036,37 @@ export class CoreToolScheduler {
|
|||
explicitErrorType ?? ToolErrorType.UNHANDLED_EXCEPTION,
|
||||
),
|
||||
);
|
||||
// Non-aborted catch is a system error (e.g. getConfirmationDetails
|
||||
// threw). 'error' decision keeps it distinct from user 'cancel'
|
||||
// counts in dashboards.
|
||||
this.finalizeBlockedSpan(reqInfo.callId, 'error', 'system');
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_TOOL_EXCEPTION,
|
||||
error instanceof Error ? error.message : String(error),
|
||||
);
|
||||
this.finalizeToolSpan(reqInfo.callId);
|
||||
}
|
||||
}
|
||||
await this.attemptExecutionOfScheduledCalls(signal);
|
||||
void this.checkAndNotifyCompletion();
|
||||
// Listener removal happens inside `finalizeToolSpan` →
|
||||
// `releaseBatchListenerIfDrained` for every callId, so we don't
|
||||
// need a duplicate cleanup here. That path also covers the
|
||||
// exception case (this method's outer try/catch finalizes spans
|
||||
// before re-throwing), satisfying the
|
||||
// "stillLive cleanup not in finally" concern from review-3.
|
||||
//
|
||||
// Edge case: if every newToolCall was non-validating (all failed
|
||||
// pre-validation — invalid params, tool not registered, etc.),
|
||||
// batchState.callIds stays empty and no finalizeToolSpan call
|
||||
// ever fires for this batch. Drop the listener here so the
|
||||
// signal doesn't accumulate dead listeners across many such
|
||||
// batches in a daemon session (#4321 review-5 wenshao
|
||||
// Suggestion).
|
||||
if (batchState.callIds.size === 0) {
|
||||
signal.removeEventListener('abort', batchState.onAbort);
|
||||
}
|
||||
} finally {
|
||||
this.isScheduling = false;
|
||||
}
|
||||
|
|
@ -1713,6 +2091,82 @@ export class CoreToolScheduler {
|
|||
// processing and potential re-execution.
|
||||
if (!toolCall) return;
|
||||
|
||||
try {
|
||||
await this._handleConfirmationResponseInner(
|
||||
callId,
|
||||
toolCall,
|
||||
originalOnConfirm,
|
||||
outcome,
|
||||
signal,
|
||||
payload,
|
||||
);
|
||||
} catch (error) {
|
||||
// Defensive: a throw from the confirmation flow (originalOnConfirm,
|
||||
// persistPermissionOutcome, autoApproveCompatiblePendingTools,
|
||||
// modifyWithEditor, _applyInlineModify, status transitions) would
|
||||
// otherwise leave A's blocked + tool spans open until the 30-min
|
||||
// TTL fires. Finalize both so the trace shows a deterministic
|
||||
// close. finalizeXSpan are idempotent — if the success/cancel
|
||||
// path already closed them, these are no-ops.
|
||||
//
|
||||
// attemptExecutionOfScheduledCalls is NOT covered by this catch
|
||||
// (see below). A sister tool's prelude throw escaping through
|
||||
// attemptExecutionOfScheduledCalls would otherwise corrupt A's
|
||||
// span — each executeSingleToolCall handles its own span
|
||||
// lifecycle via its own catch (#4321 review-9 wenshao Critical).
|
||||
//
|
||||
// Branch on signal.aborted so a throw caused by the abort signal
|
||||
// (e.g. ModifyWithEditor child interrupted by Ctrl+C) lands as
|
||||
// 'aborted'/'system' + UNSET status — matching the sister catch
|
||||
// in `_schedule:1797` and the dashboard intent of separating
|
||||
// user/system aborts from real exceptions (#4321 review-2 wenshao).
|
||||
const aborted = signal.aborted;
|
||||
this.finalizeBlockedSpan(callId, aborted ? 'aborted' : 'error', 'system');
|
||||
const toolSpan = this.toolSpans.get(callId);
|
||||
if (toolSpan) {
|
||||
if (aborted) {
|
||||
setToolSpanCancelled(toolSpan);
|
||||
} else {
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_TOOL_EXCEPTION,
|
||||
error instanceof Error ? error.message : String(error),
|
||||
);
|
||||
}
|
||||
}
|
||||
this.finalizeToolSpan(callId);
|
||||
// Surface the failure in application logs even though we re-throw.
|
||||
// The trace backend captures it via the span, but operators
|
||||
// grepping logs by callId would otherwise see nothing if the
|
||||
// caller doesn't log the rejection itself (#4321 review-5
|
||||
// wenshao Suggestion).
|
||||
debugLogger.warn(
|
||||
`handleConfirmationResponse failed for ${callId}: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
throw error;
|
||||
}
|
||||
|
||||
// Execution phase runs OUTSIDE the catch above so a sister tool's
|
||||
// prelude throw (re-thrown by executeSingleToolCall after SF-H2)
|
||||
// can't be mis-attributed to A's span. Each executeSingleToolCall
|
||||
// handles its own span lifecycle; failures propagate to the caller
|
||||
// as-is. (#4321 review-9 wenshao Critical refines review-2
|
||||
// pushback which became live after SF-H2 added the prelude
|
||||
// re-throw.)
|
||||
await this.attemptExecutionOfScheduledCalls(signal);
|
||||
}
|
||||
|
||||
private async _handleConfirmationResponseInner(
|
||||
callId: string,
|
||||
toolCall: ToolCall,
|
||||
originalOnConfirm: (
|
||||
outcome: ToolConfirmationOutcome,
|
||||
payload?: ToolConfirmationPayload,
|
||||
) => Promise<void>,
|
||||
outcome: ToolConfirmationOutcome,
|
||||
signal: AbortSignal,
|
||||
payload?: ToolConfirmationPayload,
|
||||
): Promise<void> {
|
||||
await originalOnConfirm(outcome, payload);
|
||||
|
||||
if (
|
||||
|
|
@ -1755,12 +2209,54 @@ export class CoreToolScheduler {
|
|||
const cancelMessage =
|
||||
payload?.cancelMessage || 'User did not allow tool call';
|
||||
this.setStatusInternal(callId, 'cancelled', cancelMessage);
|
||||
// Tool span is cancelled too — finalize it via setToolSpanCancelled
|
||||
// before pulling it out of the map so the status survives end().
|
||||
const toolSpan = this.toolSpans.get(callId);
|
||||
if (toolSpan) {
|
||||
setToolSpanCancelled(toolSpan);
|
||||
}
|
||||
// Explicit user Cancel takes precedence over a concurrent global
|
||||
// abort: when both are true, treat it as an explicit cancel so
|
||||
// dashboards counting `decision: 'aborted'` aren't polluted by
|
||||
// benign user actions that race with shutdown.
|
||||
const explicitCancel = outcome === ToolConfirmationOutcome.Cancel;
|
||||
this.finalizeBlockedSpan(
|
||||
callId,
|
||||
explicitCancel ? 'cancel' : 'aborted',
|
||||
explicitCancel ? this.getBlockedSource() : 'system',
|
||||
);
|
||||
this.finalizeToolSpan(callId);
|
||||
} else if (outcome === ToolConfirmationOutcome.ModifyWithEditor) {
|
||||
const waitingToolCall = toolCall as WaitingToolCall;
|
||||
if (isModifiableDeclarativeTool(waitingToolCall.tool)) {
|
||||
const modifyContext = waitingToolCall.tool.getModifyContext(signal);
|
||||
const editorType = this.getPreferredEditor();
|
||||
if (!editorType) {
|
||||
// No editor configured: ModifyWithEditor cannot proceed. Log so
|
||||
// the silent failure is at least visible in debug telemetry.
|
||||
// Do NOT finalize spans here — the tool stays in awaiting_approval
|
||||
// and the user can still recover with Cancel or Proceed; their
|
||||
// eventual decision closes the spans correctly. Closing them
|
||||
// here would make the user's eventual finalize a no-op (Map
|
||||
// already cleared) and lose the actual decision/source — same
|
||||
// pattern as the autoApprove catch (#4321 review codex P3).
|
||||
// The 30-min TTL is the safety net if the user walks away.
|
||||
debugLogger.warn(
|
||||
`ModifyWithEditor requested for ${callId} but no editor available — tool stays in awaiting_approval; user can recover via Cancel/Proceed`,
|
||||
);
|
||||
// Tag the tool span so operators can detect this state in
|
||||
// production traces without enabling debug logging
|
||||
// (#4321 review-2 DeepSeek Critical).
|
||||
const toolSpan = this.toolSpans.get(callId);
|
||||
if (toolSpan) {
|
||||
try {
|
||||
toolSpan.setAttributes({
|
||||
'qwen-code.tool.modify_with_editor_unavailable': true,
|
||||
});
|
||||
} catch {
|
||||
// OTel errors must not block API behavior.
|
||||
}
|
||||
}
|
||||
return;
|
||||
}
|
||||
|
||||
|
|
@ -1808,8 +2304,20 @@ export class CoreToolScheduler {
|
|||
);
|
||||
}
|
||||
this.setStatusInternal(callId, 'scheduled');
|
||||
// Proceed: end the blocked span before execution begins. ProceedOnce
|
||||
// and the three ProceedAlways* variants all close the awaiting phase.
|
||||
// The tool span itself stays open and is finalized in
|
||||
// executeSingleToolCall.
|
||||
const decision: ToolBlockedDecision =
|
||||
outcome === ToolConfirmationOutcome.ProceedOnce
|
||||
? 'proceed_once'
|
||||
: 'proceed_always';
|
||||
this.finalizeBlockedSpan(callId, decision, this.getBlockedSource());
|
||||
}
|
||||
await this.attemptExecutionOfScheduledCalls(signal);
|
||||
// attemptExecutionOfScheduledCalls is invoked by the caller
|
||||
// (handleConfirmationResponse, outside its catch) so a sister
|
||||
// tool's prelude throw can't be mis-attributed to this callId
|
||||
// (#4321 review-9 wenshao Critical).
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
@ -1994,16 +2502,64 @@ export class CoreToolScheduler {
|
|||
const scheduledCall = toolCall;
|
||||
const { callId, name: toolName } = scheduledCall.request;
|
||||
|
||||
const toolSpan = startToolSpan(toolName, {
|
||||
tool_name: toolName,
|
||||
call_id: callId,
|
||||
});
|
||||
// The tool span is opened in `_schedule` so it covers validating →
|
||||
// awaiting_approval → executing in one span. Reuse it here. If it's
|
||||
// missing (defensive — shouldn't happen on the happy path), create one
|
||||
// so the success path still produces telemetry.
|
||||
let toolSpan = this.toolSpans.get(callId);
|
||||
if (!toolSpan) {
|
||||
// canonicalToolName matches the _schedule path so dashboards
|
||||
// grouping by span name don't see two entries for migrated/MCP tools
|
||||
// when this defensive fallback fires (#4321 review).
|
||||
const canonical = canonicalToolName(toolName);
|
||||
toolSpan = startToolSpan(canonical, {
|
||||
'tool.call_id': callId,
|
||||
call_id: callId, // legacy alias — see _schedule for context
|
||||
tool_name: canonical, // legacy alias — see _schedule for context
|
||||
});
|
||||
this.toolSpans.set(callId, toolSpan);
|
||||
}
|
||||
try {
|
||||
await runInToolSpanContext(toolSpan, () =>
|
||||
this._executeToolCallBody(scheduledCall, signal, toolSpan),
|
||||
);
|
||||
} catch (error) {
|
||||
// _executeToolCallBody pre-sets span status (OK / FAILURE /
|
||||
// CANCELLED) only AFTER its main try/catch is entered. Throws
|
||||
// from the prelude — addToolInputAttributes, getMessageBus,
|
||||
// startToolExecutionSpan, etc. — happen BEFORE the
|
||||
// `scheduled → executing` transition, so the span would end
|
||||
// UNSET with no failure_kind AND the tool call would stay in
|
||||
// `scheduled` forever (checkAndNotifyCompletion never sees a
|
||||
// terminal state). Set failure status + error response here so
|
||||
// the finalizeToolSpan in `finally` produces meaningful
|
||||
// telemetry and the scheduler can complete (#4321 review-7
|
||||
// silent-failure-hunter HIGH-2; review-8 wenshao Critical
|
||||
// dropped the `status === 'executing'` guard the previous
|
||||
// attempt used — `setStatusInternal` already no-ops on
|
||||
// terminal states, so the unconditional call covers both
|
||||
// `scheduled` and `executing` prelude-throw paths).
|
||||
const errorMessage =
|
||||
error instanceof Error ? error.message : String(error);
|
||||
setToolSpanFailure(
|
||||
toolSpan,
|
||||
TOOL_FAILURE_KIND_TOOL_EXCEPTION,
|
||||
errorMessage,
|
||||
);
|
||||
this.setStatusInternal(
|
||||
callId,
|
||||
'error',
|
||||
createErrorResponse(
|
||||
scheduledCall.request,
|
||||
error instanceof Error ? error : new Error(errorMessage),
|
||||
ToolErrorType.UNHANDLED_EXCEPTION,
|
||||
),
|
||||
);
|
||||
throw error;
|
||||
} finally {
|
||||
endToolSpan(toolSpan);
|
||||
// _executeToolCallBody pre-sets status (OK / FAILURE / CANCELLED) via
|
||||
// setToolSpan*; finalize without metadata to preserve that.
|
||||
this.finalizeToolSpan(callId);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -2048,14 +2604,37 @@ export class CoreToolScheduler {
|
|||
if (hooksEnabled && messageBus) {
|
||||
// Convert ApprovalMode to permission_mode string for hooks
|
||||
const permissionMode = this.config.getApprovalMode();
|
||||
const preHookResult = await firePreToolUseHook(
|
||||
messageBus,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolUseId,
|
||||
permissionMode,
|
||||
const preHookResult = await this.withHookSpan(
|
||||
{ hookEvent: 'PreToolUse', toolName: canonicalName, toolUseId },
|
||||
() =>
|
||||
firePreToolUseHook(
|
||||
messageBus,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolUseId,
|
||||
permissionMode,
|
||||
),
|
||||
(r) =>
|
||||
r.hookError
|
||||
? {
|
||||
success: false,
|
||||
error: r.hookError,
|
||||
// Hook transport failures do NOT block tool execution
|
||||
// (firePreToolUseHook returns shouldProceed:true with a
|
||||
// hookError). Surface that on the span too so operators
|
||||
// see the same allow-on-failure semantics the runtime
|
||||
// applies (#4321 review-2 DeepSeek Suggestion).
|
||||
shouldProceed: true,
|
||||
}
|
||||
: {
|
||||
success: true,
|
||||
shouldProceed: r.shouldProceed,
|
||||
// Propagate the actual blockType ('denied' / 'ask' / 'stop')
|
||||
// instead of collapsing every block to 'denied'.
|
||||
blockType: r.shouldProceed ? undefined : r.blockType,
|
||||
hasAdditionalContext: !!r.additionalContext,
|
||||
},
|
||||
);
|
||||
|
||||
if (!preHookResult.shouldProceed) {
|
||||
// Hook blocked the execution
|
||||
const blockMessage =
|
||||
|
|
@ -2174,14 +2753,24 @@ export class CoreToolScheduler {
|
|||
// PostToolUseFailure Hook
|
||||
let cancelMessage = 'User cancelled tool execution.';
|
||||
if (hooksEnabled && messageBus) {
|
||||
const failureHookResult = await safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
cancelMessage,
|
||||
true,
|
||||
this.config.getApprovalMode(),
|
||||
const failureHookResult = await this.withHookSpan(
|
||||
{
|
||||
hookEvent: 'PostToolUseFailure',
|
||||
toolName: canonicalName,
|
||||
toolUseId,
|
||||
isInterrupt: true,
|
||||
},
|
||||
() =>
|
||||
safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
cancelMessage,
|
||||
true,
|
||||
this.config.getApprovalMode(),
|
||||
),
|
||||
this.postToolUseFailureEndMeta,
|
||||
);
|
||||
|
||||
// Append additional context from hook if provided
|
||||
|
|
@ -2212,13 +2801,35 @@ export class CoreToolScheduler {
|
|||
returnDisplay: toolResult.returnDisplay,
|
||||
};
|
||||
const permissionMode = this.config.getApprovalMode();
|
||||
const postHookResult = await firePostToolUseHook(
|
||||
messageBus,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolResponse,
|
||||
toolUseId,
|
||||
permissionMode,
|
||||
const postHookResult = await this.withHookSpan(
|
||||
{ hookEvent: 'PostToolUse', toolName: canonicalName, toolUseId },
|
||||
() =>
|
||||
firePostToolUseHook(
|
||||
messageBus,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolResponse,
|
||||
toolUseId,
|
||||
permissionMode,
|
||||
),
|
||||
(r) =>
|
||||
r.hookError
|
||||
? {
|
||||
success: false,
|
||||
error: r.hookError,
|
||||
// Hook transport failures do NOT halt the post-execution
|
||||
// flow (firePostToolUseHook returns shouldStop:false with
|
||||
// a hookError). Mirror the PreToolUse fix so the span
|
||||
// matches runtime semantics (#4321 review-2 DeepSeek
|
||||
// Suggestion).
|
||||
shouldStop: false,
|
||||
}
|
||||
: {
|
||||
success: true,
|
||||
shouldStop: r.shouldStop,
|
||||
hasAdditionalContext: !!r.additionalContext,
|
||||
blockType: r.shouldStop ? 'stop' : undefined,
|
||||
},
|
||||
);
|
||||
|
||||
// Append additional context from hook if provided
|
||||
|
|
@ -2378,14 +2989,24 @@ export class CoreToolScheduler {
|
|||
// PostToolUseFailure Hook
|
||||
let errorMessage = toolResult.error.message;
|
||||
if (hooksEnabled && messageBus) {
|
||||
const failureHookResult = await safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolResult.error.message,
|
||||
false,
|
||||
this.config.getApprovalMode(),
|
||||
const failureHookResult = await this.withHookSpan(
|
||||
{
|
||||
hookEvent: 'PostToolUseFailure',
|
||||
toolName: canonicalName,
|
||||
toolUseId,
|
||||
isInterrupt: false,
|
||||
},
|
||||
() =>
|
||||
safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
toolResult.error!.message,
|
||||
false,
|
||||
this.config.getApprovalMode(),
|
||||
),
|
||||
this.postToolUseFailureEndMeta,
|
||||
);
|
||||
|
||||
// Append additional context from hook if provided
|
||||
|
|
@ -2437,14 +3058,24 @@ export class CoreToolScheduler {
|
|||
// PostToolUseFailure Hook (user interrupt)
|
||||
let cancelMessage = 'User cancelled tool execution.';
|
||||
if (hooksEnabled && messageBus) {
|
||||
const failureHookResult = await safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
cancelMessage,
|
||||
true,
|
||||
this.config.getApprovalMode(),
|
||||
const failureHookResult = await this.withHookSpan(
|
||||
{
|
||||
hookEvent: 'PostToolUseFailure',
|
||||
toolName: canonicalName,
|
||||
toolUseId,
|
||||
isInterrupt: true,
|
||||
},
|
||||
() =>
|
||||
safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
cancelMessage,
|
||||
true,
|
||||
this.config.getApprovalMode(),
|
||||
),
|
||||
this.postToolUseFailureEndMeta,
|
||||
);
|
||||
|
||||
// Append additional context from hook if provided
|
||||
|
|
@ -2465,14 +3096,24 @@ export class CoreToolScheduler {
|
|||
// PostToolUseFailure Hook
|
||||
let exceptionErrorMessage = errorMessage;
|
||||
if (hooksEnabled && messageBus) {
|
||||
const failureHookResult = await safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
errorMessage,
|
||||
false,
|
||||
this.config.getApprovalMode(),
|
||||
const failureHookResult = await this.withHookSpan(
|
||||
{
|
||||
hookEvent: 'PostToolUseFailure',
|
||||
toolName: canonicalName,
|
||||
toolUseId,
|
||||
isInterrupt: false,
|
||||
},
|
||||
() =>
|
||||
safelyFirePostToolUseFailureHook(
|
||||
messageBus,
|
||||
toolUseId,
|
||||
canonicalName,
|
||||
toolInput,
|
||||
errorMessage,
|
||||
false,
|
||||
this.config.getApprovalMode(),
|
||||
),
|
||||
this.postToolUseFailureEndMeta,
|
||||
);
|
||||
|
||||
// Append additional context from hook if provided
|
||||
|
|
@ -2615,12 +3256,28 @@ export class CoreToolScheduler {
|
|||
ToolConfirmationOutcome.ProceedAlways,
|
||||
);
|
||||
this.setStatusInternal(pendingTool.request.callId, 'scheduled');
|
||||
// Sister tool was waiting on the user but a sibling's
|
||||
// ProceedAlways* outcome auto-approved it. Close the blocked span
|
||||
// with auto_approved so the trace explains why this branch
|
||||
// skipped a manual decision (#3731 Phase 2).
|
||||
this.finalizeBlockedSpan(
|
||||
pendingTool.request.callId,
|
||||
'auto_approved',
|
||||
'auto',
|
||||
);
|
||||
}
|
||||
} catch (error) {
|
||||
debugLogger.error(
|
||||
`Error checking confirmation for tool ${pendingTool.request.callId}:`,
|
||||
error,
|
||||
);
|
||||
// Intentionally do NOT finalize the blocked span here: the tool
|
||||
// remains in `awaiting_approval` and the user can still respond.
|
||||
// Closing the span on a transient permission-flow error would
|
||||
// make the user's eventual decision a no-op (Map already cleared)
|
||||
// and the actual decision/source would be lost. If the user
|
||||
// never responds, the 30-min TTL in session-tracing.ts cleans
|
||||
// up the span (#4321 codex P3 review).
|
||||
}
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -58,7 +58,7 @@ describe('toolHookTriggers', () => {
|
|||
expect(result).toEqual({ shouldProceed: true });
|
||||
});
|
||||
|
||||
it('should return shouldProceed: true when hook execution fails', async () => {
|
||||
it('should return shouldProceed: true with sentinel hookError when hook execution fails without an error message', async () => {
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
|
|
@ -72,7 +72,38 @@ describe('toolHookTriggers', () => {
|
|||
'auto',
|
||||
);
|
||||
|
||||
expect(result).toEqual({ shouldProceed: true });
|
||||
// #4321 review-7 SF-H1: runner contract violation (success:false
|
||||
// with no error.message) used to silently return allow with no
|
||||
// telemetry. Now synthesizes a sentinel hookError so the span
|
||||
// records `success: false` + the description of what went wrong.
|
||||
expect(result.shouldProceed).toBe(true);
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
});
|
||||
|
||||
it('synthesizes sentinel hookError when runner returns empty-string error message (#4321)', async () => {
|
||||
// #4321 review-9: pin the `||` (not `??`) semantics. A future
|
||||
// regression back to `??` would preserve `hookError: ""` here
|
||||
// which downstream `r.hookError ? ...` truthiness then silently
|
||||
// drops — same allow-without-telemetry pathology SF-H1 closed.
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
error: { message: '' },
|
||||
});
|
||||
|
||||
const result = await firePreToolUseHook(
|
||||
mockMessageBus,
|
||||
'test-tool',
|
||||
{},
|
||||
'test-id',
|
||||
'auto',
|
||||
);
|
||||
|
||||
expect(result.shouldProceed).toBe(true);
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
// Specifically NOT empty: an empty string would round-trip through
|
||||
// a downstream truthiness check as missing.
|
||||
expect(result.hookError).not.toBe('');
|
||||
});
|
||||
|
||||
it('should return shouldProceed: true when hook output is empty', async () => {
|
||||
|
|
@ -215,7 +246,13 @@ describe('toolHookTriggers', () => {
|
|||
'auto',
|
||||
);
|
||||
|
||||
expect(result).toEqual({ shouldProceed: true });
|
||||
// #4321 review: hookError surfaces the swallowed transport error so
|
||||
// observers (telemetry spans, debug logs) can distinguish a failed
|
||||
// hook from a successful "allow" decision.
|
||||
expect(result).toEqual({
|
||||
shouldProceed: true,
|
||||
hookError: 'Network error',
|
||||
});
|
||||
});
|
||||
});
|
||||
|
||||
|
|
@ -233,7 +270,7 @@ describe('toolHookTriggers', () => {
|
|||
expect(result).toEqual({ shouldStop: false });
|
||||
});
|
||||
|
||||
it('should return shouldStop: false when hook execution fails', async () => {
|
||||
it('should return shouldStop: false with sentinel hookError when hook execution fails without an error message', async () => {
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
|
|
@ -248,7 +285,31 @@ describe('toolHookTriggers', () => {
|
|||
'auto',
|
||||
);
|
||||
|
||||
expect(result).toEqual({ shouldStop: false });
|
||||
// #4321 review-7 SF-H1 — see firePreToolUseHook counterpart.
|
||||
expect(result.shouldStop).toBe(false);
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
});
|
||||
|
||||
it('synthesizes sentinel hookError when runner returns empty-string error message (#4321)', async () => {
|
||||
// #4321 review-9 — see firePreToolUseHook counterpart.
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
error: { message: '' },
|
||||
});
|
||||
|
||||
const result = await firePostToolUseHook(
|
||||
mockMessageBus,
|
||||
'test-tool',
|
||||
{},
|
||||
{},
|
||||
'test-id',
|
||||
'auto',
|
||||
);
|
||||
|
||||
expect(result.shouldStop).toBe(false);
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
expect(result.hookError).not.toBe('');
|
||||
});
|
||||
|
||||
it('should return shouldStop: false when hook output is empty', async () => {
|
||||
|
|
@ -338,7 +399,9 @@ describe('toolHookTriggers', () => {
|
|||
'auto',
|
||||
);
|
||||
|
||||
expect(result).toEqual({ shouldStop: false });
|
||||
// #4321 review: hookError now surfaced to caller (see PreToolUse parallel test).
|
||||
expect(result.shouldStop).toBe(false);
|
||||
expect(result.hookError).toBeDefined();
|
||||
});
|
||||
});
|
||||
|
||||
|
|
@ -355,7 +418,7 @@ describe('toolHookTriggers', () => {
|
|||
expect(result).toEqual({});
|
||||
});
|
||||
|
||||
it('should return empty object when hook execution fails', async () => {
|
||||
it('should return sentinel hookError when hook execution fails without an error message', async () => {
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
|
|
@ -369,7 +432,28 @@ describe('toolHookTriggers', () => {
|
|||
'error message',
|
||||
);
|
||||
|
||||
expect(result).toEqual({});
|
||||
// #4321 review-7 SF-H1 — see firePreToolUseHook counterpart.
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
});
|
||||
|
||||
it('synthesizes sentinel hookError when runner returns empty-string error message (#4321)', async () => {
|
||||
// #4321 review-9 — see firePreToolUseHook counterpart.
|
||||
const mockMessageBus = createMockMessageBus();
|
||||
(mockMessageBus.request as ReturnType<typeof vi.fn>).mockResolvedValue({
|
||||
success: false,
|
||||
error: { message: '' },
|
||||
});
|
||||
|
||||
const result = await firePostToolUseFailureHook(
|
||||
mockMessageBus,
|
||||
'test-id',
|
||||
'test-tool',
|
||||
{},
|
||||
'error message',
|
||||
);
|
||||
|
||||
expect(result.hookError).toMatch(/success: false/);
|
||||
expect(result.hookError).not.toBe('');
|
||||
});
|
||||
|
||||
it('should return empty object when hook output is empty', async () => {
|
||||
|
|
@ -429,7 +513,9 @@ describe('toolHookTriggers', () => {
|
|||
'error message',
|
||||
);
|
||||
|
||||
expect(result).toEqual({});
|
||||
// #4321 review: hookError now surfaced to caller.
|
||||
expect(result.hookError).toBeDefined();
|
||||
expect(result.additionalContext).toBeUndefined();
|
||||
});
|
||||
});
|
||||
|
||||
|
|
|
|||
|
|
@ -43,6 +43,14 @@ export interface PreToolUseHookResult {
|
|||
blockType?: 'denied' | 'ask' | 'stop';
|
||||
/** Additional context to add */
|
||||
additionalContext?: string;
|
||||
/**
|
||||
* Set when the hook helper caught and absorbed a transport / dispatch
|
||||
* error. The tool execution still proceeds (existing non-blocking
|
||||
* contract), but observers (telemetry spans, debug logs) can detect
|
||||
* that the hook itself failed instead of treating the safe-default
|
||||
* response as a successful "allow" decision (#4321 review).
|
||||
*/
|
||||
hookError?: string;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
@ -55,6 +63,8 @@ export interface PostToolUseHookResult {
|
|||
stopReason?: string;
|
||||
/** Additional context to append to tool response */
|
||||
additionalContext?: string;
|
||||
/** See PreToolUseHookResult.hookError. */
|
||||
hookError?: string;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
@ -63,6 +73,8 @@ export interface PostToolUseHookResult {
|
|||
export interface PostToolUseFailureHookResult {
|
||||
/** Additional context about the failure */
|
||||
additionalContext?: string;
|
||||
/** See PreToolUseHookResult.hookError. */
|
||||
hookError?: string;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
@ -107,7 +119,27 @@ export async function firePreToolUseHook(
|
|||
);
|
||||
|
||||
if (!response.success || !response.output) {
|
||||
return { shouldProceed: true };
|
||||
// Hook runner reported failure (URL validation, fn exception,
|
||||
// prompt-runner crash, ...). The `response.error` from the runner
|
||||
// is the canonical cause — forward it so telemetry and operators
|
||||
// see the actual failure instead of a fake "allow" success
|
||||
// (#4321 review silent-failure-hunter HIGH).
|
||||
//
|
||||
// If runner returned `{ success: false }` (or missing output) with no
|
||||
// `error.message`, synthesize a sentinel so the contract violation is
|
||||
// still visible on the span instead of silently degrading to an allow
|
||||
// with empty telemetry (#4321 review-7 silent-failure-hunter HIGH-1).
|
||||
// `||` (revert from `??`): downstream consumers in
|
||||
// coreToolScheduler.ts gate on `r.hookError ? ...`, so an
|
||||
// empty-string message would be silently dropped — the previous
|
||||
// `??` change defeated its own intent. Empty-string error
|
||||
// messages carry no operator value; the sentinel is more
|
||||
// actionable. (#4321 review-9 wenshao Suggestion refines
|
||||
// review-8.)
|
||||
const message =
|
||||
response.error?.message ||
|
||||
`hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`;
|
||||
return { shouldProceed: true, hookError: message };
|
||||
}
|
||||
|
||||
const preToolOutput = createHookOutput(
|
||||
|
|
@ -155,10 +187,9 @@ export async function firePreToolUseHook(
|
|||
};
|
||||
} catch (error) {
|
||||
// Hook errors should not block tool execution
|
||||
debugLogger.warn(
|
||||
`PreToolUse hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
return { shouldProceed: true };
|
||||
const message = error instanceof Error ? error.message : String(error);
|
||||
debugLogger.warn(`PreToolUse hook error for ${toolName}: ${message}`);
|
||||
return { shouldProceed: true, hookError: message };
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -207,7 +238,18 @@ export async function firePostToolUseHook(
|
|||
);
|
||||
|
||||
if (!response.success || !response.output) {
|
||||
return { shouldStop: false };
|
||||
// See firePreToolUseHook for the rationale.
|
||||
// `||` (revert from `??`): downstream consumers in
|
||||
// coreToolScheduler.ts gate on `r.hookError ? ...`, so an
|
||||
// empty-string message would be silently dropped — the previous
|
||||
// `??` change defeated its own intent. Empty-string error
|
||||
// messages carry no operator value; the sentinel is more
|
||||
// actionable. (#4321 review-9 wenshao Suggestion refines
|
||||
// review-8.)
|
||||
const message =
|
||||
response.error?.message ||
|
||||
`hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`;
|
||||
return { shouldStop: false, hookError: message };
|
||||
}
|
||||
|
||||
const postToolOutput = createHookOutput(
|
||||
|
|
@ -232,10 +274,9 @@ export async function firePostToolUseHook(
|
|||
};
|
||||
} catch (error) {
|
||||
// Hook errors should not affect tool result
|
||||
debugLogger.warn(
|
||||
`PostToolUse hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
return { shouldStop: false };
|
||||
const message = error instanceof Error ? error.message : String(error);
|
||||
debugLogger.warn(`PostToolUse hook error for ${toolName}: ${message}`);
|
||||
return { shouldStop: false, hookError: message };
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -287,7 +328,18 @@ export async function firePostToolUseFailureHook(
|
|||
);
|
||||
|
||||
if (!response.success || !response.output) {
|
||||
return {};
|
||||
// See firePreToolUseHook for the rationale.
|
||||
// `||` (revert from `??`): downstream consumers in
|
||||
// coreToolScheduler.ts gate on `r.hookError ? ...`, so an
|
||||
// empty-string message would be silently dropped — the previous
|
||||
// `??` change defeated its own intent. Empty-string error
|
||||
// messages carry no operator value; the sentinel is more
|
||||
// actionable. (#4321 review-9 wenshao Suggestion refines
|
||||
// review-8.)
|
||||
const message =
|
||||
response.error?.message ||
|
||||
`hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`;
|
||||
return { hookError: message };
|
||||
}
|
||||
|
||||
const failureOutput = createHookOutput(
|
||||
|
|
@ -301,10 +353,11 @@ export async function firePostToolUseFailureHook(
|
|||
};
|
||||
} catch (error) {
|
||||
// Hook errors should not affect error handling
|
||||
const message = error instanceof Error ? error.message : String(error);
|
||||
debugLogger.warn(
|
||||
`PostToolUseFailure hook error for ${toolName}: ${error instanceof Error ? error.message : String(error)}`,
|
||||
`PostToolUseFailure hook error for ${toolName}: ${message}`,
|
||||
);
|
||||
return {};
|
||||
return { hookError: message };
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -64,3 +64,7 @@ export const SPAN_INTERACTION = 'qwen-code.interaction';
|
|||
export const SPAN_LLM_REQUEST = 'qwen-code.llm_request';
|
||||
export const SPAN_TOOL = 'qwen-code.tool';
|
||||
export const SPAN_TOOL_EXECUTION = 'qwen-code.tool.execution';
|
||||
/** Brackets the time a tool spends in `awaiting_approval` waiting on the user. */
|
||||
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';
|
||||
|
|
|
|||
|
|
@ -146,13 +146,23 @@ export {
|
|||
runInToolSpanContext,
|
||||
startToolExecutionSpan,
|
||||
endToolExecutionSpan,
|
||||
startToolBlockedOnUserSpan,
|
||||
endToolBlockedOnUserSpan,
|
||||
startHookSpan,
|
||||
endHookSpan,
|
||||
getActiveInteractionSpan,
|
||||
truncateSpanError,
|
||||
} from './session-tracing.js';
|
||||
export type {
|
||||
StartInteractionOptions,
|
||||
EndInteractionOptions,
|
||||
LLMRequestMetadata,
|
||||
ToolSpanMetadata,
|
||||
ToolBlockedDecision,
|
||||
ToolBlockedSource,
|
||||
HookEvent,
|
||||
StartHookSpanOptions,
|
||||
HookSpanMetadata,
|
||||
} from './session-tracing.js';
|
||||
export {
|
||||
addUserPromptAttributes,
|
||||
|
|
|
|||
|
|
@ -132,8 +132,14 @@ import {
|
|||
runInToolSpanContext,
|
||||
startToolExecutionSpan,
|
||||
endToolExecutionSpan,
|
||||
startToolBlockedOnUserSpan,
|
||||
endToolBlockedOnUserSpan,
|
||||
startHookSpan,
|
||||
endHookSpan,
|
||||
getActiveInteractionSpan,
|
||||
clearSessionTracingForTesting,
|
||||
runTTLSweepForTesting,
|
||||
truncateSpanError,
|
||||
} from './session-tracing.js';
|
||||
|
||||
function createMockConfig(
|
||||
|
|
@ -537,6 +543,224 @@ describe('session-tracing', () => {
|
|||
});
|
||||
});
|
||||
|
||||
describe('blocked_on_user spans (#3731 Phase 2)', () => {
|
||||
it('parents the blocked span under the explicitly-passed tool span', () => {
|
||||
const toolSpan = startToolSpan('Bash', { 'tool.call_id': 'c1' });
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan, {
|
||||
tool_name: 'Bash',
|
||||
call_id: 'c1',
|
||||
});
|
||||
|
||||
const blockedRecord = mockSpans.find(
|
||||
(s) => s.name === 'qwen-code.tool.blocked_on_user',
|
||||
);
|
||||
expect(blockedRecord).toBeDefined();
|
||||
// Parent context carries the tool span via setSpan()'s __parentSpan tag.
|
||||
expect(blockedRecord?.parentContext).toMatchObject({
|
||||
__parentSpan: toolSpan,
|
||||
});
|
||||
expect(blockedRecord?.attributes['tool.name']).toBe('Bash');
|
||||
expect(blockedRecord?.attributes['tool.call_id']).toBe('c1');
|
||||
|
||||
endToolBlockedOnUserSpan(blockedSpan, {
|
||||
decision: 'proceed_once',
|
||||
source: 'cli',
|
||||
});
|
||||
endToolSpan(toolSpan, { success: true });
|
||||
});
|
||||
|
||||
it('records decision/source attributes on end and leaves status UNSET', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan);
|
||||
endToolBlockedOnUserSpan(blockedSpan, {
|
||||
decision: 'cancel',
|
||||
source: 'cli',
|
||||
});
|
||||
|
||||
const blockedRecord = mockSpans.find(
|
||||
(s) => s.name === 'qwen-code.tool.blocked_on_user',
|
||||
);
|
||||
expect(blockedRecord?.ended).toBe(true);
|
||||
expect(blockedRecord?.attributes['decision']).toBe('cancel');
|
||||
expect(blockedRecord?.attributes['source']).toBe('cli');
|
||||
// Waiting on the user is neither OK nor ERROR — status stays UNSET.
|
||||
expect(blockedRecord?.statuses).toHaveLength(0);
|
||||
});
|
||||
|
||||
it('is idempotent — second end is a no-op', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan);
|
||||
endToolBlockedOnUserSpan(blockedSpan, { decision: 'proceed_once' });
|
||||
endToolBlockedOnUserSpan(blockedSpan, { decision: 'cancel' });
|
||||
|
||||
const blockedRecord = mockSpans.find(
|
||||
(s) => s.name === 'qwen-code.tool.blocked_on_user',
|
||||
);
|
||||
// The second end must NOT overwrite decision recorded by the first.
|
||||
expect(blockedRecord?.attributes['decision']).toBe('proceed_once');
|
||||
});
|
||||
|
||||
it('returns NOOP span when SDK is not initialized', () => {
|
||||
mockState.sdkInitialized = false;
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan);
|
||||
expect(blockedSpan.spanContext().traceId).toBe('0'.repeat(32));
|
||||
|
||||
// End on NOOP span must not throw.
|
||||
endToolBlockedOnUserSpan(blockedSpan, { decision: 'cancel' });
|
||||
});
|
||||
|
||||
it('handles concurrent blocked spans without findLast confusion', () => {
|
||||
// Regression test for the claude-code findLast-by-type bug.
|
||||
// Two concurrent tools each have their own blocked span; ending the
|
||||
// second one first must NOT close the first.
|
||||
const toolA = startToolSpan('Bash', { 'tool.call_id': 'a' });
|
||||
const toolB = startToolSpan('Read', { 'tool.call_id': 'b' });
|
||||
const blockedA = startToolBlockedOnUserSpan(toolA, { call_id: 'a' });
|
||||
const blockedB = startToolBlockedOnUserSpan(toolB, { call_id: 'b' });
|
||||
|
||||
endToolBlockedOnUserSpan(blockedB, { decision: 'cancel' });
|
||||
|
||||
const recordA = mockSpans.find(
|
||||
(s) =>
|
||||
s.name === 'qwen-code.tool.blocked_on_user' &&
|
||||
s.attributes['tool.call_id'] === 'a',
|
||||
);
|
||||
const recordB = mockSpans.find(
|
||||
(s) =>
|
||||
s.name === 'qwen-code.tool.blocked_on_user' &&
|
||||
s.attributes['tool.call_id'] === 'b',
|
||||
);
|
||||
// Only B is ended; A still active.
|
||||
expect(recordB?.ended).toBe(true);
|
||||
expect(recordA?.ended).toBeFalsy();
|
||||
|
||||
endToolBlockedOnUserSpan(blockedA, { decision: 'proceed_once' });
|
||||
expect(recordA?.attributes['decision']).toBe('proceed_once');
|
||||
expect(recordB?.attributes['decision']).toBe('cancel');
|
||||
|
||||
endToolSpan(toolA, { success: true });
|
||||
endToolSpan(toolB, { success: false, error: 'cancelled' });
|
||||
});
|
||||
|
||||
it('falls back to resolveParentContext when the tool span was already ended', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
// Simulate someone passing an already-ended tool span — the helper
|
||||
// should still produce a span (correlated via the standard fallback
|
||||
// chain) instead of crashing.
|
||||
endToolSpan(toolSpan, { success: true });
|
||||
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan);
|
||||
expect(
|
||||
mockSpans.find((s) => s.name === 'qwen-code.tool.blocked_on_user'),
|
||||
).toBeDefined();
|
||||
|
||||
endToolBlockedOnUserSpan(blockedSpan, { decision: 'proceed_once' });
|
||||
});
|
||||
});
|
||||
|
||||
describe('hook spans (#3731 Phase 2)', () => {
|
||||
it('parents under the active tool span when called inside runInToolSpanContext', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
|
||||
let hookSpan!: ReturnType<typeof startHookSpan>;
|
||||
runInToolSpanContext(toolSpan, () => {
|
||||
hookSpan = startHookSpan({
|
||||
hookEvent: 'PreToolUse',
|
||||
toolName: 'Bash',
|
||||
toolUseId: 'use-1',
|
||||
});
|
||||
});
|
||||
|
||||
const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook');
|
||||
expect(hookRecord).toBeDefined();
|
||||
expect(hookRecord?.parentContext).toBeDefined();
|
||||
expect(hookRecord?.attributes['hook_event']).toBe('PreToolUse');
|
||||
expect(hookRecord?.attributes['tool.name']).toBe('Bash');
|
||||
expect(hookRecord?.attributes['tool.use_id']).toBe('use-1');
|
||||
|
||||
endHookSpan(hookSpan, { success: true, shouldProceed: true });
|
||||
endToolSpan(toolSpan, { success: true });
|
||||
});
|
||||
|
||||
it('records shouldProceed/blockType when PreToolUse blocks', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
let hookSpan!: ReturnType<typeof startHookSpan>;
|
||||
runInToolSpanContext(toolSpan, () => {
|
||||
hookSpan = startHookSpan({
|
||||
hookEvent: 'PreToolUse',
|
||||
toolName: 'Bash',
|
||||
});
|
||||
});
|
||||
endHookSpan(hookSpan, {
|
||||
success: true,
|
||||
shouldProceed: false,
|
||||
blockType: 'denied',
|
||||
});
|
||||
|
||||
const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook');
|
||||
expect(hookRecord?.attributes['should_proceed']).toBe(false);
|
||||
expect(hookRecord?.attributes['block_type']).toBe('denied');
|
||||
// Blocking is intentional, not an error — status must stay UNSET.
|
||||
expect(hookRecord?.statuses).toHaveLength(0);
|
||||
|
||||
endToolSpan(toolSpan, { success: false, error: 'denied' });
|
||||
});
|
||||
|
||||
it('records shouldStop/hasAdditionalContext on PostToolUse', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
let hookSpan!: ReturnType<typeof startHookSpan>;
|
||||
runInToolSpanContext(toolSpan, () => {
|
||||
hookSpan = startHookSpan({
|
||||
hookEvent: 'PostToolUse',
|
||||
toolName: 'Bash',
|
||||
});
|
||||
});
|
||||
endHookSpan(hookSpan, {
|
||||
success: true,
|
||||
shouldStop: true,
|
||||
hasAdditionalContext: true,
|
||||
});
|
||||
|
||||
const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook');
|
||||
expect(hookRecord?.attributes['should_stop']).toBe(true);
|
||||
expect(hookRecord?.attributes['has_additional_context']).toBe(true);
|
||||
expect(hookRecord?.statuses).toHaveLength(0);
|
||||
|
||||
endToolSpan(toolSpan, { success: true });
|
||||
});
|
||||
|
||||
it('marks status ERROR only when the hook itself threw', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
let hookSpan!: ReturnType<typeof startHookSpan>;
|
||||
runInToolSpanContext(toolSpan, () => {
|
||||
hookSpan = startHookSpan({
|
||||
hookEvent: 'PostToolUseFailure',
|
||||
toolName: 'Bash',
|
||||
isInterrupt: true,
|
||||
});
|
||||
});
|
||||
endHookSpan(hookSpan, { success: false, error: 'hook crashed' });
|
||||
|
||||
const hookRecord = mockSpans.find((s) => s.name === 'qwen-code.hook');
|
||||
expect(hookRecord?.statuses[0]?.code).toBe(SpanStatusCode.ERROR);
|
||||
expect(hookRecord?.statuses[0]?.message).toBe('hook crashed');
|
||||
expect(hookRecord?.attributes['is_interrupt']).toBe(true);
|
||||
|
||||
endToolSpan(toolSpan, { success: false, error: 'cancelled' });
|
||||
});
|
||||
|
||||
it('returns NOOP span when SDK is not initialized', () => {
|
||||
mockState.sdkInitialized = false;
|
||||
const hookSpan = startHookSpan({
|
||||
hookEvent: 'PreToolUse',
|
||||
toolName: 'Bash',
|
||||
});
|
||||
expect(hookSpan.spanContext().traceId).toBe('0'.repeat(32));
|
||||
endHookSpan(hookSpan, { success: true });
|
||||
});
|
||||
});
|
||||
|
||||
describe('toolContext ALS lifecycle', () => {
|
||||
it('runInToolSpanContext scopes toolContext via run(), not enterWith', () => {
|
||||
const toolSpan = startToolSpan('Bash');
|
||||
|
|
@ -714,4 +938,115 @@ describe('session-tracing', () => {
|
|||
endToolSpan(toolSpan, { success: true });
|
||||
});
|
||||
});
|
||||
|
||||
describe('TTL safety net (#4321 review)', () => {
|
||||
it('marks stale spans with ttl_expired + duration_ms before ending them', () => {
|
||||
const toolSpan = startToolSpan('staleTool');
|
||||
const record = mockSpans.find((s) => s.name === 'qwen-code.tool')!;
|
||||
|
||||
// 31 minutes after the span started — past the 30-min TTL.
|
||||
const staleNow = Date.now() + 31 * 60 * 1000;
|
||||
runTTLSweepForTesting(staleNow);
|
||||
|
||||
expect(record.ended).toBe(true);
|
||||
// Without the sentinel attrs, operators couldn't tell a TTL-aborted
|
||||
// span from a deliberately-ended span that lost attribution.
|
||||
expect(record.attributes['qwen-code.span.ttl_expired']).toBe(true);
|
||||
expect(
|
||||
record.attributes['qwen-code.span.duration_ms'] as number,
|
||||
).toBeGreaterThanOrEqual(31 * 60 * 1000 - 1000);
|
||||
|
||||
// Calling endToolSpan after the TTL fires must still be safe — span
|
||||
// already ended, attempt is a no-op.
|
||||
endToolSpan(toolSpan, { success: false });
|
||||
});
|
||||
|
||||
it('does not mark spans that were ended before TTL expiry', () => {
|
||||
const toolSpan = startToolSpan('liveTool');
|
||||
const record = mockSpans.find((s) => s.name === 'qwen-code.tool')!;
|
||||
|
||||
// End normally, then run a sweep. The span is already ended → the
|
||||
// sweep must not retroactively stamp ttl_expired on it.
|
||||
endToolSpan(toolSpan, { success: true });
|
||||
runTTLSweepForTesting(Date.now() + 31 * 60 * 1000);
|
||||
|
||||
expect(record.attributes['qwen-code.span.ttl_expired']).toBeUndefined();
|
||||
});
|
||||
|
||||
it('stamps decision=aborted/source=system on TTL-expired blocked_on_user spans', () => {
|
||||
// The blocked-span branch in sweepStaleSpans tags the canonical
|
||||
// taxonomy so dashboards filtering by `decision: 'aborted'` count
|
||||
// walk-aways alongside explicit user aborts.
|
||||
const toolSpan = startToolSpan('blockedStaleParent');
|
||||
const blockedSpan = startToolBlockedOnUserSpan(toolSpan, {
|
||||
tool_name: 'blockedStaleParent',
|
||||
});
|
||||
const blockedRecord = mockSpans.find(
|
||||
(s) => s.name === 'qwen-code.tool.blocked_on_user',
|
||||
)!;
|
||||
|
||||
runTTLSweepForTesting(Date.now() + 31 * 60 * 1000);
|
||||
|
||||
expect(blockedRecord.ended).toBe(true);
|
||||
expect(blockedRecord.attributes['qwen-code.span.ttl_expired']).toBe(true);
|
||||
expect(blockedRecord.attributes['decision']).toBe('aborted');
|
||||
expect(blockedRecord.attributes['source']).toBe('system');
|
||||
|
||||
// Cleanup the still-active tool span.
|
||||
endToolBlockedOnUserSpan(blockedSpan);
|
||||
endToolSpan(toolSpan, { success: false });
|
||||
});
|
||||
});
|
||||
|
||||
describe('truncateSpanError (#4321 review)', () => {
|
||||
it('returns short strings unchanged', () => {
|
||||
expect(truncateSpanError('short message')).toBe('short message');
|
||||
expect(truncateSpanError('')).toBe('');
|
||||
});
|
||||
|
||||
it('truncates strings over 1024 chars and appends a sentinel suffix', () => {
|
||||
const oversized = 'a'.repeat(2000);
|
||||
const truncated = truncateSpanError(oversized);
|
||||
expect(truncated.length).toBeLessThan(oversized.length);
|
||||
expect(truncated.endsWith('…[truncated]')).toBe(true);
|
||||
expect(truncated.startsWith('a'.repeat(1024))).toBe(true);
|
||||
});
|
||||
|
||||
it('does not double-suffix already-truncated input', () => {
|
||||
// Hard guarantee: the sentinel is only appended when the input
|
||||
// exceeds the cap. A short string with the suffix already present
|
||||
// would NOT pass back through truncate at production sites — but
|
||||
// sanity-check the boundary anyway.
|
||||
const exactlyAtCap = 'b'.repeat(1024);
|
||||
expect(truncateSpanError(exactlyAtCap)).toBe(exactlyAtCap);
|
||||
});
|
||||
|
||||
it('backs up one code unit when the cut would split a surrogate pair (#4321)', () => {
|
||||
// OTLP/gRPC collectors reject batches with invalid UTF-8. If the
|
||||
// 1024-char cap lands between the high + low surrogate of an
|
||||
// emoji or rare CJK character, truncateSpanError must back up one
|
||||
// code unit so we never emit a lone high surrogate.
|
||||
// 🚀 is U+1F680, encoded as the surrogate pair [0xD83D, 0xDE80].
|
||||
// Put it so the high surrogate is at char index 1023 (last byte
|
||||
// BEFORE the cap), low surrogate at 1024 (first byte AFTER the
|
||||
// cap): pad with 1023 'a's, then the rocket, then enough filler
|
||||
// to push above the cap.
|
||||
const oversized = 'a'.repeat(1023) + '🚀' + 'b'.repeat(100);
|
||||
const truncated = truncateSpanError(oversized);
|
||||
// The truncated string must not END with a lone high surrogate
|
||||
// (code point in [0xD800, 0xDBFF]). The implementation backs up
|
||||
// one code unit when needed.
|
||||
const lastBeforeSentinel = truncated.slice(0, -'…[truncated]'.length);
|
||||
const lastCharCode = lastBeforeSentinel.charCodeAt(
|
||||
lastBeforeSentinel.length - 1,
|
||||
);
|
||||
expect(lastCharCode).not.toBeGreaterThanOrEqual(0xd800);
|
||||
// Validate there are no orphan high surrogates anywhere in the
|
||||
// string — `Buffer.from(s, 'utf16le')` doesn't validate
|
||||
// surrogate pairs (#4321 review-9), so test the property
|
||||
// directly with a regex that matches a high surrogate NOT
|
||||
// followed by a low surrogate.
|
||||
expect(truncated).not.toMatch(/[\uD800-\uDBFF](?![\uDC00-\uDFFF])/);
|
||||
});
|
||||
});
|
||||
});
|
||||
|
|
|
|||
|
|
@ -17,9 +17,11 @@ import {
|
|||
import type { Config } from '../config/config.js';
|
||||
import {
|
||||
SERVICE_NAME,
|
||||
SPAN_HOOK,
|
||||
SPAN_INTERACTION,
|
||||
SPAN_LLM_REQUEST,
|
||||
SPAN_TOOL,
|
||||
SPAN_TOOL_BLOCKED_ON_USER,
|
||||
SPAN_TOOL_EXECUTION,
|
||||
} from './constants.js';
|
||||
import { clearDetailedSpanState } from './detailed-span-attributes.js';
|
||||
|
|
@ -121,26 +123,75 @@ let lastInteractionCtx: SpanContext | undefined;
|
|||
let cleanupIntervalStarted = false;
|
||||
const SPAN_TTL_MS = 30 * 60 * 1000;
|
||||
|
||||
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;
|
||||
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)}`,
|
||||
);
|
||||
}
|
||||
}
|
||||
activeSpans.delete(spanId);
|
||||
strongSpans.delete(spanId);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function ensureCleanupInterval(): void {
|
||||
if (cleanupIntervalStarted) return;
|
||||
cleanupIntervalStarted = true;
|
||||
const interval = setInterval(() => {
|
||||
const cutoff = Date.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;
|
||||
ctx.span.end();
|
||||
}
|
||||
activeSpans.delete(spanId);
|
||||
strongSpans.delete(spanId);
|
||||
}
|
||||
}
|
||||
}, 60_000);
|
||||
const interval = setInterval(() => sweepStaleSpans(Date.now()), 60_000);
|
||||
if (typeof interval.unref === 'function') {
|
||||
interval.unref();
|
||||
}
|
||||
|
|
@ -150,6 +201,35 @@ function getSpanId(span: Span): string {
|
|||
return span.spanContext().spanId || '';
|
||||
}
|
||||
|
||||
const SPAN_ERROR_MAX_CHARS = 1024;
|
||||
|
||||
/**
|
||||
* Bound the size of error strings written to span attributes / status
|
||||
* messages. Hook server responses, raw exception stacks, or malicious
|
||||
* inputs can be unbounded; some OTel backends drop the entire span when
|
||||
* any field exceeds their limit (#4321 review-3 wenshao Critical).
|
||||
*
|
||||
* Truncates by UTF-16 code units (`String.length`/`String.slice`), not
|
||||
* bytes — for ASCII-heavy text this approximates a 1KB byte limit, but
|
||||
* CJK/emoji-heavy errors can land in the ~2-3KB range after UTF-8
|
||||
* encoding. That's still well under all major OTel backends'
|
||||
* per-attribute limits (Jaeger ~64KB, Honeycomb ~64KB, OTLP default
|
||||
* ~32KB), so we keep the simpler char-count bound rather than paying
|
||||
* the encoder cost on every endXSpan (review-4 follow-up).
|
||||
*/
|
||||
export function truncateSpanError(s: string): string {
|
||||
if (s.length <= SPAN_ERROR_MAX_CHARS) return s;
|
||||
// Back up one code unit if the cut lands on a high surrogate so we
|
||||
// don't emit a lone surrogate followed by the sentinel — strict
|
||||
// OTLP/gRPC collectors reject span batches with invalid UTF-8
|
||||
// (a lone high surrogate encodes to an invalid byte sequence)
|
||||
// (#4321 review-8 wenshao Suggestion).
|
||||
let end = SPAN_ERROR_MAX_CHARS;
|
||||
const code = s.charCodeAt(end - 1);
|
||||
if (code >= 0xd800 && code <= 0xdbff) end--;
|
||||
return s.slice(0, end) + '…[truncated]';
|
||||
}
|
||||
|
||||
function getTracer() {
|
||||
return trace.getTracer(SERVICE_NAME, '1.0.0');
|
||||
}
|
||||
|
|
@ -287,7 +367,8 @@ export function endLLMRequestSpan(
|
|||
if (metadata.outputTokens !== undefined)
|
||||
endAttributes['output_tokens'] = metadata.outputTokens;
|
||||
endAttributes['success'] = metadata.success;
|
||||
if (metadata.error !== undefined) endAttributes['error'] = metadata.error;
|
||||
if (metadata.error !== undefined)
|
||||
endAttributes['error'] = truncateSpanError(metadata.error);
|
||||
}
|
||||
|
||||
spanCtx.span.setAttributes(endAttributes);
|
||||
|
|
@ -297,7 +378,9 @@ export function endLLMRequestSpan(
|
|||
} else {
|
||||
spanCtx.span.setStatus({
|
||||
code: SpanStatusCode.ERROR,
|
||||
message: metadata.error ?? 'unknown error',
|
||||
message: metadata.error
|
||||
? truncateSpanError(metadata.error)
|
||||
: 'unknown error',
|
||||
});
|
||||
}
|
||||
} catch (error) {
|
||||
|
|
@ -394,7 +477,8 @@ export function endToolSpan(span: Span, metadata?: ToolSpanMetadata): void {
|
|||
if (metadata) {
|
||||
if (metadata.success !== undefined)
|
||||
endAttributes['success'] = metadata.success;
|
||||
if (metadata.error !== undefined) endAttributes['error'] = metadata.error;
|
||||
if (metadata.error !== undefined)
|
||||
endAttributes['error'] = truncateSpanError(metadata.error);
|
||||
}
|
||||
|
||||
spanCtx.span.setAttributes(endAttributes);
|
||||
|
|
@ -405,7 +489,9 @@ export function endToolSpan(span: Span, metadata?: ToolSpanMetadata): void {
|
|||
} else {
|
||||
spanCtx.span.setStatus({
|
||||
code: SpanStatusCode.ERROR,
|
||||
message: metadata.error ?? 'tool error',
|
||||
message: metadata.error
|
||||
? truncateSpanError(metadata.error)
|
||||
: 'tool error',
|
||||
});
|
||||
}
|
||||
}
|
||||
|
|
@ -491,7 +577,8 @@ export function endToolExecutionSpan(
|
|||
if (metadata) {
|
||||
if (metadata.success !== undefined)
|
||||
endAttributes['success'] = metadata.success;
|
||||
if (metadata.error !== undefined) endAttributes['error'] = metadata.error;
|
||||
if (metadata.error !== undefined)
|
||||
endAttributes['error'] = truncateSpanError(metadata.error);
|
||||
}
|
||||
|
||||
spanCtx.span.setAttributes(endAttributes);
|
||||
|
|
@ -506,7 +593,9 @@ export function endToolExecutionSpan(
|
|||
} else {
|
||||
spanCtx.span.setStatus({
|
||||
code: SpanStatusCode.ERROR,
|
||||
message: metadata.error ?? 'tool execution error',
|
||||
message: metadata.error
|
||||
? truncateSpanError(metadata.error)
|
||||
: 'tool execution error',
|
||||
});
|
||||
}
|
||||
}
|
||||
|
|
@ -527,6 +616,243 @@ export function endToolExecutionSpan(
|
|||
strongSpans.delete(spanId);
|
||||
}
|
||||
|
||||
// --- Tool Blocked-on-User Spans ---
|
||||
|
||||
export type ToolBlockedDecision =
|
||||
| 'proceed_once'
|
||||
| 'proceed_always'
|
||||
| 'cancel'
|
||||
| 'aborted'
|
||||
| 'auto_approved'
|
||||
// System-error close — distinct from user 'cancel' so dashboards counting
|
||||
// user cancels don't double-count thrown exceptions in the approval path.
|
||||
| 'error';
|
||||
|
||||
export type ToolBlockedSource = 'cli' | 'ide' | 'hook' | 'auto' | 'system';
|
||||
|
||||
/**
|
||||
* Brackets the time a tool spends in `awaiting_approval` waiting on the user.
|
||||
*
|
||||
* The parent is passed explicitly because this span starts BEFORE the tool
|
||||
* body's `runInToolSpanContext` block — so `toolContext.getStore()` is empty.
|
||||
* Passing the span object also avoids the `findLast`-by-type concurrency bug
|
||||
* (claude-code's sessionTracing has it; we deliberately don't).
|
||||
*/
|
||||
export function startToolBlockedOnUserSpan(
|
||||
toolSpan: Span,
|
||||
attrs?: { tool_name?: string; call_id?: string },
|
||||
): Span {
|
||||
if (!isTelemetrySdkInitialized()) {
|
||||
return NOOP_SPAN;
|
||||
}
|
||||
// Idempotent — kick off the 30-min TTL cleanup in case this span is
|
||||
// started in a code path where no interaction span has been created
|
||||
// yet (sub-agent tool calls, side queries, future patterns).
|
||||
ensureCleanupInterval();
|
||||
|
||||
const parentSpanId = getSpanId(toolSpan);
|
||||
const parentSpanCtx = activeSpans.get(parentSpanId)?.deref();
|
||||
// If the tool span was already ended (defensive — shouldn't happen on the
|
||||
// happy path), fall back to the standard parent-resolution chain so we
|
||||
// still produce a span correlated with the session.
|
||||
if (!parentSpanCtx) {
|
||||
debugLogger.debug(
|
||||
'startToolBlockedOnUserSpan: tool span not in activeSpans (already ended?) — using resolveParentContext fallback',
|
||||
);
|
||||
}
|
||||
const ctx = parentSpanCtx
|
||||
? trace.setSpan(otelContext.active(), parentSpanCtx.span)
|
||||
: resolveParentContext(undefined);
|
||||
|
||||
const attributes: Attributes = {};
|
||||
if (attrs?.tool_name !== undefined) attributes['tool.name'] = attrs.tool_name;
|
||||
if (attrs?.call_id !== undefined) attributes['tool.call_id'] = attrs.call_id;
|
||||
|
||||
const span = getTracer().startSpan(
|
||||
SPAN_TOOL_BLOCKED_ON_USER,
|
||||
{ kind: SpanKind.INTERNAL, attributes },
|
||||
ctx,
|
||||
);
|
||||
|
||||
const spanId = getSpanId(span);
|
||||
const spanContextObj: SpanContext = {
|
||||
span,
|
||||
startTime: Date.now(),
|
||||
attributes: attributes as Record<string, string | number | boolean>,
|
||||
type: 'tool.blocked_on_user',
|
||||
};
|
||||
activeSpans.set(spanId, new WeakRef(spanContextObj));
|
||||
strongSpans.set(spanId, spanContextObj);
|
||||
|
||||
return span;
|
||||
}
|
||||
|
||||
/**
|
||||
* Status stays UNSET — waiting on the user is neither OK nor ERROR.
|
||||
* The decision/source attributes are the canonical signal.
|
||||
*/
|
||||
export function endToolBlockedOnUserSpan(
|
||||
span: Span,
|
||||
metadata?: {
|
||||
decision?: ToolBlockedDecision;
|
||||
source?: ToolBlockedSource;
|
||||
},
|
||||
): void {
|
||||
const spanId = getSpanId(span);
|
||||
const spanCtx = activeSpans.get(spanId)?.deref();
|
||||
if (!spanCtx || spanCtx.ended) return;
|
||||
|
||||
spanCtx.ended = true;
|
||||
|
||||
try {
|
||||
const duration = Date.now() - spanCtx.startTime;
|
||||
const endAttributes: Attributes = { duration_ms: duration };
|
||||
if (metadata?.decision !== undefined)
|
||||
endAttributes['decision'] = metadata.decision;
|
||||
if (metadata?.source !== undefined)
|
||||
endAttributes['source'] = metadata.source;
|
||||
spanCtx.span.setAttributes(endAttributes);
|
||||
} catch (error) {
|
||||
debugLogger.warn(
|
||||
`Failed to update blocked_on_user span attributes: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
}
|
||||
try {
|
||||
spanCtx.span.end();
|
||||
} catch (error) {
|
||||
debugLogger.warn(
|
||||
`Failed to end blocked_on_user span: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
}
|
||||
activeSpans.delete(spanId);
|
||||
strongSpans.delete(spanId);
|
||||
}
|
||||
|
||||
// --- Hook Spans ---
|
||||
|
||||
export type HookEvent = 'PreToolUse' | 'PostToolUse' | 'PostToolUseFailure';
|
||||
|
||||
export interface StartHookSpanOptions {
|
||||
hookEvent: HookEvent;
|
||||
toolName: string;
|
||||
toolUseId?: string;
|
||||
/** PostToolUseFailure only: true when the failure is a user interrupt. */
|
||||
isInterrupt?: boolean;
|
||||
}
|
||||
|
||||
export interface HookSpanMetadata {
|
||||
/** Whether the hook fire site completed without throwing. */
|
||||
success?: boolean;
|
||||
/** PreToolUse: false means the hook blocked tool execution. */
|
||||
shouldProceed?: boolean;
|
||||
/** PostToolUse: true means the hook stopped further processing. */
|
||||
shouldStop?: boolean;
|
||||
/** Discriminator for blocking decision when applicable. */
|
||||
blockType?: 'denied' | 'ask' | 'stop';
|
||||
hasAdditionalContext?: boolean;
|
||||
/** Hook threw — span ends as ERROR with this message. */
|
||||
error?: string;
|
||||
}
|
||||
|
||||
export function startHookSpan(opts: StartHookSpanOptions): Span {
|
||||
if (!isTelemetrySdkInitialized()) {
|
||||
return NOOP_SPAN;
|
||||
}
|
||||
// Same defensive cleanup-interval kick as startToolBlockedOnUserSpan —
|
||||
// hook spans may run before any interaction span has been created.
|
||||
ensureCleanupInterval();
|
||||
|
||||
// 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).
|
||||
const parentCtx =
|
||||
toolContext.getStore() ?? interactionContext.getStore() ?? undefined;
|
||||
const ctx = resolveParentContext(parentCtx);
|
||||
|
||||
const attributes: Attributes = {
|
||||
hook_event: opts.hookEvent,
|
||||
'tool.name': opts.toolName,
|
||||
};
|
||||
if (opts.toolUseId !== undefined) attributes['tool.use_id'] = opts.toolUseId;
|
||||
if (opts.isInterrupt !== undefined)
|
||||
attributes['is_interrupt'] = opts.isInterrupt;
|
||||
|
||||
const span = getTracer().startSpan(
|
||||
SPAN_HOOK,
|
||||
{ kind: SpanKind.INTERNAL, attributes },
|
||||
ctx,
|
||||
);
|
||||
|
||||
const spanId = getSpanId(span);
|
||||
const spanContextObj: SpanContext = {
|
||||
span,
|
||||
startTime: Date.now(),
|
||||
attributes: attributes as Record<string, string | number | boolean>,
|
||||
type: 'hook',
|
||||
};
|
||||
activeSpans.set(spanId, new WeakRef(spanContextObj));
|
||||
strongSpans.set(spanId, spanContextObj);
|
||||
|
||||
return span;
|
||||
}
|
||||
|
||||
/**
|
||||
* Status: UNSET on normal flow (including blocking decisions like
|
||||
* shouldProceed: false or shouldStop: true — those are intentional, not
|
||||
* errors). Only an actual hook-side throw (caught by the safelyFire wrapper
|
||||
* or rethrown) maps to ERROR via the `error` metadata field.
|
||||
*/
|
||||
export function endHookSpan(span: Span, metadata?: HookSpanMetadata): void {
|
||||
const spanId = getSpanId(span);
|
||||
const spanCtx = activeSpans.get(spanId)?.deref();
|
||||
if (!spanCtx || spanCtx.ended) return;
|
||||
|
||||
spanCtx.ended = true;
|
||||
|
||||
try {
|
||||
const duration = Date.now() - spanCtx.startTime;
|
||||
const endAttributes: Attributes = { duration_ms: duration };
|
||||
|
||||
if (metadata) {
|
||||
if (metadata.success !== undefined)
|
||||
endAttributes['success'] = metadata.success;
|
||||
if (metadata.shouldProceed !== undefined)
|
||||
endAttributes['should_proceed'] = metadata.shouldProceed;
|
||||
if (metadata.shouldStop !== undefined)
|
||||
endAttributes['should_stop'] = metadata.shouldStop;
|
||||
if (metadata.blockType !== undefined)
|
||||
endAttributes['block_type'] = metadata.blockType;
|
||||
if (metadata.hasAdditionalContext !== undefined)
|
||||
endAttributes['has_additional_context'] = metadata.hasAdditionalContext;
|
||||
if (metadata.error !== undefined)
|
||||
endAttributes['error'] = truncateSpanError(metadata.error);
|
||||
}
|
||||
|
||||
spanCtx.span.setAttributes(endAttributes);
|
||||
|
||||
if (metadata?.error !== undefined) {
|
||||
spanCtx.span.setStatus({
|
||||
code: SpanStatusCode.ERROR,
|
||||
message: truncateSpanError(metadata.error),
|
||||
});
|
||||
}
|
||||
} catch (error) {
|
||||
debugLogger.warn(
|
||||
`Failed to update hook span attributes/status: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
}
|
||||
try {
|
||||
spanCtx.span.end();
|
||||
} catch (error) {
|
||||
debugLogger.warn(
|
||||
`Failed to end hook span: ${error instanceof Error ? error.message : String(error)}`,
|
||||
);
|
||||
}
|
||||
activeSpans.delete(spanId);
|
||||
strongSpans.delete(spanId);
|
||||
}
|
||||
|
||||
// --- Interaction Span Attribute Access ---
|
||||
|
||||
export function getActiveInteractionSpan(): Span | undefined {
|
||||
|
|
@ -546,3 +872,12 @@ export function clearSessionTracingForTesting(): void {
|
|||
lastInteractionCtx = undefined;
|
||||
clearDetailedSpanState();
|
||||
}
|
||||
|
||||
/**
|
||||
* Test-only: invoke the TTL sweep with a synthetic `now`. Lets tests
|
||||
* exercise the stale-span path without waiting 30 minutes or stubbing
|
||||
* setInterval globally.
|
||||
*/
|
||||
export function runTTLSweepForTesting(now: number): void {
|
||||
sweepStaleSpans(now);
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue