From 38ba22d9c306c6c4afa82d471d733ecf611cb893 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 17:49:24 +0800 Subject: [PATCH 01/21] =?UTF-8?q?feat(telemetry):=20Phase=202=20=E2=80=94?= =?UTF-8?q?=20tool.blocked=5Fon=5Fuser=20+=20hook=20spans?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 261 ++++++++++ packages/core/src/core/coreToolScheduler.ts | 455 ++++++++++++++---- packages/core/src/telemetry/constants.ts | 2 + packages/core/src/telemetry/index.ts | 9 + .../src/telemetry/session-tracing.test.ts | 222 +++++++++ .../core/src/telemetry/session-tracing.ts | 223 +++++++++ 6 files changed, 1088 insertions(+), 84 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index ec9be0ce3d5..c3edaf67595 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -67,6 +67,17 @@ type ToolSpanRecord = { * tests can assert success/error/cancelled values are forwarded correctly. */ endMetadata?: { success?: boolean; error?: string; cancelled?: boolean }; + /** Metadata passed to endToolBlockedOnUserSpan. */ + blockedMetadata?: { decision?: string; source?: string }; + /** Metadata passed to endHookSpan. */ + hookMetadata?: { + success?: boolean; + shouldProceed?: boolean; + shouldStop?: boolean; + blockType?: string; + hasAdditionalContext?: boolean; + error?: string; + }; }; const toolSpanRecords = vi.hoisted((): ToolSpanRecord[] => []); @@ -162,6 +173,53 @@ vi.mock('../telemetry/session-tracing.js', () => ({ span.ended = true; }, ), + startToolBlockedOnUserSpan: vi.fn( + (_toolSpan: unknown, attrs?: { tool_name?: string; call_id?: string }) => { + const extra: Record = {}; + if (attrs?.tool_name !== undefined) extra['tool.name'] = attrs.tool_name; + if (attrs?.call_id !== undefined) extra['tool.call_id'] = attrs.call_id; + return createMockToolSpan('tool.blocked_on_user', extra); + }, + ), + endToolBlockedOnUserSpan: vi.fn( + ( + span: ToolSpanRecord & ReturnType, + metadata?: { decision?: string; source?: string }, + ) => { + if (metadata) { + span.blockedMetadata = metadata; + } + span.ended = true; + }, + ), + startHookSpan: vi.fn( + (opts: { + hookEvent: string; + toolName: string; + toolUseId?: string; + isInterrupt?: boolean; + }) => { + const attrs: Record = { + hook_event: opts.hookEvent, + 'tool.name': opts.toolName, + }; + if (opts.toolUseId !== undefined) attrs['tool.use_id'] = opts.toolUseId; + if (opts.isInterrupt !== undefined) + attrs['is_interrupt'] = opts.isInterrupt; + return createMockToolSpan('hook', attrs); + }, + ), + endHookSpan: vi.fn( + ( + span: ToolSpanRecord & ReturnType, + metadata?: ToolSpanRecord['hookMetadata'], + ) => { + if (metadata) { + span.hookMetadata = metadata; + } + span.ended = true; + }, + ), startInteractionSpan: vi.fn(), endInteractionSpan: vi.fn(), startLLMRequestSpan: vi.fn(), @@ -3822,6 +3880,209 @@ describe('CoreToolScheduler telemetry spans', () => { // status. cancelled stays falsy. expect(exec!.endMetadata?.cancelled).toBeFalsy(); }); + + // ------------------------------------------------------------------- + // #3731 Phase 2 — tool span lifecycle now spans validating → + // awaiting_approval → executing in one span; blocked_on_user is a child + // span; each hook fire site gets its own hook span. + // ------------------------------------------------------------------- + + function getToolSpans(): ToolSpanRecord[] { + return toolSpanRecords.filter((r) => r.name === 'tool.mockTool'); + } + function getBlockedSpans(): ToolSpanRecord[] { + return toolSpanRecords.filter((r) => r.name === 'tool.blocked_on_user'); + } + function getHookSpans(): ToolSpanRecord[] { + return toolSpanRecords.filter((r) => r.name === 'hook'); + } + + it('tool span is started in _schedule and ended even when pre-hook denies execution (#3731 Phase 2)', async () => { + const messageBus = { + request: vi.fn().mockResolvedValue({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'pre-hook', + success: true, + output: { decision: 'deny', reason: 'denied' }, + }), + }; + await runSingleTool({ messageBus, disableHooks: false }); + + const toolSpans = getToolSpans(); + expect(toolSpans).toHaveLength(1); + expect(toolSpans[0].ended).toBe(true); + // No execution sub-span — request didn't reach _executeToolCallBody. + expect(getExecutionSpan()).toBeUndefined(); + // No blocked span either — the deny path takes the permission_hook + // branch BEFORE awaiting_approval is set. + expect(getBlockedSpans()).toHaveLength(0); + }); + + it('blocked_on_user span ends with cancel when the user rejects (#3731 Phase 2)', async () => { + // Reuses MockEditTool — same setup as the existing edit-cancellation + // test in `CoreToolScheduler edit cancellation`, just instrumented for + // the new Phase 2 spans. + toolSpanRecords.length = 0; + const mockEditTool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => mockEditTool, + ensureTool: async () => mockEditTool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => mockEditTool, + getToolByDisplayName: () => mockEditTool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({ + model: 'test-model', + authType: 'gemini', + }), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const onAllToolCallsComplete = vi.fn(); + const onToolCallsUpdate = vi.fn(); + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete, + onToolCallsUpdate, + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'block-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-block', + }, + ], + new AbortController().signal, + ); + + // The blocked span is open while waiting for the user. + const blockedSpans = toolSpanRecords.filter( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpans).toHaveLength(1); + expect(blockedSpans[0].ended).toBe(false); + + const awaitingCall = (await waitForStatus( + onToolCallsUpdate, + 'awaiting_approval', + )) as WaitingToolCall; + await awaitingCall.confirmationDetails.onConfirm( + ToolConfirmationOutcome.Cancel, + ); + + // After cancel: blocked + tool spans both ended; decision/source recorded. + expect(blockedSpans[0].ended).toBe(true); + expect(blockedSpans[0].blockedMetadata?.decision).toBe('cancel'); + expect(blockedSpans[0].blockedMetadata?.source).toBe('cli'); + + const toolSpans = toolSpanRecords.filter( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpans).toHaveLength(1); + expect(toolSpans[0].ended).toBe(true); + }); + + it('hook span records shouldProceed=false / blockType=denied when pre-hook blocks (#3731 Phase 2)', async () => { + const messageBus = { + request: vi.fn().mockResolvedValue({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'pre-hook', + success: true, + output: { decision: 'block', reason: 'denied' }, + }), + }; + await runSingleTool({ messageBus, disableHooks: false }); + + // The PreToolUse hook span is the only one fired in this path. + const hookSpans = getHookSpans(); + expect(hookSpans).toHaveLength(1); + expect(hookSpans[0].attributes['hook_event']).toBe('PreToolUse'); + expect(hookSpans[0].hookMetadata?.success).toBe(true); + expect(hookSpans[0].hookMetadata?.shouldProceed).toBe(false); + expect(hookSpans[0].hookMetadata?.blockType).toBe('denied'); + }); + + it('hook span records shouldStop=true when post-hook stops execution (#3731 Phase 2)', async () => { + // Hook protocol: continue:false + stopReason on the post-hook response + // is what the production code maps to shouldStop=true. + const messageBus = { + request: vi + .fn() + .mockResolvedValueOnce({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'pre-hook', + success: true, + output: { decision: 'allow' }, + }) + .mockResolvedValueOnce({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'post-hook', + success: true, + output: { + decision: 'allow', + continue: false, + stopReason: 'stop reason', + }, + }), + }; + await runSingleTool({ messageBus, disableHooks: false }); + + const postHookSpan = getHookSpans().find( + (s) => s.attributes['hook_event'] === 'PostToolUse', + ); + expect(postHookSpan).toBeDefined(); + expect(postHookSpan!.hookMetadata?.shouldStop).toBe(true); + expect(postHookSpan!.hookMetadata?.blockType).toBe('stop'); + }); + + it('every span recorded in a successful tool call is ended (#3731 Phase 2)', async () => { + // Leak guard: every span we record should be ended by the time + // schedule() returns. If a future change forgets to finalize a tool + // span on some terminal path, this assertion catches it. + await runSingleTool(); + + const lifecycleSpans = toolSpanRecords.filter( + (r) => + r.name === 'tool.mockTool' || + r.name === 'tool.execution' || + r.name === 'tool.blocked_on_user' || + r.name === 'hook', + ); + expect(lifecycleSpans.length).toBeGreaterThan(0); + for (const span of lifecycleSpans) { + expect(span.ended).toBe(true); + } + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 2138a84c91c..0764def3542 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -83,8 +83,16 @@ import { runInToolSpanContext, startToolExecutionSpan, endToolExecutionSpan, + startToolBlockedOnUserSpan, + endToolBlockedOnUserSpan, + startHookSpan, + endHookSpan, addToolInputAttributes, addToolResultAttributes, + type ToolBlockedDecision, + type ToolBlockedSource, + type ToolSpanMetadata, + type HookSpanMetadata, } from '../telemetry/index.js'; import { safeJsonStringify } from '../utils/safeJsonStringify.js'; @@ -732,6 +740,21 @@ export class CoreToolScheduler { private isFinalizingToolCalls = false; private isScheduling = false; private validationRetryCounts = new Map(); + // 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(); + // 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). + // + // No global signal.aborted listener: if a session aborts mid-prompt, the + // span is cleaned up by the 30-min TTL safety net in session-tracing.ts. + // We accept the bounded leak in exchange for not threading listener- + // cleanup state through this class. + private blockedSpans = new Map(); private requestQueue: Array<{ request: ToolCallRequestInfo | ToolCallRequestInfo[]; signal: AbortSignal; @@ -982,6 +1005,36 @@ 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. + */ + private finalizeToolSpan(callId: string, metadata?: ToolSpanMetadata): void { + const span = this.toolSpans.get(callId); + if (!span) return; + this.toolSpans.delete(callId); + endToolSpan(span, metadata); + } + + /** + * 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 }); + } + private buildInvocation( tool: AnyDeclarativeTool, args: object, @@ -1293,6 +1346,17 @@ 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. + const toolSpan = startToolSpan(canonicalName, { + tool_name: canonicalName, + call_id: reqInfo.callId, + }); + this.toolSpans.set(reqInfo.callId, toolSpan); + try { if (signal.aborted) { this.setStatusInternal( @@ -1300,6 +1364,8 @@ export class CoreToolScheduler { 'cancelled', 'Tool call cancelled by user.', ); + setToolSpanCancelled(toolSpan); + this.finalizeToolSpan(reqInfo.callId); continue; } @@ -1344,6 +1410,12 @@ export class CoreToolScheduler { ToolErrorType.EXECUTION_DENIED, ), ); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + ); + this.finalizeToolSpan(reqInfo.callId); continue; } @@ -1389,6 +1461,12 @@ export class CoreToolScheduler { error: undefined, errorType: undefined, }); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + 'Plan mode blocked a non-read-only tool call.', + ); + this.finalizeToolSpan(reqInfo.callId); continue; } @@ -1421,6 +1499,12 @@ export class CoreToolScheduler { ToolErrorType.EXECUTION_DENIED, ), ); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + 'Non-interactive mode declined permission', + ); + this.finalizeToolSpan(reqInfo.callId); continue; } @@ -1486,6 +1570,12 @@ export class CoreToolScheduler { ToolErrorType.EXECUTION_DENIED, ), ); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + ); + this.finalizeToolSpan(reqInfo.callId); } continue; } @@ -1504,6 +1594,12 @@ export class CoreToolScheduler { ToolErrorType.EXECUTION_DENIED, ), ); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + 'Background agent cannot prompt for confirmation', + ); + this.finalizeToolSpan(reqInfo.callId); continue; } @@ -1539,6 +1635,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( @@ -1560,6 +1667,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; } @@ -1581,6 +1693,13 @@ export class CoreToolScheduler { explicitErrorType ?? ToolErrorType.UNHANDLED_EXCEPTION, ), ); + this.finalizeBlockedSpan(reqInfo.callId, 'cancel', 'system'); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_TOOL_EXCEPTION, + error instanceof Error ? error.message : String(error), + ); + this.finalizeToolSpan(reqInfo.callId); } } await this.attemptExecutionOfScheduledCalls(signal); @@ -1634,6 +1753,18 @@ 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); + } + this.finalizeBlockedSpan( + callId, + signal.aborted ? 'aborted' : 'cancel', + signal.aborted ? 'system' : 'cli', + ); + this.finalizeToolSpan(callId); } else if (outcome === ToolConfirmationOutcome.ModifyWithEditor) { const waitingToolCall = toolCall as WaitingToolCall; if (isModifiableDeclarativeTool(waitingToolCall.tool)) { @@ -1687,6 +1818,15 @@ 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, 'cli'); } await this.attemptExecutionOfScheduledCalls(signal); } @@ -1873,16 +2013,26 @@ 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) { + toolSpan = startToolSpan(toolName, { + tool_name: toolName, + call_id: callId, + }); + this.toolSpans.set(callId, toolSpan); + } try { await runInToolSpanContext(toolSpan, () => this._executeToolCallBody(scheduledCall, signal, toolSpan), ); } finally { - endToolSpan(toolSpan); + // _executeToolCallBody pre-sets status (OK / FAILURE / CANCELLED) via + // setToolSpan*; finalize without metadata to preserve that. + this.finalizeToolSpan(callId); } } @@ -1927,36 +2077,57 @@ 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, + const hookSpan = startHookSpan({ + hookEvent: 'PreToolUse', + toolName: canonicalName, toolUseId, - permissionMode, - ); - - if (!preHookResult.shouldProceed) { - // Hook blocked the execution - const blockMessage = - preHookResult.blockReason || 'Tool execution blocked by hook'; - const errorResponse = createErrorResponse( - scheduledCall.request, - new Error(blockMessage), - ToolErrorType.EXECUTION_DENIED, - ); - addToolResultAttributes( - this.config, - span, - toolName, - `BLOCKED: ${blockMessage}`, - ); - this.setStatusInternal(callId, 'error', errorResponse); - setToolSpanFailure( - span, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + }); + let endMeta: HookSpanMetadata = { success: false }; + try { + const preHookResult = await firePreToolUseHook( + messageBus, + canonicalName, + toolInput, + toolUseId, + permissionMode, ); - return; + endMeta = { + success: true, + shouldProceed: preHookResult.shouldProceed, + blockType: preHookResult.shouldProceed ? undefined : 'denied', + }; + + if (!preHookResult.shouldProceed) { + // Hook blocked the execution + const blockMessage = + preHookResult.blockReason || 'Tool execution blocked by hook'; + const errorResponse = createErrorResponse( + scheduledCall.request, + new Error(blockMessage), + ToolErrorType.EXECUTION_DENIED, + ); + addToolResultAttributes( + this.config, + span, + toolName, + `BLOCKED: ${blockMessage}`, + ); + this.setStatusInternal(callId, 'error', errorResponse); + setToolSpanFailure( + span, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + ); + return; + } + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + throw e; + } finally { + endHookSpan(hookSpan, endMeta); } } @@ -2053,19 +2224,40 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const hookSpan = startHookSpan({ + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - cancelMessage, - true, - this.config.getApprovalMode(), - ); + isInterrupt: true, + }); + let endMeta: HookSpanMetadata = { success: false }; + try { + const failureHookResult = await safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + cancelMessage, + true, + this.config.getApprovalMode(), + ); + endMeta = { + success: true, + hasAdditionalContext: !!failureHookResult.additionalContext, + }; - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - cancelMessage += `\n\n${failureHookResult.additionalContext}`; + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + cancelMessage += `\n\n${failureHookResult.additionalContext}`; + } + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + throw e; + } finally { + endHookSpan(hookSpan, endMeta); } } addToolResultAttributes( @@ -2091,14 +2283,37 @@ export class CoreToolScheduler { returnDisplay: toolResult.returnDisplay, }; const permissionMode = this.config.getApprovalMode(); - const postHookResult = await firePostToolUseHook( - messageBus, - canonicalName, - toolInput, - toolResponse, + const hookSpan = startHookSpan({ + hookEvent: 'PostToolUse', + toolName: canonicalName, toolUseId, - permissionMode, - ); + }); + let endMeta: HookSpanMetadata = { success: false }; + let postHookResult: Awaited>; + try { + postHookResult = await firePostToolUseHook( + messageBus, + canonicalName, + toolInput, + toolResponse, + toolUseId, + permissionMode, + ); + endMeta = { + success: true, + shouldStop: postHookResult.shouldStop, + hasAdditionalContext: !!postHookResult.additionalContext, + blockType: postHookResult.shouldStop ? 'stop' : undefined, + }; + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + endHookSpan(hookSpan, endMeta); + throw e; + } + endHookSpan(hookSpan, endMeta); // Append additional context from hook if provided if (postHookResult.additionalContext) { @@ -2257,19 +2472,40 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let errorMessage = toolResult.error.message; if (hooksEnabled && messageBus) { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const hookSpan = startHookSpan({ + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - toolResult.error.message, - false, - this.config.getApprovalMode(), - ); + isInterrupt: false, + }); + let endMeta: HookSpanMetadata = { success: false }; + try { + const failureHookResult = await safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + toolResult.error.message, + false, + this.config.getApprovalMode(), + ); + endMeta = { + success: true, + hasAdditionalContext: !!failureHookResult.additionalContext, + }; - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - errorMessage += `\n\n${failureHookResult.additionalContext}`; + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + errorMessage += `\n\n${failureHookResult.additionalContext}`; + } + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + throw e; + } finally { + endHookSpan(hookSpan, endMeta); } } @@ -2316,19 +2552,40 @@ export class CoreToolScheduler { // PostToolUseFailure Hook (user interrupt) let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const hookSpan = startHookSpan({ + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - cancelMessage, - true, - this.config.getApprovalMode(), - ); + isInterrupt: true, + }); + let endMeta: HookSpanMetadata = { success: false }; + try { + const failureHookResult = await safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + cancelMessage, + true, + this.config.getApprovalMode(), + ); + endMeta = { + success: true, + hasAdditionalContext: !!failureHookResult.additionalContext, + }; - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - cancelMessage += `\n\n${failureHookResult.additionalContext}`; + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + cancelMessage += `\n\n${failureHookResult.additionalContext}`; + } + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + throw e; + } finally { + endHookSpan(hookSpan, endMeta); } } addToolResultAttributes( @@ -2344,19 +2601,40 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let exceptionErrorMessage = errorMessage; if (hooksEnabled && messageBus) { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const hookSpan = startHookSpan({ + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - errorMessage, - false, - this.config.getApprovalMode(), - ); + isInterrupt: false, + }); + let endMeta: HookSpanMetadata = { success: false }; + try { + const failureHookResult = await safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + errorMessage, + false, + this.config.getApprovalMode(), + ); + endMeta = { + success: true, + hasAdditionalContext: !!failureHookResult.additionalContext, + }; - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - exceptionErrorMessage += `\n\n${failureHookResult.additionalContext}`; + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + exceptionErrorMessage += `\n\n${failureHookResult.additionalContext}`; + } + } catch (e) { + endMeta = { + success: false, + error: e instanceof Error ? e.message : String(e), + }; + throw e; + } finally { + endHookSpan(hookSpan, endMeta); } } addToolResultAttributes( @@ -2494,6 +2772,15 @@ 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( diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index aac92491304..5fd68c50b5a 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -64,3 +64,5 @@ 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'; +export const SPAN_TOOL_BLOCKED_ON_USER = 'qwen-code.tool.blocked_on_user'; +export const SPAN_HOOK = 'qwen-code.hook'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index f81192ad0db..988e31211a9 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -146,6 +146,10 @@ export { runInToolSpanContext, startToolExecutionSpan, endToolExecutionSpan, + startToolBlockedOnUserSpan, + endToolBlockedOnUserSpan, + startHookSpan, + endHookSpan, getActiveInteractionSpan, } from './session-tracing.js'; export type { @@ -153,6 +157,11 @@ export type { EndInteractionOptions, LLMRequestMetadata, ToolSpanMetadata, + ToolBlockedDecision, + ToolBlockedSource, + HookEvent, + StartHookSpanOptions, + HookSpanMetadata, } from './session-tracing.js'; export { addUserPromptAttributes, diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index 608aa859160..e04c6a8a4e6 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -132,6 +132,10 @@ import { runInToolSpanContext, startToolExecutionSpan, endToolExecutionSpan, + startToolBlockedOnUserSpan, + endToolBlockedOnUserSpan, + startHookSpan, + endHookSpan, getActiveInteractionSpan, clearSessionTracingForTesting, } from './session-tracing.js'; @@ -537,6 +541,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; + 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; + 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; + 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; + 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'); diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index d750a8cf349..b130c89d6e1 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -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'; @@ -527,6 +529,227 @@ export function endToolExecutionSpan( strongSpans.delete(spanId); } +// --- Tool Blocked-on-User Spans --- + +export type ToolBlockedDecision = + | 'proceed_once' + | 'proceed_always' + | 'cancel' + | 'aborted' + | 'auto_approved'; + +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; + } + + 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. + 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, + 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; + } + + // 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, + 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'] = metadata.error; + } + + spanCtx.span.setAttributes(endAttributes); + + if (metadata?.error !== undefined) { + spanCtx.span.setStatus({ + code: SpanStatusCode.ERROR, + message: 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 { From 6767469b23817f076ab1362930c735ebaf2750da Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 19:24:52 +0800 Subject: [PATCH 02/21] =?UTF-8?q?fix(telemetry):=20address=20#4321=20revie?= =?UTF-8?q?w=20=E2=80=94=20Copilot=20inline=20+=20code-reviewer=20+=20sile?= =?UTF-8?q?nt-failure-hunter?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 34 +++++ packages/core/src/core/coreToolScheduler.ts | 133 +++++++++++------- .../core/src/telemetry/session-tracing.ts | 5 +- 3 files changed, 124 insertions(+), 48 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index c3edaf67595..a2ed6f4ad3a 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -2380,6 +2380,13 @@ describe('CoreToolScheduler request queueing', () => { const abortController = new AbortController(); + // toolSpanRecords accumulates across tests in this describe block. + // Snapshot before schedule() so the assertions below see only this + // test's records. + const blockedSpansBefore = toolSpanRecords.filter( + (r) => r.name === 'tool.blocked_on_user', + ).length; + // Schedule multiple tools that need confirmation const requests = [ { @@ -2436,6 +2443,26 @@ describe('CoreToolScheduler request queueing', () => { // Verify approval mode was changed expect(approvalMode).toBe(ApprovalMode.AUTO_EDIT); + + // #3731 Phase 2 / #4321 review: the first tool's blocked span ends as + // 'proceed_always' / cli; the two siblings auto-approved by + // autoApproveCompatiblePendingTools must end as + // 'auto_approved' / 'auto'. Slice from blockedSpansBefore so we see + // only the spans this test produced. + const blockedRecords = toolSpanRecords + .filter((r) => r.name === 'tool.blocked_on_user') + .slice(blockedSpansBefore); + expect(blockedRecords).toHaveLength(3); + const decisions = blockedRecords + .map((r) => r.blockedMetadata?.decision) + .sort(); + const sources = blockedRecords.map((r) => r.blockedMetadata?.source).sort(); + expect(decisions).toEqual([ + 'auto_approved', + 'auto_approved', + 'proceed_always', + ]); + expect(sources).toEqual(['auto', 'auto', 'cli']); }); }); @@ -4010,6 +4037,13 @@ describe('CoreToolScheduler telemetry spans', () => { ); expect(toolSpans).toHaveLength(1); expect(toolSpans[0].ended).toBe(true); + + // #4321 review: the awaiting_approval phase produces exactly one + // blocked_on_user span across the lifecycle. ModifyWithEditor's + // intentional invariant is the same — re-entering awaiting_approval + // must NOT spawn a second span. This assertion guards against a + // future refactor that re-starts the blocked span on each transition. + expect(blockedSpans).toHaveLength(1); }); it('hook span records shouldProceed=false / blockType=denied when pre-hook blocks (#3731 Phase 2)', async () => { diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 0764def3542..c315923761c 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1035,6 +1035,17 @@ export class CoreToolScheduler { endToolBlockedOnUserSpan(span, { decision, source }); } + /** + * 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'; + } + private buildInvocation( tool: AnyDeclarativeTool, args: object, @@ -1351,9 +1362,10 @@ export class CoreToolScheduler { // 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. const toolSpan = startToolSpan(canonicalName, { - tool_name: canonicalName, - call_id: reqInfo.callId, + 'tool.call_id': reqInfo.callId, }); this.toolSpans.set(reqInfo.callId, toolSpan); @@ -1693,7 +1705,10 @@ export class CoreToolScheduler { explicitErrorType ?? ToolErrorType.UNHANDLED_EXCEPTION, ), ); - this.finalizeBlockedSpan(reqInfo.callId, 'cancel', 'system'); + // 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, @@ -1728,6 +1743,47 @@ export class CoreToolScheduler { // processing and potential re-execution. if (!toolCall) return; + try { + await this._handleConfirmationResponseInner( + callId, + toolCall, + originalOnConfirm, + outcome, + signal, + payload, + ); + } catch (error) { + // Defensive: any throw from originalOnConfirm / modifyWithEditor / + // _applyInlineModify / attemptExecutionOfScheduledCalls would + // otherwise leave the 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. + this.finalizeBlockedSpan(callId, 'error', 'system'); + const toolSpan = this.toolSpans.get(callId); + if (toolSpan) { + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_TOOL_EXCEPTION, + error instanceof Error ? error.message : String(error), + ); + } + this.finalizeToolSpan(callId); + throw error; + } + } + + private async _handleConfirmationResponseInner( + callId: string, + toolCall: ToolCall, + originalOnConfirm: ( + outcome: ToolConfirmationOutcome, + payload?: ToolConfirmationPayload, + ) => Promise, + outcome: ToolConfirmationOutcome, + signal: AbortSignal, + payload?: ToolConfirmationPayload, + ): Promise { await originalOnConfirm(outcome, payload); if ( @@ -1759,10 +1815,15 @@ export class CoreToolScheduler { 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, - signal.aborted ? 'aborted' : 'cancel', - signal.aborted ? 'system' : 'cli', + explicitCancel ? 'cancel' : 'aborted', + explicitCancel ? this.getBlockedSource() : 'system', ); this.finalizeToolSpan(callId); } else if (outcome === ToolConfirmationOutcome.ModifyWithEditor) { @@ -1826,7 +1887,7 @@ export class CoreToolScheduler { outcome === ToolConfirmationOutcome.ProceedOnce ? 'proceed_once' : 'proceed_always'; - this.finalizeBlockedSpan(callId, decision, 'cli'); + this.finalizeBlockedSpan(callId, decision, this.getBlockedSource()); } await this.attemptExecutionOfScheduledCalls(signal); } @@ -2020,8 +2081,7 @@ export class CoreToolScheduler { let toolSpan = this.toolSpans.get(callId); if (!toolSpan) { toolSpan = startToolSpan(toolName, { - tool_name: toolName, - call_id: callId, + 'tool.call_id': callId, }); this.toolSpans.set(callId, toolSpan); } @@ -2082,6 +2142,10 @@ export class CoreToolScheduler { toolName: canonicalName, toolUseId, }); + // try/finally (no catch): firePreToolUseHook is wrapped in its own + // safelyFire-style guard inside toolHookTriggers and never throws. + // The default endMeta records success: false so a future change that + // makes it throw would still close the span with a sensible state. let endMeta: HookSpanMetadata = { success: false }; try { const preHookResult = await firePreToolUseHook( @@ -2094,7 +2158,12 @@ export class CoreToolScheduler { endMeta = { success: true, shouldProceed: preHookResult.shouldProceed, - blockType: preHookResult.shouldProceed ? undefined : 'denied', + // Propagate the actual blockType ('denied' / 'ask' / 'stop') + // instead of collapsing every block to 'denied'. + blockType: preHookResult.shouldProceed + ? undefined + : preHookResult.blockType, + hasAdditionalContext: !!preHookResult.additionalContext, }; if (!preHookResult.shouldProceed) { @@ -2120,12 +2189,6 @@ export class CoreToolScheduler { ); return; } - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; - throw e; } finally { endHookSpan(hookSpan, endMeta); } @@ -2230,6 +2293,8 @@ export class CoreToolScheduler { toolUseId, isInterrupt: true, }); + // safelyFirePostToolUseFailureHook absorbs throws — try/finally + // is enough; default endMeta covers a hypothetical future change. let endMeta: HookSpanMetadata = { success: false }; try { const failureHookResult = await safelyFirePostToolUseFailureHook( @@ -2250,12 +2315,6 @@ export class CoreToolScheduler { if (failureHookResult.additionalContext) { cancelMessage += `\n\n${failureHookResult.additionalContext}`; } - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; - throw e; } finally { endHookSpan(hookSpan, endMeta); } @@ -2288,8 +2347,12 @@ export class CoreToolScheduler { toolName: canonicalName, toolUseId, }); + // try/finally; firePostToolUseHook is wrapped via the + // safelyFire-style guard inside toolHookTriggers and never + // throws today. definite-assignment lets us use the result + // after the finally. let endMeta: HookSpanMetadata = { success: false }; - let postHookResult: Awaited>; + let postHookResult!: Awaited>; try { postHookResult = await firePostToolUseHook( messageBus, @@ -2305,15 +2368,9 @@ export class CoreToolScheduler { hasAdditionalContext: !!postHookResult.additionalContext, blockType: postHookResult.shouldStop ? 'stop' : undefined, }; - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; + } finally { endHookSpan(hookSpan, endMeta); - throw e; } - endHookSpan(hookSpan, endMeta); // Append additional context from hook if provided if (postHookResult.additionalContext) { @@ -2498,12 +2555,6 @@ export class CoreToolScheduler { if (failureHookResult.additionalContext) { errorMessage += `\n\n${failureHookResult.additionalContext}`; } - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; - throw e; } finally { endHookSpan(hookSpan, endMeta); } @@ -2578,12 +2629,6 @@ export class CoreToolScheduler { if (failureHookResult.additionalContext) { cancelMessage += `\n\n${failureHookResult.additionalContext}`; } - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; - throw e; } finally { endHookSpan(hookSpan, endMeta); } @@ -2627,12 +2672,6 @@ export class CoreToolScheduler { if (failureHookResult.additionalContext) { exceptionErrorMessage += `\n\n${failureHookResult.additionalContext}`; } - } catch (e) { - endMeta = { - success: false, - error: e instanceof Error ? e.message : String(e), - }; - throw e; } finally { endHookSpan(hookSpan, endMeta); } diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index b130c89d6e1..80de52c837d 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -536,7 +536,10 @@ export type ToolBlockedDecision = | 'proceed_always' | 'cancel' | 'aborted' - | 'auto_approved'; + | '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'; From 32f94d348597038705c0b1fafc8442a6011228bd Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 20:12:06 +0800 Subject: [PATCH 03/21] fix(telemetry): close autoApprove blocked-span leak + cover three new behaviors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two follow-ups from the post-#6767469b2 review pass on PR #4321: 1. autoApproveCompatiblePendingTools error path was logging-only and leaving the sibling tool's blocked_on_user span open until the 30-min TTL fires. Symmetric with the success branch's finalizeBlockedSpan('auto_approved', 'auto'), the catch now finalizes with ('error', 'system') so the trace deterministically explains why the sibling didn't auto-approve. 2. Three behaviors introduced by 6767469b2 had no test coverage: - decision='error' from _schedule's outer catch when getConfirmationDetails throws (asserts tool span ends, no blocked span ever opens since the throw happens pre-awaiting_approval). - source='ide' when getBlockedSource() honors getIdeMode (Cancel path with getIdeMode: () => true). - Explicit Cancel takes precedence over a concurrent signal.aborted in the decision label — the bug the precedence flip was meant to fix is now regression-tested. Extracted a small `buildApprovalScheduler` helper for the two awaiting_approval-flow tests; the throw-on-confirmation test reuses StructuredErrorOnConfirmationTool. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) --- .../core/src/core/coreToolScheduler.test.ts | 221 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 5 + 2 files changed, 226 insertions(+) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index a2ed6f4ad3a..6beb81ad9ed 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4117,6 +4117,227 @@ describe('CoreToolScheduler telemetry spans', () => { expect(span.ended).toBe(true); } }); + + // ------------------------------------------------------------------- + // #4321 follow-up review tests — three behaviors introduced by the + // 6767469b2 follow-up that were not previously asserted. + // ------------------------------------------------------------------- + + /** + * Build a scheduler around a single MockEditTool that requires + * approval. Used by the awaiting_approval-flow tests below. + */ + function buildApprovalScheduler(overrides: { getIdeMode?: () => boolean }): { + scheduler: CoreToolScheduler; + onToolCallsUpdate: ReturnType; + } { + const mockEditTool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => mockEditTool, + ensureTool: async () => mockEditTool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => mockEditTool, + getToolByDisplayName: () => mockEditTool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({ + model: 'test-model', + authType: 'gemini', + }), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: overrides.getIdeMode ?? (() => false), + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const onToolCallsUpdate = vi.fn(); + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate, + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + return { scheduler, onToolCallsUpdate }; + } + + it('blocked_on_user span ends with decision=error when getConfirmationDetails throws (#4321)', async () => { + // Trigger _schedule's outer catch (line ~1711) by making + // getConfirmationDetails throw. The blocked span hasn't been started + // yet at the catch point — the span only opens AFTER setStatusInternal + // 'awaiting_approval' which never runs in this path. So the outer + // finalizeBlockedSpan('error', 'system') call is a no-op. Assert the + // tool span still ends correctly. + toolSpanRecords.length = 0; + const declarativeTool = new StructuredErrorOnConfirmationTool( + ToolErrorType.EDIT_REQUIRES_PRIOR_READ, + ); + const mockToolRegistry = { + getTool: () => declarativeTool, + ensureTool: async () => declarativeTool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => declarativeTool, + getToolByDisplayName: () => declarativeTool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({ + model: 'test-model', + authType: 'gemini', + }), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getTruncateToolOutputThreshold: () => + DEFAULT_TRUNCATE_TOOL_OUTPUT_THRESHOLD, + getTruncateToolOutputLines: () => DEFAULT_TRUNCATE_TOOL_OUTPUT_LINES, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + getChatRecordingService: () => undefined, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + + await scheduler.schedule( + [ + { + callId: 'err-1', + name: 'structuredErrorOnConfirmationTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-err', + }, + ], + new AbortController().signal, + ); + + // Tool span exists and ended; no blocked span ever opened (the throw + // happens before setStatusInternal awaiting_approval). + const toolSpans = toolSpanRecords.filter( + (r) => r.name === 'tool.structuredErrorOnConfirmationTool', + ); + expect(toolSpans).toHaveLength(1); + expect(toolSpans[0].ended).toBe(true); + expect( + toolSpanRecords.filter((r) => r.name === 'tool.blocked_on_user'), + ).toHaveLength(0); + }); + + it('blocked_on_user span source=ide when getIdeMode returns true (#4321)', async () => { + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({ + getIdeMode: () => true, + }); + await scheduler.schedule( + [ + { + callId: 'ide-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-ide', + }, + ], + new AbortController().signal, + ); + + const awaitingCall = (await waitForStatus( + onToolCallsUpdate, + 'awaiting_approval', + )) as WaitingToolCall; + await awaitingCall.confirmationDetails.onConfirm( + ToolConfirmationOutcome.Cancel, + ); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.blockedMetadata?.decision).toBe('cancel'); + // Key assertion: getBlockedSource() honored getIdeMode -> 'ide'. + expect(blockedSpan?.blockedMetadata?.source).toBe('ide'); + }); + + it('explicit Cancel takes precedence over signal.aborted in decision label (#4321)', async () => { + toolSpanRecords.length = 0; + const abortController = new AbortController(); + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + await scheduler.schedule( + [ + { + callId: 'cancel-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-cancel', + }, + ], + abortController.signal, + ); + + const awaitingCall = (await waitForStatus( + onToolCallsUpdate, + 'awaiting_approval', + )) as WaitingToolCall; + + // Abort the signal AND pass Cancel as outcome — both conditions true. + abortController.abort(); + await awaitingCall.confirmationDetails.onConfirm( + ToolConfirmationOutcome.Cancel, + ); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + // Pre-fix this would have been 'aborted' / 'system'. The fix flips + // precedence so an explicit user Cancel always wins. + expect(blockedSpan?.blockedMetadata?.decision).toBe('cancel'); + expect(blockedSpan?.blockedMetadata?.source).toBe('cli'); + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index c315923761c..8838bd711f0 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -2826,6 +2826,11 @@ export class CoreToolScheduler { `Error checking confirmation for tool ${pendingTool.request.callId}:`, error, ); + // Symmetry with the success branch above: finalize this sibling's + // blocked span with 'error' so the trace explains why it didn't + // get auto-approved. Without this, the span lingers until the + // 30-min TTL fires (#4321 review follow-up). + this.finalizeBlockedSpan(pendingTool.request.callId, 'error', 'system'); } } } From 68dea8a58d94bde7e2176c56fbc1412279237cc8 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 20:33:13 +0800 Subject: [PATCH 04/21] fix(telemetry): revert autoApprove catch finalizeBlockedSpan (#4321 codex P3) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The previous commit 32f94d348 added a `finalizeBlockedSpan(callId, 'error', 'system')` to the autoApproveCompatiblePendingTools catch in the name of "symmetry with the success branch". Codex review pointed out the bug: that catch fires when evaluatePermissionFlow throws for a SIBLING tool, but the sibling itself is still in `awaiting_approval` — the user can still respond. By closing the blocked span at the catch, the eventual handleConfirmationResponse → finalizeBlockedSpan call becomes a no-op (Map.delete already cleared it), and the user's actual decision / source attributes are lost from the trace. Revert that line. The previous behavior was correct: log the error, leave the span open, let the user's eventual decision close it correctly. If the user never responds, the 30-min TTL in session-tracing.ts cleans up the orphan span — same fallback that already covered every other "user walks away" scenario. The "leak" the original change was trying to fix was a phantom: the span IS finalized once the user (or the abort signal) drives the tool to a terminal state. The TTL is just the safety net. 🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code) --- packages/core/src/core/coreToolScheduler.ts | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 8838bd711f0..e3d7da67c76 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -2826,11 +2826,13 @@ export class CoreToolScheduler { `Error checking confirmation for tool ${pendingTool.request.callId}:`, error, ); - // Symmetry with the success branch above: finalize this sibling's - // blocked span with 'error' so the trace explains why it didn't - // get auto-approved. Without this, the span lingers until the - // 30-min TTL fires (#4321 review follow-up). - this.finalizeBlockedSpan(pendingTool.request.callId, 'error', 'system'); + // 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). } } } From 2b227b08afb01048c4b442228ec4fed961419a3c Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 21:30:23 +0800 Subject: [PATCH 05/21] fix(telemetry): split tool.failure_kind labels + cover proceed_once decision MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 38 +++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 37 +++++++++++++----- 2 files changed, 65 insertions(+), 10 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 6beb81ad9ed..b271496d7d8 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -3494,6 +3494,9 @@ describe('CoreToolScheduler telemetry spans', () => { expect(execute).not.toHaveBeenCalled(); expect(completedCalls[0].status).toBe('error'); + // This test exercises the actual PreToolUse hook deny path inside + // _executeToolCallBody — which is the only site that should still emit + // 'pre_hook_blocked' (#4321 review C-Critical). expectSanitizedFailure( spanRecord, 'Tool execution blocked by hook', @@ -4338,6 +4341,41 @@ describe('CoreToolScheduler telemetry spans', () => { expect(blockedSpan?.blockedMetadata?.decision).toBe('cancel'); expect(blockedSpan?.blockedMetadata?.source).toBe('cli'); }); + + it('blocked_on_user span ends with decision=proceed_once on single ProceedOnce confirmation (#4321)', async () => { + // ProceedOnce is the most common user interaction; previously only + // 'cancel' and 'proceed_always' (auto-approve) had decision-label + // assertions. Cover the gap so swapping or dropping the decision + // label for one-off approvals is caught. + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + await scheduler.schedule( + [ + { + callId: 'proceed-once-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-proceed-once', + }, + ], + new AbortController().signal, + ); + + const awaitingCall = (await waitForStatus( + onToolCallsUpdate, + 'awaiting_approval', + )) as WaitingToolCall; + await awaitingCall.confirmationDetails.onConfirm( + ToolConfirmationOutcome.ProceedOnce, + ); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.blockedMetadata?.decision).toBe('proceed_once'); + expect(blockedSpan?.blockedMetadata?.source).toBe('cli'); + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index e3d7da67c76..785b40eb381 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -102,9 +102,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'; @@ -1424,8 +1441,8 @@ export class CoreToolScheduler { ); setToolSpanFailure( toolSpan, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + TOOL_FAILURE_KIND_PERMISSION_DENIED, + TOOL_SPAN_STATUS_PERMISSION_DENIED, ); this.finalizeToolSpan(reqInfo.callId); continue; @@ -1475,8 +1492,8 @@ export class CoreToolScheduler { }); setToolSpanFailure( toolSpan, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - 'Plan mode blocked a non-read-only tool call.', + TOOL_FAILURE_KIND_PLAN_MODE_BLOCKED, + TOOL_SPAN_STATUS_PLAN_MODE_BLOCKED, ); this.finalizeToolSpan(reqInfo.callId); continue; @@ -1513,8 +1530,8 @@ export class CoreToolScheduler { ); setToolSpanFailure( toolSpan, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - 'Non-interactive mode declined permission', + TOOL_FAILURE_KIND_NON_INTERACTIVE_DENIED, + TOOL_SPAN_STATUS_NON_INTERACTIVE_DENIED, ); this.finalizeToolSpan(reqInfo.callId); continue; @@ -1584,8 +1601,8 @@ export class CoreToolScheduler { ); setToolSpanFailure( toolSpan, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + TOOL_FAILURE_KIND_PERMISSION_HOOK_DENIED, + TOOL_SPAN_STATUS_PERMISSION_HOOK_DENIED, ); this.finalizeToolSpan(reqInfo.callId); } @@ -1608,8 +1625,8 @@ export class CoreToolScheduler { ); setToolSpanFailure( toolSpan, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - 'Background agent cannot prompt for confirmation', + TOOL_FAILURE_KIND_BACKGROUND_AGENT_DENIED, + TOOL_SPAN_STATUS_BACKGROUND_AGENT_DENIED, ); this.finalizeToolSpan(reqInfo.callId); continue; From cc3f7fc1ec4164c5465921fbe8fec00db4b0e2ae Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 21:43:49 +0800 Subject: [PATCH 06/21] fix(telemetry): address #4321 wenshao Critical + bot summary nits MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- packages/core/src/core/coreToolScheduler.ts | 12 ++++++++++++ packages/core/src/telemetry/constants.ts | 2 ++ packages/core/src/telemetry/session-tracing.ts | 5 +++++ 3 files changed, 19 insertions(+) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 785b40eb381..35b0149876d 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1849,6 +1849,18 @@ export class CoreToolScheduler { 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`, + ); return; } diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 5fd68c50b5a..8ef41eaef83 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -64,5 +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'; diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index 80de52c837d..cedda91fa8b 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -564,6 +564,11 @@ export function startToolBlockedOnUserSpan( // 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); From f9ff554950d47e3bf52966df038ca0ae8c7ff943 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Tue, 19 May 2026 22:39:28 +0800 Subject: [PATCH 07/21] refactor(telemetry): extract withHookSpan helper + drop dead finalizeToolSpan param MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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(opts, fn, toEndMeta): Promise 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) --- packages/core/src/core/coreToolScheduler.ts | 366 ++++++++++---------- 1 file changed, 182 insertions(+), 184 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 35b0149876d..8f5a4cb54a1 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -91,7 +91,7 @@ import { addToolResultAttributes, type ToolBlockedDecision, type ToolBlockedSource, - type ToolSpanMetadata, + type StartHookSpanOptions, type HookSpanMetadata, } from '../telemetry/index.js'; import { safeJsonStringify } from '../utils/safeJsonStringify.js'; @@ -1027,12 +1027,15 @@ export class CoreToolScheduler { * 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, metadata?: ToolSpanMetadata): void { + private finalizeToolSpan(callId: string): void { const span = this.toolSpans.get(callId); if (!span) return; this.toolSpans.delete(callId); - endToolSpan(span, metadata); + endToolSpan(span); } /** @@ -1063,6 +1066,35 @@ export class CoreToolScheduler { return this.config.getIdeMode?.() ? 'ide' : 'cli'; } + /** + * 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( + opts: StartHookSpanOptions, + fn: () => Promise, + toEndMeta: (result: T) => HookSpanMetadata, + ): Promise { + const hookSpan = startHookSpan(opts); + let endMeta: HookSpanMetadata = { success: false }; + try { + const result = await fn(); + endMeta = toEndMeta(result); + return result; + } finally { + endHookSpan(hookSpan, endMeta); + } + } + private buildInvocation( tool: AnyDeclarativeTool, args: object, @@ -2166,60 +2198,47 @@ export class CoreToolScheduler { if (hooksEnabled && messageBus) { // Convert ApprovalMode to permission_mode string for hooks const permissionMode = this.config.getApprovalMode(); - const hookSpan = startHookSpan({ - hookEvent: 'PreToolUse', - toolName: canonicalName, - toolUseId, - }); - // try/finally (no catch): firePreToolUseHook is wrapped in its own - // safelyFire-style guard inside toolHookTriggers and never throws. - // The default endMeta records success: false so a future change that - // makes it throw would still close the span with a sensible state. - let endMeta: HookSpanMetadata = { success: false }; - try { - const preHookResult = await firePreToolUseHook( - messageBus, - canonicalName, - toolInput, - toolUseId, - permissionMode, - ); - endMeta = { + const preHookResult = await this.withHookSpan( + { hookEvent: 'PreToolUse', toolName: canonicalName, toolUseId }, + () => + firePreToolUseHook( + messageBus, + canonicalName, + toolInput, + toolUseId, + permissionMode, + ), + (r) => ({ success: true, - shouldProceed: preHookResult.shouldProceed, + shouldProceed: r.shouldProceed, // Propagate the actual blockType ('denied' / 'ask' / 'stop') // instead of collapsing every block to 'denied'. - blockType: preHookResult.shouldProceed - ? undefined - : preHookResult.blockType, - hasAdditionalContext: !!preHookResult.additionalContext, - }; - - if (!preHookResult.shouldProceed) { - // Hook blocked the execution - const blockMessage = - preHookResult.blockReason || 'Tool execution blocked by hook'; - const errorResponse = createErrorResponse( - scheduledCall.request, - new Error(blockMessage), - ToolErrorType.EXECUTION_DENIED, - ); - addToolResultAttributes( - this.config, - span, - toolName, - `BLOCKED: ${blockMessage}`, - ); - this.setStatusInternal(callId, 'error', errorResponse); - setToolSpanFailure( - span, - TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, - TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, - ); - return; - } - } finally { - endHookSpan(hookSpan, endMeta); + blockType: r.shouldProceed ? undefined : r.blockType, + hasAdditionalContext: !!r.additionalContext, + }), + ); + if (!preHookResult.shouldProceed) { + // Hook blocked the execution + const blockMessage = + preHookResult.blockReason || 'Tool execution blocked by hook'; + const errorResponse = createErrorResponse( + scheduledCall.request, + new Error(blockMessage), + ToolErrorType.EXECUTION_DENIED, + ); + addToolResultAttributes( + this.config, + span, + toolName, + `BLOCKED: ${blockMessage}`, + ); + this.setStatusInternal(callId, 'error', errorResponse); + setToolSpanFailure( + span, + TOOL_FAILURE_KIND_PRE_HOOK_BLOCKED, + TOOL_SPAN_STATUS_PRE_HOOK_BLOCKED, + ); + return; } } @@ -2316,36 +2335,32 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { - const hookSpan = startHookSpan({ - hookEvent: 'PostToolUseFailure', - toolName: canonicalName, - toolUseId, - isInterrupt: true, - }); - // safelyFirePostToolUseFailureHook absorbs throws — try/finally - // is enough; default endMeta covers a hypothetical future change. - let endMeta: HookSpanMetadata = { success: false }; - try { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const failureHookResult = await this.withHookSpan( + { + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - cancelMessage, - true, - this.config.getApprovalMode(), - ); - endMeta = { + isInterrupt: true, + }, + () => + safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + cancelMessage, + true, + this.config.getApprovalMode(), + ), + (r) => ({ success: true, - hasAdditionalContext: !!failureHookResult.additionalContext, - }; + hasAdditionalContext: !!r.additionalContext, + }), + ); - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - cancelMessage += `\n\n${failureHookResult.additionalContext}`; - } - } finally { - endHookSpan(hookSpan, endMeta); + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + cancelMessage += `\n\n${failureHookResult.additionalContext}`; } } addToolResultAttributes( @@ -2371,35 +2386,24 @@ export class CoreToolScheduler { returnDisplay: toolResult.returnDisplay, }; const permissionMode = this.config.getApprovalMode(); - const hookSpan = startHookSpan({ - hookEvent: 'PostToolUse', - toolName: canonicalName, - toolUseId, - }); - // try/finally; firePostToolUseHook is wrapped via the - // safelyFire-style guard inside toolHookTriggers and never - // throws today. definite-assignment lets us use the result - // after the finally. - let endMeta: HookSpanMetadata = { success: false }; - let postHookResult!: Awaited>; - try { - postHookResult = await firePostToolUseHook( - messageBus, - canonicalName, - toolInput, - toolResponse, - toolUseId, - permissionMode, - ); - endMeta = { + const postHookResult = await this.withHookSpan( + { hookEvent: 'PostToolUse', toolName: canonicalName, toolUseId }, + () => + firePostToolUseHook( + messageBus, + canonicalName, + toolInput, + toolResponse, + toolUseId, + permissionMode, + ), + (r) => ({ success: true, - shouldStop: postHookResult.shouldStop, - hasAdditionalContext: !!postHookResult.additionalContext, - blockType: postHookResult.shouldStop ? 'stop' : undefined, - }; - } finally { - endHookSpan(hookSpan, endMeta); - } + shouldStop: r.shouldStop, + hasAdditionalContext: !!r.additionalContext, + blockType: r.shouldStop ? 'stop' : undefined, + }), + ); // Append additional context from hook if provided if (postHookResult.additionalContext) { @@ -2558,34 +2562,32 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let errorMessage = toolResult.error.message; if (hooksEnabled && messageBus) { - const hookSpan = startHookSpan({ - hookEvent: 'PostToolUseFailure', - toolName: canonicalName, - toolUseId, - isInterrupt: false, - }); - let endMeta: HookSpanMetadata = { success: false }; - try { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const failureHookResult = await this.withHookSpan( + { + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - toolResult.error.message, - false, - this.config.getApprovalMode(), - ); - endMeta = { + isInterrupt: false, + }, + () => + safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + toolResult.error!.message, + false, + this.config.getApprovalMode(), + ), + (r) => ({ success: true, - hasAdditionalContext: !!failureHookResult.additionalContext, - }; + hasAdditionalContext: !!r.additionalContext, + }), + ); - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - errorMessage += `\n\n${failureHookResult.additionalContext}`; - } - } finally { - endHookSpan(hookSpan, endMeta); + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + errorMessage += `\n\n${failureHookResult.additionalContext}`; } } @@ -2632,34 +2634,32 @@ export class CoreToolScheduler { // PostToolUseFailure Hook (user interrupt) let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { - const hookSpan = startHookSpan({ - hookEvent: 'PostToolUseFailure', - toolName: canonicalName, - toolUseId, - isInterrupt: true, - }); - let endMeta: HookSpanMetadata = { success: false }; - try { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const failureHookResult = await this.withHookSpan( + { + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - cancelMessage, - true, - this.config.getApprovalMode(), - ); - endMeta = { + isInterrupt: true, + }, + () => + safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + cancelMessage, + true, + this.config.getApprovalMode(), + ), + (r) => ({ success: true, - hasAdditionalContext: !!failureHookResult.additionalContext, - }; + hasAdditionalContext: !!r.additionalContext, + }), + ); - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - cancelMessage += `\n\n${failureHookResult.additionalContext}`; - } - } finally { - endHookSpan(hookSpan, endMeta); + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + cancelMessage += `\n\n${failureHookResult.additionalContext}`; } } addToolResultAttributes( @@ -2675,34 +2675,32 @@ export class CoreToolScheduler { // PostToolUseFailure Hook let exceptionErrorMessage = errorMessage; if (hooksEnabled && messageBus) { - const hookSpan = startHookSpan({ - hookEvent: 'PostToolUseFailure', - toolName: canonicalName, - toolUseId, - isInterrupt: false, - }); - let endMeta: HookSpanMetadata = { success: false }; - try { - const failureHookResult = await safelyFirePostToolUseFailureHook( - messageBus, + const failureHookResult = await this.withHookSpan( + { + hookEvent: 'PostToolUseFailure', + toolName: canonicalName, toolUseId, - canonicalName, - toolInput, - errorMessage, - false, - this.config.getApprovalMode(), - ); - endMeta = { + isInterrupt: false, + }, + () => + safelyFirePostToolUseFailureHook( + messageBus, + toolUseId, + canonicalName, + toolInput, + errorMessage, + false, + this.config.getApprovalMode(), + ), + (r) => ({ success: true, - hasAdditionalContext: !!failureHookResult.additionalContext, - }; + hasAdditionalContext: !!r.additionalContext, + }), + ); - // Append additional context from hook if provided - if (failureHookResult.additionalContext) { - exceptionErrorMessage += `\n\n${failureHookResult.additionalContext}`; - } - } finally { - endHookSpan(hookSpan, endMeta); + // Append additional context from hook if provided + if (failureHookResult.additionalContext) { + exceptionErrorMessage += `\n\n${failureHookResult.additionalContext}`; } } addToolResultAttributes( From eafe68820e74fe25c4ed620821fe7859699d6f5b Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 00:01:13 +0800 Subject: [PATCH 08/21] fix(telemetry): hook span error tracking + TTL cleanup safety + call_id back-compat MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- packages/core/src/core/coreToolScheduler.ts | 90 ++++++++++++------- .../core/src/core/toolHookTriggers.test.ts | 16 +++- packages/core/src/core/toolHookTriggers.ts | 31 ++++--- .../core/src/telemetry/session-tracing.ts | 7 ++ 4 files changed, 98 insertions(+), 46 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 8f5a4cb54a1..4a2e85cb691 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -197,10 +197,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 }; } } @@ -1412,9 +1413,13 @@ export class CoreToolScheduler { // 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. + // 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). const toolSpan = startToolSpan(canonicalName, { 'tool.call_id': reqInfo.callId, + call_id: reqInfo.callId, }); this.toolSpans.set(reqInfo.callId, toolSpan); @@ -2143,6 +2148,7 @@ export class CoreToolScheduler { if (!toolSpan) { toolSpan = startToolSpan(toolName, { 'tool.call_id': callId, + call_id: callId, // legacy alias — see _schedule for context }); this.toolSpans.set(callId, toolSpan); } @@ -2208,14 +2214,17 @@ export class CoreToolScheduler { toolUseId, permissionMode, ), - (r) => ({ - 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, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + 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 @@ -2352,10 +2361,13 @@ export class CoreToolScheduler { true, this.config.getApprovalMode(), ), - (r) => ({ - success: true, - hasAdditionalContext: !!r.additionalContext, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + hasAdditionalContext: !!r.additionalContext, + }, ); // Append additional context from hook if provided @@ -2397,12 +2409,15 @@ export class CoreToolScheduler { toolUseId, permissionMode, ), - (r) => ({ - success: true, - shouldStop: r.shouldStop, - hasAdditionalContext: !!r.additionalContext, - blockType: r.shouldStop ? 'stop' : undefined, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + shouldStop: r.shouldStop, + hasAdditionalContext: !!r.additionalContext, + blockType: r.shouldStop ? 'stop' : undefined, + }, ); // Append additional context from hook if provided @@ -2579,10 +2594,13 @@ export class CoreToolScheduler { false, this.config.getApprovalMode(), ), - (r) => ({ - success: true, - hasAdditionalContext: !!r.additionalContext, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + hasAdditionalContext: !!r.additionalContext, + }, ); // Append additional context from hook if provided @@ -2651,10 +2669,13 @@ export class CoreToolScheduler { true, this.config.getApprovalMode(), ), - (r) => ({ - success: true, - hasAdditionalContext: !!r.additionalContext, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + hasAdditionalContext: !!r.additionalContext, + }, ); // Append additional context from hook if provided @@ -2692,10 +2713,13 @@ export class CoreToolScheduler { false, this.config.getApprovalMode(), ), - (r) => ({ - success: true, - hasAdditionalContext: !!r.additionalContext, - }), + (r) => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + hasAdditionalContext: !!r.additionalContext, + }, ); // Append additional context from hook if provided diff --git a/packages/core/src/core/toolHookTriggers.test.ts b/packages/core/src/core/toolHookTriggers.test.ts index 57d6539cd38..f1f15f9e5fe 100644 --- a/packages/core/src/core/toolHookTriggers.test.ts +++ b/packages/core/src/core/toolHookTriggers.test.ts @@ -215,7 +215,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', + }); }); }); @@ -338,7 +344,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(); }); }); @@ -429,7 +437,9 @@ describe('toolHookTriggers', () => { 'error message', ); - expect(result).toEqual({}); + // #4321 review: hookError now surfaced to caller. + expect(result.hookError).toBeDefined(); + expect(result.additionalContext).toBeUndefined(); }); }); diff --git a/packages/core/src/core/toolHookTriggers.ts b/packages/core/src/core/toolHookTriggers.ts index 65c9eb38ab1..9fbf7a99c69 100644 --- a/packages/core/src/core/toolHookTriggers.ts +++ b/packages/core/src/core/toolHookTriggers.ts @@ -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; } /** @@ -155,10 +167,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 }; } } @@ -232,10 +243,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 }; } } @@ -301,10 +311,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 }; } } diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index cedda91fa8b..f548e4f2a3b 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -558,6 +558,10 @@ export function startToolBlockedOnUserSpan( 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(); @@ -667,6 +671,9 @@ 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 From 574f64528f4defc1421d97be6766fa59a74a29a3 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 00:52:06 +0800 Subject: [PATCH 09/21] fix(telemetry): close hookError plumbing gaps from final pre-merge audit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Final-pass review surfaced two gaps in the hookError contract added in eafe68820: 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) --- .../core/src/core/coreToolScheduler.test.ts | 29 +++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 11 ++++++- packages/core/src/core/toolHookTriggers.ts | 20 +++++++++++-- 3 files changed, 56 insertions(+), 4 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index b271496d7d8..03509a93078 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4069,6 +4069,35 @@ describe('CoreToolScheduler telemetry spans', () => { expect(hookSpans[0].hookMetadata?.blockType).toBe('denied'); }); + it('hook span records error when underlying hook helper surfaces hookError (#4321)', async () => { + // Runner-layer failure (URL validation, fn exception, etc) shows up + // as response.success: false with response.error populated. Our + // helpers now forward response.error into hookError; withHookSpan's + // toEndMeta callbacks must produce { success: false, error } so + // operators see the failure in telemetry instead of a fake "allow". + const messageBus = { + request: vi.fn().mockResolvedValue({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'pre-hook', + success: false, + error: new Error('URL validation failed: hooks-server unreachable'), + }), + }; + await runSingleTool({ messageBus, disableHooks: false }); + + // shouldProceed defaults to true on hookError, so the tool runs and + // a PostToolUse hook span fires too. The PreToolUse one is the one + // we care about — it must report failure + the actual error. + const preHookSpan = getHookSpans().find( + (s) => s.attributes['hook_event'] === 'PreToolUse', + ); + expect(preHookSpan).toBeDefined(); + expect(preHookSpan!.hookMetadata?.success).toBe(false); + expect(preHookSpan!.hookMetadata?.error).toBe( + 'URL validation failed: hooks-server unreachable', + ); + }); + it('hook span records shouldStop=true when post-hook stops execution (#3731 Phase 2)', async () => { // Hook protocol: continue:false + stopReason on the post-hook response // is what the production code maps to shouldStop=true. diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 4a2e85cb691..a18430e995f 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1086,7 +1086,16 @@ export class CoreToolScheduler { toEndMeta: (result: T) => HookSpanMetadata, ): Promise { const hookSpan = startHookSpan(opts); - let endMeta: HookSpanMetadata = { success: false }; + // 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, + error: 'hook fn threw before toEndMeta', + }; try { const result = await fn(); endMeta = toEndMeta(result); diff --git a/packages/core/src/core/toolHookTriggers.ts b/packages/core/src/core/toolHookTriggers.ts index 9fbf7a99c69..e305df08909 100644 --- a/packages/core/src/core/toolHookTriggers.ts +++ b/packages/core/src/core/toolHookTriggers.ts @@ -119,7 +119,15 @@ 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). + const message = response.error?.message; + return message + ? { shouldProceed: true, hookError: message } + : { shouldProceed: true }; } const preToolOutput = createHookOutput( @@ -218,7 +226,11 @@ export async function firePostToolUseHook( ); if (!response.success || !response.output) { - return { shouldStop: false }; + // See firePreToolUseHook for the rationale. + const message = response.error?.message; + return message + ? { shouldStop: false, hookError: message } + : { shouldStop: false }; } const postToolOutput = createHookOutput( @@ -297,7 +309,9 @@ export async function firePostToolUseFailureHook( ); if (!response.success || !response.output) { - return {}; + // See firePreToolUseHook for the rationale. + const message = response.error?.message; + return message ? { hookError: message } : {}; } const failureOutput = createHookOutput( From 48e78d65de37e180c4573a184cef547e443987d9 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 00:58:57 +0800 Subject: [PATCH 10/21] test(telemetry): cover #4321 rethrow path + 2 of the new failure_kind labels MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 227 ++++++++++++++++++ 1 file changed, 227 insertions(+) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 03509a93078..27b2b4b0cb5 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4405,6 +4405,233 @@ describe('CoreToolScheduler telemetry spans', () => { expect(blockedSpan?.blockedMetadata?.decision).toBe('proceed_once'); expect(blockedSpan?.blockedMetadata?.source).toBe('cli'); }); + + it('handleConfirmationResponse outer catch finalizes spans + rethrows when originalOnConfirm throws (#4321)', async () => { + // Defensive error-recovery path added by this PR: if anything inside + // _handleConfirmationResponseInner throws (originalOnConfirm, + // modifyWithEditor, _applyInlineModify, attemptExecutionOfScheduledCalls), + // both spans must be finalized and the error rethrown — otherwise + // operators see a leak until the 30-min TTL. + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + await scheduler.schedule( + [ + { + callId: 'rethrow-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-rethrow', + }, + ], + new AbortController().signal, + ); + + // Wait until the call is awaiting_approval — both blocked + tool spans + // are in the scheduler's Maps at this point. + await waitForStatus(onToolCallsUpdate, 'awaiting_approval'); + + // Call handleConfirmationResponse DIRECTLY with a throwing + // originalOnConfirm. The outer catch in handleConfirmationResponse + // is the only thing protecting both spans from leaking. + const boom = new Error('originalOnConfirm boom'); + const throwingOnConfirm = async () => { + throw boom; + }; + await expect( + scheduler.handleConfirmationResponse( + 'rethrow-1', + throwingOnConfirm, + ToolConfirmationOutcome.ProceedOnce, + new AbortController().signal, + ), + ).rejects.toBe(boom); + + // Blocked span finalized as 'error' / 'system'. + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.ended).toBe(true); + expect(blockedSpan?.blockedMetadata?.decision).toBe('error'); + expect(blockedSpan?.blockedMetadata?.source).toBe('system'); + + // Tool span finalized with TOOL_FAILURE_KIND_TOOL_EXCEPTION. + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'tool_exception', + ); + }); + + it('PM hard-deny path emits failure_kind=permission_denied (#4321)', async () => { + // _schedule line ~1444: finalPermission === 'deny' branch sets the + // span failure with the PERMISSION_DENIED kind. Without test + // coverage, dropping setToolSpanFailure on this branch would + // silently lose the failure_kind attribution. + toolSpanRecords.length = 0; + class HardDenyTool extends BaseDeclarativeTool< + Record, + ToolResult + > { + constructor() { + super('hardDenyTool', 'hardDenyTool', 'Always deny', Kind.Other, {}); + } + protected createInvocation(params: Record) { + return new (class extends BaseToolInvocation< + Record, + ToolResult + > { + getDescription() { + return 'deny'; + } + override async getDefaultPermission(): Promise { + return 'deny'; + } + async execute(): Promise { + return { llmContent: '', returnDisplay: '' }; + } + })(params); + } + } + const tool = new HardDenyTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'deny-1', + name: 'hardDenyTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-deny', + }, + ], + new AbortController().signal, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.hardDenyTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'permission_denied', + ); + }); + + it('non-interactive deny path emits failure_kind=non_interactive_denied (#4321)', async () => { + // _schedule line ~1532: when the tool needs confirmation but + // isInteractive() is false (and not zed/streaming-json), the + // scheduler auto-denies and tags failure_kind=non_interactive_denied. + toolSpanRecords.length = 0; + const tool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => false, // forces non-interactive deny path + getInputFormat: () => undefined, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'noninteractive-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-noninteractive', + }, + ], + new AbortController().signal, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'non_interactive_denied', + ); + }); }); // Integration tests for the fire* functions From 9cbbdfc25ba76344f429889a349b6a93dd543cf7 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 10:12:04 +0800 Subject: [PATCH 11/21] fix(telemetry): adopt 4 wenshao Critical/Suggestion findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 220 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 58 ++++- .../src/telemetry/session-tracing.test.ts | 36 +++ .../core/src/telemetry/session-tracing.ts | 56 +++-- 4 files changed, 348 insertions(+), 22 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 27b2b4b0cb5..ffeda95678c 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4632,6 +4632,226 @@ describe('CoreToolScheduler telemetry spans', () => { 'non_interactive_denied', ); }); + + it('PermissionRequest hook deny path emits failure_kind=permission_hook_denied (#4321)', async () => { + // _schedule line ~1683: when firePermissionRequestHook returns + // hasDecision=true with shouldAllow=false, the scheduler tags the + // span with permission_hook_denied. Without this regression test, + // dropping setToolSpanFailure on this branch would silently lose + // hook-denial attribution for operators. + toolSpanRecords.length = 0; + const tool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const messageBus = { + request: vi.fn().mockResolvedValue({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'permission-request', + success: true, + output: { + hookSpecificOutput: { + decision: { behavior: 'deny', message: 'policy says no' }, + }, + }, + }), + }; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(messageBus), + getDisableAllHooks: vi.fn().mockReturnValue(false), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'permhook-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-permhook', + }, + ], + new AbortController().signal, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'permission_hook_denied', + ); + }); + + it('background-agent auto-deny emits failure_kind=background_agent_denied (#4321)', async () => { + // _schedule line ~1697: getShouldAvoidPermissionPrompts() === true + // forces an auto-deny because background agents have no UI to prompt + // on. This branch is otherwise untested — a regression dropping the + // setToolSpanFailure call would silently lose attribution for a key + // deployment mode. + toolSpanRecords.length = 0; + const tool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + getShouldAvoidPermissionPrompts: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'bgagent-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-bgagent', + }, + ], + new AbortController().signal, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'background_agent_denied', + ); + }); + + it('signal.abort drains scheduler-local toolSpans + blockedSpans Maps (#4321)', async () => { + // The 30-min TTL in session-tracing.ts ends underlying spans but + // cannot reach the scheduler-local toolSpans/blockedSpans Maps. If + // the signal aborts while a tool is awaiting_approval (user walked + // away, session abort), the per-batch listener registered in + // _schedule must drain both Maps so they don't grow unbounded. + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + const abortController = new AbortController(); + await scheduler.schedule( + [ + { + callId: 'abort-drain-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-abort-drain', + }, + ], + abortController.signal, + ); + + // Wait until the call is awaiting_approval — both Maps populated. + await waitForStatus(onToolCallsUpdate, 'awaiting_approval'); + expect( + (scheduler as unknown as { toolSpans: Map }).toolSpans + .size, + ).toBe(1); + expect( + (scheduler as unknown as { blockedSpans: Map }) + .blockedSpans.size, + ).toBe(1); + + // Abort the signal — the listener registered in _schedule schedules + // the drain via setTimeout(0). Flush macrotasks so it runs before + // assertions. + abortController.abort(); + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect( + (scheduler as unknown as { toolSpans: Map }).toolSpans + .size, + ).toBe(0); + expect( + (scheduler as unknown as { blockedSpans: Map }) + .blockedSpans.size, + ).toBe(0); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.ended).toBe(true); + expect(blockedSpan?.blockedMetadata?.decision).toBe('aborted'); + expect(blockedSpan?.blockedMetadata?.source).toBe('system'); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index a18430e995f..22d626bcd9e 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -768,10 +768,10 @@ export class CoreToolScheduler { // awaiting_approval phase. ModifyWithEditor stays inside one span until // the user makes a final decision (#3731 Phase 2). // - // No global signal.aborted listener: if a session aborts mid-prompt, the - // span is cleaned up by the 30-min TTL safety net in session-tracing.ts. - // We accept the bounded leak in exchange for not threading listener- - // cleanup state through this class. + // 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(); private requestQueue: Array<{ request: ToolCallRequestInfo | ToolCallRequestInfo[]; @@ -1067,6 +1067,41 @@ export class CoreToolScheduler { 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): void { + const ids = Array.from(callIds); + setTimeout(() => { + for (const callId of ids) { + if (this.blockedSpans.has(callId)) { + this.finalizeBlockedSpan(callId, 'aborted', 'system'); + } + const span = this.toolSpans.get(callId); + if (span) { + setToolSpanCancelled(span); + this.finalizeToolSpan(callId); + } + } + }, 0); + } + /** * Wrap a hook fire site with span lifecycle management. Centralizes the * try/finally pattern across the 6 hook fire sites (PreToolUse, @@ -1408,6 +1443,15 @@ export class CoreToolScheduler { this.toolCalls = this.toolCalls.concat(newToolCalls); this.notifyToolCallsUpdate(); + // Track every callId whose tool span is opened in this batch so we + // can drain stragglers on signal.abort. Necessary for the + // walk-away-during-awaiting_approval scenario: the session-tracing + // TTL cleans up the underlying spans but cannot reach the + // scheduler-local toolSpans/blockedSpans Maps (#4321 review). + const batchCallIds = new Set(); + const onAbort = () => this.drainSpansForBatch(batchCallIds); + signal.addEventListener('abort', onAbort, { once: true }); + for (const toolCall of newToolCalls) { if (toolCall.status !== 'validating') { continue; @@ -1431,6 +1475,7 @@ export class CoreToolScheduler { call_id: reqInfo.callId, }); this.toolSpans.set(reqInfo.callId, toolSpan); + batchCallIds.add(reqInfo.callId); try { if (signal.aborted) { @@ -2155,7 +2200,10 @@ export class CoreToolScheduler { // so the success path still produces telemetry. let toolSpan = this.toolSpans.get(callId); if (!toolSpan) { - toolSpan = startToolSpan(toolName, { + // 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). + toolSpan = startToolSpan(canonicalToolName(toolName), { 'tool.call_id': callId, call_id: callId, // legacy alias — see _schedule for context }); diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index e04c6a8a4e6..e5eeb37f5be 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -138,6 +138,7 @@ import { endHookSpan, getActiveInteractionSpan, clearSessionTracingForTesting, + runTTLSweepForTesting, } from './session-tracing.js'; function createMockConfig( @@ -936,4 +937,39 @@ 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(); + }); + }); }); diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index f548e4f2a3b..ade3b0b10a0 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -123,26 +123,39 @@ 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; + ctx.span.setAttributes({ + 'qwen-code.span.ttl_expired': true, + 'qwen-code.span.duration_ms': ageMs, + }); + debugLogger.warn( + `Stale ${ctx.type} span ended by TTL safety net (age=${ageMs}ms, spanId=${spanId})`, + ); + ctx.span.end(); + } + 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(); } @@ -784,3 +797,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); +} From 31921a93d9f37e0a6fa1553ab4527d541673f82a Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 10:28:07 +0800 Subject: [PATCH 12/21] fix(telemetry): adopt 7 DeepSeek /review findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 128 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 62 +++++++-- 2 files changed, 182 insertions(+), 8 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index ffeda95678c..8e582b3e31a 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4852,6 +4852,134 @@ describe('CoreToolScheduler telemetry spans', () => { ); expect(toolSpan?.ended).toBe(true); }); + + it('plan-mode block emits failure_kind=plan_mode_blocked (#4321)', async () => { + // _schedule line ~1599: plan mode blocks non-read-only confirmation + // tools. Without a regression test, dropping setToolSpanFailure or + // finalizeToolSpan on this branch would silently leak spans or + // lose attribution. + toolSpanRecords.length = 0; + const tool = new MockEditTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.PLAN, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'plan-block-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-plan-block', + }, + ], + new AbortController().signal, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'plan_mode_blocked', + ); + }); + + it('pre-aborted signal: tool span ends without entering execution (#4321)', async () => { + // _schedule line ~1487 early-exit when signal.aborted is true at the + // start of the for-loop. setToolSpanCancelled + finalizeToolSpan + // here are otherwise untested — a regression dropping either would + // leak the span or land it in ERROR rather than UNSET. + toolSpanRecords.length = 0; + const execute = vi + .fn() + .mockResolvedValue({ llmContent: 'ok', returnDisplay: 'ok' }); + const abortController = new AbortController(); + abortController.abort(); + await runSingleTool({ execute, abortController }); + + expect(execute).not.toHaveBeenCalled(); + const toolSpan = toolSpanRecords.findLast( + (r) => r.name === 'tool.mockTool', + ); + expect(toolSpan?.ended).toBe(true); + // setToolSpanCancelled records UNSET status — distinguishes from + // setToolSpanFailure paths which would land ERROR. + expect(toolSpan?.statusCalls).toEqual([{ code: SpanStatusCode.UNSET }]); + }); + + it('signal.abort during awaiting_approval: blocked span ends with aborted/system (#4321)', async () => { + // Companion to "signal.abort drains scheduler-local Maps" — that test + // covers tool span cancellation; this one specifically asserts the + // blocked_on_user decision label/source for the same drain path so + // dashboards filtering on `decision: 'aborted'` are guarded. + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + const abortController = new AbortController(); + await scheduler.schedule( + [ + { + callId: 'aborted-decision-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-aborted-decision', + }, + ], + abortController.signal, + ); + + await waitForStatus(onToolCallsUpdate, 'awaiting_approval'); + abortController.abort(); + await new Promise((resolve) => setTimeout(resolve, 0)); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.ended).toBe(true); + expect(blockedSpan?.blockedMetadata?.decision).toBe('aborted'); + expect(blockedSpan?.blockedMetadata?.source).toBe('system'); + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 22d626bcd9e..27e2d80e980 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1127,14 +1127,23 @@ export class CoreToolScheduler { // 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, - error: 'hook fn threw before toEndMeta', - }; + 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); } @@ -1469,10 +1478,14 @@ export class CoreToolScheduler { // 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). + // 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); batchCallIds.add(reqInfo.callId); @@ -1952,6 +1965,19 @@ export class CoreToolScheduler { 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; } @@ -2203,9 +2229,11 @@ export class CoreToolScheduler { // 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). - toolSpan = startToolSpan(canonicalToolName(toolName), { + 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); } @@ -2273,7 +2301,16 @@ export class CoreToolScheduler { ), (r) => r.hookError - ? { success: false, error: 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, @@ -2468,7 +2505,16 @@ export class CoreToolScheduler { ), (r) => r.hookError - ? { success: false, error: 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, From fc509d50e9d1eb3a44bdcd3db4d31e0aa01e0b23 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 11:47:54 +0800 Subject: [PATCH 13/21] fix(telemetry): adopt 3 wenshao /review findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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) --- .../core/src/core/coreToolScheduler.test.ts | 62 +++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 41 ++++++++++-- 2 files changed, 97 insertions(+), 6 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 8e582b3e31a..e7ac2eca6fe 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4131,6 +4131,68 @@ describe('CoreToolScheduler telemetry spans', () => { expect(postHookSpan!.hookMetadata?.blockType).toBe('stop'); }); + it('PostToolUseFailure hook span records is_interrupt=true on user-abort path (#4321)', async () => { + // _executeToolCallBody catch fires PostToolUseFailure with + // isInterrupt:true when the abort signal is set. Operators rely on + // is_interrupt to separate user-initiated cancellations from real + // exceptions in dashboards — assert the hook span carries the + // correct value. + toolSpanRecords.length = 0; + const abortController = new AbortController(); + const messageBus = { + request: vi.fn(async (req: { eventName: string }) => ({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'fail-hook', + success: true, + output: req.eventName === 'PreToolUse' ? { decision: 'allow' } : {}, + })), + }; + await runSingleTool({ + abortController, + messageBus, + disableHooks: false, + execute: vi.fn().mockImplementation(async () => { + abortController.abort(); + throw new Error('aborted'); + }), + }); + + const failureHookSpan = getHookSpans().find( + (s) => s.attributes['hook_event'] === 'PostToolUseFailure', + ); + expect(failureHookSpan).toBeDefined(); + expect(failureHookSpan!.attributes['is_interrupt']).toBe(true); + expect(failureHookSpan!.hookMetadata?.success).toBe(true); + }); + + it('PostToolUseFailure hook span records is_interrupt=false on real exception path (#4321)', async () => { + // Companion to the abort test — same hook event but the + // executeError-not-from-abort branch tags is_interrupt:false. A + // copy-paste regression flipping the flag would be invisible + // without this assertion. + toolSpanRecords.length = 0; + const messageBus = { + request: vi.fn(async (req: { eventName: string }) => ({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'fail-hook', + success: true, + output: req.eventName === 'PreToolUse' ? { decision: 'allow' } : {}, + })), + }; + await runSingleTool({ + messageBus, + disableHooks: false, + execute: vi.fn().mockRejectedValue(new Error('real boom')), + }); + + const failureHookSpan = getHookSpans().find( + (s) => s.attributes['hook_event'] === 'PostToolUseFailure', + ); + expect(failureHookSpan).toBeDefined(); + expect(failureHookSpan!.attributes['is_interrupt']).toBe(false); + expect(failureHookSpan!.hookMetadata?.success).toBe(true); + }); + it('every span recorded in a successful tool call is ended (#3731 Phase 2)', async () => { // Leak guard: every span we record should be ended by the time // schedule() returns. If a future change forgets to finalize a tool diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 27e2d80e980..84d2ac30e75 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1840,6 +1840,24 @@ export class CoreToolScheduler { } await this.attemptExecutionOfScheduledCalls(signal); void this.checkAndNotifyCompletion(); + + // Drop the abort listener early when the batch is fully drained + // (no awaiting_approval entries left). Long-lived sessions reuse + // the same AbortSignal across many _schedule calls; without this + // cleanup, every batch leaves a one-shot listener behind and + // Node's MaxListenersExceededWarning trips around the 10th batch. + // Listeners that still cover awaiting_approval entries stay + // attached — the user's eventual confirmation closes the spans + // (handleConfirmationResponse → finalize{Blocked,Tool}Span), and + // the listener becomes a no-op when it later fires; or it + // auto-removes via `{ once: true }` on real abort (#4321 + // review-2 wenshao Suggestion). + const stillLive = Array.from(batchCallIds).some( + (id) => this.toolSpans.has(id) || this.blockedSpans.has(id), + ); + if (!stillLive) { + signal.removeEventListener('abort', onAbort); + } } finally { this.isScheduling = false; } @@ -1880,14 +1898,25 @@ export class CoreToolScheduler { // 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. - this.finalizeBlockedSpan(callId, 'error', 'system'); + // + // 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) { - setToolSpanFailure( - toolSpan, - TOOL_FAILURE_KIND_TOOL_EXCEPTION, - error instanceof Error ? error.message : String(error), - ); + if (aborted) { + setToolSpanCancelled(toolSpan); + } else { + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_TOOL_EXCEPTION, + error instanceof Error ? error.message : String(error), + ); + } } this.finalizeToolSpan(callId); throw error; From f0befac57cbda73793c085367cb18c9ae1fa7996 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 12:44:58 +0800 Subject: [PATCH 14/21] fix(telemetry): adopt 7 wenshao /review round-3 findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 197 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 188 +++++++++++------ .../core/src/telemetry/session-tracing.ts | 84 ++++++-- 3 files changed, 393 insertions(+), 76 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index e7ac2eca6fe..8570364d468 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -5042,6 +5042,203 @@ describe('CoreToolScheduler telemetry spans', () => { expect(blockedSpan?.blockedMetadata?.decision).toBe('aborted'); expect(blockedSpan?.blockedMetadata?.source).toBe('system'); }); + + it('handleConfirmationResponse outer catch routes aborted-signal throw to aborted/system (#4321)', async () => { + // Companion to the existing rethrow test — covers the OTHER branch + // of the catch, where signal.aborted is true at throw time. Without + // this assertion, dropping the abort branch would silently + // misattribute the throw as 'error'/'tool_exception'. + toolSpanRecords.length = 0; + const { scheduler, onToolCallsUpdate } = buildApprovalScheduler({}); + const abortController = new AbortController(); + await scheduler.schedule( + [ + { + callId: 'rethrow-aborted-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-rethrow-aborted', + }, + ], + abortController.signal, + ); + + await waitForStatus(onToolCallsUpdate, 'awaiting_approval'); + + abortController.abort(); + const boom = new Error('originalOnConfirm boom while aborted'); + const throwingOnConfirm = async () => { + throw boom; + }; + await expect( + scheduler.handleConfirmationResponse( + 'rethrow-aborted-1', + throwingOnConfirm, + ToolConfirmationOutcome.ProceedOnce, + abortController.signal, + ), + ).rejects.toBe(boom); + + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan?.blockedMetadata?.decision).toBe('aborted'); + expect(blockedSpan?.blockedMetadata?.source).toBe('system'); + // Tool span lands UNSET (setToolSpanCancelled), failure_kind is the + // cancelled-marker rather than tool_exception. + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect(toolSpan?.statusCalls).toContainEqual({ + code: SpanStatusCode.UNSET, + }); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe('cancelled'); + }); + + it('ModifyWithEditor !editorType stamps modify_with_editor_unavailable on tool span (#4321)', async () => { + // The bail-out path warns to debug logs; the telemetry attribute + // is the production-visible signal. Assert it's set on the live + // tool span when the editor is unavailable, and that the tool + // remains in awaiting_approval (no premature finalize). + // + // The branch only fires if the tool implements + // ModifiableDeclarativeTool (`getModifyContext` member). Wrap the + // existing MockEditTool with a `getModifyContext` shim so the + // scheduler's `isModifiableDeclarativeTool` check passes. + toolSpanRecords.length = 0; + const mockEditTool = Object.assign(new MockEditTool(), { + getModifyContext: () => ({ + getFilePath: () => '/tmp/test.txt', + getCurrentContent: async () => 'old', + getProposedContent: async () => 'new', + createUpdatedParams: () => ({}), + }), + }); + const mockToolRegistry = { + getTool: () => mockEditTool, + ensureTool: async () => mockEditTool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => mockEditTool, + getToolByDisplayName: () => mockEditTool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const onToolCallsUpdate = vi.fn(); + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate, + // No editor configured. + getPreferredEditor: () => undefined, + onEditorClose: vi.fn(), + }); + + await scheduler.schedule( + [ + { + callId: 'modify-no-editor-1', + name: 'mockEditTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-modify-no-editor', + }, + ], + new AbortController().signal, + ); + + const awaitingCall = (await waitForStatus( + onToolCallsUpdate, + 'awaiting_approval', + )) as WaitingToolCall; + await awaitingCall.confirmationDetails.onConfirm( + ToolConfirmationOutcome.ModifyWithEditor, + ); + + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.mockEditTool', + ); + expect( + toolSpan?.spanAttributes['qwen-code.tool.modify_with_editor_unavailable'], + ).toBe(true); + // Span stays open — user can recover via Cancel/Proceed. + expect(toolSpan?.ended).toBe(false); + }); + + it('per-batch abort listener removed when batch fully drains synchronously (#4321)', async () => { + // Long-running sessions reuse the same AbortSignal across many + // _schedule calls. The release-on-finalize hook in + // releaseBatchListenerIfDrained must drop the listener once the + // last live batch entry drains, otherwise listeners accumulate + // and Node.js trips MaxListenersExceededWarning. Use Node's + // EventEmitter API surface on AbortSignal to count listeners. + toolSpanRecords.length = 0; + const { scheduler } = buildScheduler({}); + const abortController = new AbortController(); + const listenersBefore = ( + abortController.signal as unknown as { + listenerCount?: (e: string) => number; + } + ).listenerCount?.('abort'); + await scheduler.schedule( + [ + { + callId: 'listener-drain-1', + name: 'mockTool', + args: { input: 'ok' }, + isClientInitiated: false, + prompt_id: 'prompt-listener-drain', + }, + ], + abortController.signal, + ); + + // Tool ran fully synchronously (auto-approved), so its tool span + // finalized inside _schedule → releaseBatchListenerIfDrained ran. + const listenersAfter = ( + abortController.signal as unknown as { + listenerCount?: (e: string) => number; + } + ).listenerCount?.('abort'); + if (listenersBefore !== undefined && listenersAfter !== undefined) { + expect(listenersAfter).toBe(listenersBefore); + } + // Map drain side-assertion: callIdToBatch must be empty too. + expect( + ( + scheduler as unknown as { + callIdToBatch: Map; + } + ).callIdToBatch.size, + ).toBe(0); + }); }); // Integration tests for the fire* functions diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 84d2ac30e75..47386bbc749 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -700,6 +700,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; +} + /** * Returns true if a scheduled tool call can safely execute concurrently * with other safe tools (no side effects, no shared mutable state). @@ -773,6 +786,13 @@ export class CoreToolScheduler { // 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(); + // 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(); private requestQueue: Array<{ request: ToolCallRequestInfo | ToolCallRequestInfo[]; signal: AbortSignal; @@ -1037,6 +1057,7 @@ export class CoreToolScheduler { if (!span) return; this.toolSpans.delete(callId); endToolSpan(span); + this.releaseBatchListenerIfDrained(callId); } /** @@ -1054,6 +1075,32 @@ export class CoreToolScheduler { 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); } /** @@ -1090,13 +1137,22 @@ export class CoreToolScheduler { const ids = Array.from(callIds); setTimeout(() => { for (const callId of ids) { - if (this.blockedSpans.has(callId)) { - this.finalizeBlockedSpan(callId, 'aborted', 'system'); - } - const span = this.toolSpans.get(callId); - if (span) { - setToolSpanCancelled(span); - this.finalizeToolSpan(callId); + // 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); @@ -1115,6 +1171,23 @@ export class CoreToolScheduler { * throws internally so this branch is unreachable, but the pattern * future-proofs the lifecycle if that contract changes. */ + /** + * 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>, + ): HookSpanMetadata => + r.hookError + ? { success: false, error: r.hookError } + : { + success: true, + hasAdditionalContext: !!r.additionalContext, + }; + private async withHookSpan( opts: StartHookSpanOptions, fn: () => Promise, @@ -1452,14 +1525,20 @@ export class CoreToolScheduler { this.toolCalls = this.toolCalls.concat(newToolCalls); this.notifyToolCallsUpdate(); - // Track every callId whose tool span is opened in this batch so we - // can drain stragglers on signal.abort. Necessary for the - // walk-away-during-awaiting_approval scenario: the session-tracing - // TTL cleans up the underlying spans but cannot reach the - // scheduler-local toolSpans/blockedSpans Maps (#4321 review). - const batchCallIds = new Set(); - const onAbort = () => this.drainSpansForBatch(batchCallIds); - signal.addEventListener('abort', onAbort, { once: true }); + // 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(), + }; + signal.addEventListener('abort', batchState.onAbort, { once: true }); for (const toolCall of newToolCalls) { if (toolCall.status !== 'validating') { @@ -1488,7 +1567,8 @@ export class CoreToolScheduler { tool_name: canonicalName, }); this.toolSpans.set(reqInfo.callId, toolSpan); - batchCallIds.add(reqInfo.callId); + batchState.callIds.add(reqInfo.callId); + this.callIdToBatch.set(reqInfo.callId, batchState); try { if (signal.aborted) { @@ -1736,6 +1816,26 @@ export class CoreToolScheduler { 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; + } + // Allow IDE to resolve confirmation this.openIdeDiffIfEnabled( confirmationDetails, @@ -1840,24 +1940,12 @@ export class CoreToolScheduler { } await this.attemptExecutionOfScheduledCalls(signal); void this.checkAndNotifyCompletion(); - - // Drop the abort listener early when the batch is fully drained - // (no awaiting_approval entries left). Long-lived sessions reuse - // the same AbortSignal across many _schedule calls; without this - // cleanup, every batch leaves a one-shot listener behind and - // Node's MaxListenersExceededWarning trips around the 10th batch. - // Listeners that still cover awaiting_approval entries stay - // attached — the user's eventual confirmation closes the spans - // (handleConfirmationResponse → finalize{Blocked,Tool}Span), and - // the listener becomes a no-op when it later fires; or it - // auto-removes via `{ once: true }` on real abort (#4321 - // review-2 wenshao Suggestion). - const stillLive = Array.from(batchCallIds).some( - (id) => this.toolSpans.has(id) || this.blockedSpans.has(id), - ); - if (!stillLive) { - signal.removeEventListener('abort', onAbort); - } + // 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. } finally { this.isScheduling = false; } @@ -2484,13 +2572,7 @@ export class CoreToolScheduler { true, this.config.getApprovalMode(), ), - (r) => - r.hookError - ? { success: false, error: r.hookError } - : { - success: true, - hasAdditionalContext: !!r.additionalContext, - }, + this.postToolUseFailureEndMeta, ); // Append additional context from hook if provided @@ -2726,13 +2808,7 @@ export class CoreToolScheduler { false, this.config.getApprovalMode(), ), - (r) => - r.hookError - ? { success: false, error: r.hookError } - : { - success: true, - hasAdditionalContext: !!r.additionalContext, - }, + this.postToolUseFailureEndMeta, ); // Append additional context from hook if provided @@ -2801,13 +2877,7 @@ export class CoreToolScheduler { true, this.config.getApprovalMode(), ), - (r) => - r.hookError - ? { success: false, error: r.hookError } - : { - success: true, - hasAdditionalContext: !!r.additionalContext, - }, + this.postToolUseFailureEndMeta, ); // Append additional context from hook if provided @@ -2845,13 +2915,7 @@ export class CoreToolScheduler { false, this.config.getApprovalMode(), ), - (r) => - r.hookError - ? { success: false, error: r.hookError } - : { - success: true, - hasAdditionalContext: !!r.additionalContext, - }, + this.postToolUseFailureEndMeta, ); // Append additional context from hook if provided diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index ade3b0b10a0..dc4bb6ff895 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -137,14 +137,44 @@ function sweepStaleSpans(now: number): void { // garbage-collected by the TTL safety net" from "deliberately // ended without setting status / attrs" (#4321 review). const ageMs = now - ctx.startTime; - ctx.span.setAttributes({ - 'qwen-code.span.ttl_expired': true, - 'qwen-code.span.duration_ms': ageMs, - }); + 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 { + // OTel errors must not prevent span.end() from running. + } + // 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 ${ctx.type} span ended by TTL safety net (age=${ageMs}ms, spanId=${spanId})`, + `Stale ${ctxLabel} span ended by TTL safety net (age=${ageMs}ms, spanId=${spanId})`, ); - ctx.span.end(); + 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); @@ -165,6 +195,22 @@ function getSpanId(span: Span): string { return span.spanContext().spanId || ''; } +const SPAN_ERROR_MAX_BYTES = 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. 1KB is small enough to fit any + * sensible error and large enough that operators rarely need to look + * up the raw payload (#4321 review-3 wenshao Critical). + */ +function truncateSpanError(s: string): string { + return s.length > SPAN_ERROR_MAX_BYTES + ? s.slice(0, SPAN_ERROR_MAX_BYTES) + '…[truncated]' + : s; +} + function getTracer() { return trace.getTracer(SERVICE_NAME, '1.0.0'); } @@ -302,7 +348,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); @@ -312,7 +359,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) { @@ -409,7 +458,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); @@ -420,7 +470,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', }); } } @@ -506,7 +558,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); @@ -521,7 +574,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', }); } } @@ -751,7 +806,8 @@ export function endHookSpan(span: Span, metadata?: HookSpanMetadata): void { endAttributes['block_type'] = metadata.blockType; if (metadata.hasAdditionalContext !== undefined) endAttributes['has_additional_context'] = metadata.hasAdditionalContext; - if (metadata.error !== undefined) endAttributes['error'] = metadata.error; + if (metadata.error !== undefined) + endAttributes['error'] = truncateSpanError(metadata.error); } spanCtx.span.setAttributes(endAttributes); @@ -759,7 +815,7 @@ export function endHookSpan(span: Span, metadata?: HookSpanMetadata): void { if (metadata?.error !== undefined) { spanCtx.span.setStatus({ code: SpanStatusCode.ERROR, - message: metadata.error, + message: truncateSpanError(metadata.error), }); } } catch (error) { From 87160697051d1d3ea5b6bdbb5627c9f02108c008 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 13:59:26 +0800 Subject: [PATCH 15/21] fix(telemetry): polish 2 wenshao /review round-4 nits on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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) --- packages/core/src/core/coreToolScheduler.ts | 26 +++++++++---------- .../core/src/telemetry/session-tracing.ts | 18 ++++++++----- 2 files changed, 25 insertions(+), 19 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 47386bbc749..ecf42989d89 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1158,19 +1158,6 @@ export class CoreToolScheduler { }, 0); } - /** - * 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. - */ /** * Shared toEndMeta callback for the 4 PostToolUseFailure hook fire * sites. Each was previously inlined as a byte-identical lambda; the @@ -1188,6 +1175,19 @@ export class CoreToolScheduler { 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( opts: StartHookSpanOptions, fn: () => Promise, diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index dc4bb6ff895..ecbea3e7c02 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -195,19 +195,25 @@ function getSpanId(span: Span): string { return span.spanContext().spanId || ''; } -const SPAN_ERROR_MAX_BYTES = 1024; +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. 1KB is small enough to fit any - * sensible error and large enough that operators rarely need to look - * up the raw payload (#4321 review-3 wenshao Critical). + * 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). */ function truncateSpanError(s: string): string { - return s.length > SPAN_ERROR_MAX_BYTES - ? s.slice(0, SPAN_ERROR_MAX_BYTES) + '…[truncated]' + return s.length > SPAN_ERROR_MAX_CHARS + ? s.slice(0, SPAN_ERROR_MAX_CHARS) + '…[truncated]' : s; } From e7dd8aad2e3cb746e867c917f24b6cadb5399f7a Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 16:57:00 +0800 Subject: [PATCH 16/21] fix(telemetry): adopt 4 wenshao /review round-5 findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 4 ++ packages/core/src/core/coreToolScheduler.ts | 27 +++++++++- packages/core/src/telemetry/index.ts | 1 + .../src/telemetry/session-tracing.test.ts | 49 +++++++++++++++++++ .../core/src/telemetry/session-tracing.ts | 2 +- 5 files changed, 81 insertions(+), 2 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 8570364d468..bc7a6902842 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -225,6 +225,10 @@ vi.mock('../telemetry/session-tracing.js', () => ({ startLLMRequestSpan: vi.fn(), endLLMRequestSpan: vi.fn(), clearSessionTracingForTesting: vi.fn(), + // truncateSpanError is exported from session-tracing and used in + // setToolSpanFailure to bound status messages. The real implementation + // is a pure utility function — passthrough is fine for tests. + truncateSpanError: (s: string): string => s, })); vi.mock('fs/promises', () => ({ diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index ecf42989d89..dc6ecce2b94 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -89,6 +89,7 @@ import { endHookSpan, addToolInputAttributes, addToolResultAttributes, + truncateSpanError, type ToolBlockedDecision, type ToolBlockedSource, type StartHookSpanOptions, @@ -159,9 +160,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), }); } @@ -1946,6 +1952,17 @@ export class CoreToolScheduler { // 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; } @@ -2007,6 +2024,14 @@ export class CoreToolScheduler { } } 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; } } diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index 988e31211a9..6ad5cb13c34 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -151,6 +151,7 @@ export { startHookSpan, endHookSpan, getActiveInteractionSpan, + truncateSpanError, } from './session-tracing.js'; export type { StartInteractionOptions, diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index e5eeb37f5be..f36d38a0af4 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -139,6 +139,7 @@ import { getActiveInteractionSpan, clearSessionTracingForTesting, runTTLSweepForTesting, + truncateSpanError, } from './session-tracing.js'; function createMockConfig( @@ -971,5 +972,53 @@ describe('session-tracing', () => { 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); + }); }); }); diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index ecbea3e7c02..981edf1b061 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -211,7 +211,7 @@ const SPAN_ERROR_MAX_CHARS = 1024; * ~32KB), so we keep the simpler char-count bound rather than paying * the encoder cost on every endXSpan (review-4 follow-up). */ -function truncateSpanError(s: string): string { +export function truncateSpanError(s: string): string { return s.length > SPAN_ERROR_MAX_CHARS ? s.slice(0, SPAN_ERROR_MAX_CHARS) + '…[truncated]' : s; From 51cb97cd6e98644e5c3cfcf7c90b888d3118b2d0 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Wed, 20 May 2026 18:28:18 +0800 Subject: [PATCH 17/21] fix(telemetry): adopt 1 wenshao /review round-6 finding on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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 `<>`, 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) --- .../core/src/core/coreToolScheduler.test.ts | 48 +++++++++++++++++-- 1 file changed, 45 insertions(+), 3 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index bc7a6902842..e618c5b1426 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -226,9 +226,10 @@ vi.mock('../telemetry/session-tracing.js', () => ({ endLLMRequestSpan: vi.fn(), clearSessionTracingForTesting: vi.fn(), // truncateSpanError is exported from session-tracing and used in - // setToolSpanFailure to bound status messages. The real implementation - // is a pure utility function — passthrough is fine for tests. - truncateSpanError: (s: string): string => s, + // setToolSpanFailure to bound status messages. Wrap as a spy so a + // dedicated regression test can substitute a sentinel return value + // and verify setToolSpanFailure forwards it (#4321 review-6). + truncateSpanError: vi.fn((s: string): string => s), })); vi.mock('fs/promises', () => ({ @@ -3508,6 +3509,47 @@ describe('CoreToolScheduler telemetry spans', () => { ); }); + it('setToolSpanFailure forwards the truncateSpanError result to the span status (#4321)', async () => { + // Lock the integration: if a future change drops the + // truncateSpanError(message) call inside setToolSpanFailure, this + // test catches it. Substitute a sentinel return so the assertion + // doesn't depend on the utility's exact truncation behaviour + // (review-6 wenshao). + const sessionTracing = await import('../telemetry/session-tracing.js'); + const truncateSpy = vi.mocked(sessionTracing.truncateSpanError); + truncateSpy.mockImplementationOnce(() => '<>'); + + const messageBus = { + request: vi.fn().mockResolvedValue({ + type: MessageBusType.HOOK_EXECUTION_RESPONSE, + correlationId: 'pre-hook', + success: true, + output: { + decision: 'deny', + reason: 'truncate-me-pretty-please', + }, + }), + }; + + const { spanRecord } = await runSingleTool({ + messageBus, + disableHooks: false, + }); + + // setToolSpanFailure(span, kind, msg) → safeSetStatus({code: ERROR, + // message: truncateSpanError(msg)}). The mock returns the sentinel + // for that single call, so the span's status message must equal it. + const errorStatusCall = spanRecord.statusCalls.find( + (s) => s.code === SpanStatusCode.ERROR, + ); + expect(errorStatusCall?.message).toBe('<>'); + expect(truncateSpy).toHaveBeenCalled(); + + // Restore default identity behaviour so other tests aren't affected. + truncateSpy.mockReset(); + truncateSpy.mockImplementation((s) => s); + }); + it('marks post-hook stop with a sanitized failure kind', async () => { const messageBus = { request: vi From 84851f27c886b156e0d9b2c51cbce381ccbd6e50 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Thu, 21 May 2026 08:30:19 +0800 Subject: [PATCH 18/21] fix(telemetry): close 4 silent-failure + test-gap findings from final review on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 138 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 37 +++++ .../core/src/core/toolHookTriggers.test.ts | 20 ++- packages/core/src/core/toolHookTriggers.ts | 27 ++-- .../core/src/telemetry/session-tracing.ts | 10 +- 5 files changed, 214 insertions(+), 18 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index e618c5b1426..3b8e31a2466 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -4900,6 +4900,144 @@ describe('CoreToolScheduler telemetry spans', () => { ); }); + it('signal.aborted re-check between for-loop awaits and awaiting_approval (#4321)', async () => { + // _schedule:1834 re-checks signal.aborted after the for-loop's + // await points (evaluatePermissionFlow / getConfirmationDetails / + // firePermissionRequestHook) and before opening the blocked span. + // Without this guard, an abort that resolves during one of those + // awaits would leave the tool in awaiting_approval on an already- + // aborted signal — the per-batch drain (deferred via setTimeout(0)) + // could have fired before the new entry exists, leaking it until + // TTL. + // + // Drive the path by making `getConfirmationDetails` abort the + // signal as it returns: top-of-loop check passes (signal not yet + // aborted), evaluatePermissionFlow resolves, getConfirmationDetails + // resolves AND aborts → the re-check must fire the cancel path + // before any awaiting_approval transition or blocked span open. + toolSpanRecords.length = 0; + const abortController = new AbortController(); + class AbortDuringConfirmTool extends BaseDeclarativeTool< + Record, + ToolResult + > { + constructor() { + super( + 'abortDuringConfirmTool', + 'abortDuringConfirmTool', + 'Aborts mid-confirmation', + Kind.Edit, + {}, + ); + } + protected createInvocation(params: Record) { + return new (class extends BaseToolInvocation< + Record, + ToolResult + > { + getDescription() { + return 'abort during confirmation'; + } + override async getDefaultPermission(): Promise { + return 'ask'; + } + override async getConfirmationDetails( + _signal: AbortSignal, + ): Promise { + // Abort BEFORE returning — by the time _schedule's + // re-check runs, signal.aborted is true. + abortController.abort(); + return { + type: 'edit', + title: 'Confirm Edit', + fileName: 'test.txt', + filePath: 'test.txt', + fileDiff: 'mock diff', + originalContent: 'old', + newContent: 'new', + onConfirm: async () => {}, + }; + } + async execute(): Promise { + return { llmContent: 'ok', returnDisplay: 'ok' }; + } + })(params); + } + } + const tool = new AbortDuringConfirmTool(); + const mockToolRegistry = { + getTool: () => tool, + ensureTool: async () => tool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => tool, + getToolByDisplayName: () => tool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.DEFAULT, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + isInteractive: () => true, + getIdeMode: () => false, + getExperimentalZedIntegration: () => false, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn().mockReturnValue(undefined), + getDisableAllHooks: vi.fn().mockReturnValue(true), + } as unknown as Config; + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete: vi.fn(), + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + await scheduler.schedule( + [ + { + callId: 'abort-recheck-1', + name: 'abortDuringConfirmTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-abort-recheck', + }, + ], + abortController.signal, + ); + + // Cancelled marker on the tool span; setToolSpanCancelled records + // `failure_kind: 'cancelled'` and UNSET status. + const toolSpan = toolSpanRecords.find( + (r) => r.name === 'tool.abortDuringConfirmTool', + ); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe('cancelled'); + // Crucially: NO blocked_on_user span was ever started. If the + // re-check is regressed, _schedule would have called + // setStatusInternal('awaiting_approval', ...) + startToolBlockedOnUserSpan + // before the abort drain could fire. + const blockedSpan = toolSpanRecords.find( + (r) => r.name === 'tool.blocked_on_user', + ); + expect(blockedSpan).toBeUndefined(); + }); + it('signal.abort drains scheduler-local toolSpans + blockedSpans Maps (#4321)', async () => { // The 30-min TTL in session-tracing.ts ends underlying spans but // cannot reach the scheduler-local toolSpans/blockedSpans Maps. If diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index dc6ecce2b94..23fa695d412 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -2383,6 +2383,43 @@ export class CoreToolScheduler { 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. — propagate up to this finally + // without ever calling setToolSpan*, so the span would end UNSET + // with no failure_kind AND the tool call would stay in 'executing' + // forever (checkAndNotifyCompletion never sees terminal state). + // Pre-set failure status + an error response here so the + // finalizeToolSpan in `finally` produces meaningful telemetry and + // the scheduler can complete (#4321 review-7 silent-failure-hunter + // HIGH-2). If the body's own catch already set status, the + // setStatusInternal('error', ...) below is a no-op because the + // call has already moved to a terminal status. + const errorMessage = + error instanceof Error ? error.message : String(error); + setToolSpanFailure( + toolSpan, + TOOL_FAILURE_KIND_TOOL_EXCEPTION, + errorMessage, + ); + if ( + this.toolCalls.find( + (c) => c.request.callId === callId && c.status === 'executing', + ) + ) { + this.setStatusInternal( + callId, + 'error', + createErrorResponse( + scheduledCall.request, + error instanceof Error ? error : new Error(errorMessage), + ToolErrorType.UNHANDLED_EXCEPTION, + ), + ); + } + throw error; } finally { // _executeToolCallBody pre-sets status (OK / FAILURE / CANCELLED) via // setToolSpan*; finalize without metadata to preserve that. diff --git a/packages/core/src/core/toolHookTriggers.test.ts b/packages/core/src/core/toolHookTriggers.test.ts index f1f15f9e5fe..df3a6ae7501 100644 --- a/packages/core/src/core/toolHookTriggers.test.ts +++ b/packages/core/src/core/toolHookTriggers.test.ts @@ -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).mockResolvedValue({ success: false, @@ -72,7 +72,12 @@ 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('should return shouldProceed: true when hook output is empty', async () => { @@ -239,7 +244,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).mockResolvedValue({ success: false, @@ -254,7 +259,9 @@ 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('should return shouldStop: false when hook output is empty', async () => { @@ -363,7 +370,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).mockResolvedValue({ success: false, @@ -377,7 +384,8 @@ describe('toolHookTriggers', () => { 'error message', ); - expect(result).toEqual({}); + // #4321 review-7 SF-H1 — see firePreToolUseHook counterpart. + expect(result.hookError).toMatch(/success: false/); }); it('should return empty object when hook output is empty', async () => { diff --git a/packages/core/src/core/toolHookTriggers.ts b/packages/core/src/core/toolHookTriggers.ts index e305df08909..7e5e07afadd 100644 --- a/packages/core/src/core/toolHookTriggers.ts +++ b/packages/core/src/core/toolHookTriggers.ts @@ -124,10 +124,15 @@ export async function firePreToolUseHook( // 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). - const message = response.error?.message; - return message - ? { shouldProceed: true, hookError: message } - : { shouldProceed: true }; + // + // 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). + 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( @@ -227,10 +232,10 @@ export async function firePostToolUseHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. - const message = response.error?.message; - return message - ? { shouldStop: false, hookError: message } - : { shouldStop: false }; + 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( @@ -310,8 +315,10 @@ export async function firePostToolUseFailureHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. - const message = response.error?.message; - return message ? { hookError: message } : {}; + const message = + response.error?.message || + `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; + return { hookError: message }; } const failureOutput = createHookOutput( diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index 981edf1b061..569e95ecb50 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -156,8 +156,14 @@ function sweepStaleSpans(now: number): void { } : {}), }); - } catch { - // OTel errors must not prevent span.end() from running. + } 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). From 2c268a809e9d4dcf105df5a31dfd795cd73a05e7 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Thu, 21 May 2026 09:54:36 +0800 Subject: [PATCH 19/21] fix(telemetry): adopt 3 wenshao /review round-8 findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../core/src/core/coreToolScheduler.test.ts | 107 ++++++++++++++++++ packages/core/src/core/coreToolScheduler.ts | 50 ++++---- packages/core/src/core/toolHookTriggers.ts | 18 ++- .../src/telemetry/session-tracing.test.ts | 24 ++++ .../core/src/telemetry/session-tracing.ts | 13 ++- 5 files changed, 179 insertions(+), 33 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 3b8e31a2466..3b154726ec6 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -5038,6 +5038,113 @@ describe('CoreToolScheduler telemetry spans', () => { expect(blockedSpan).toBeUndefined(); }); + it('prelude throw in _executeToolCallBody transitions tool from scheduled to error (#4321)', async () => { + // _executeToolCallBody's prelude (addToolInputAttributes, + // getMessageBus, startToolExecutionSpan, etc.) runs BEFORE the + // `scheduled → executing` transition. If a synchronous throw escapes + // the prelude, the catch in executeSingleToolCall must finalize the + // tool span with failure_kind=tool_exception AND transition the + // toolCall to 'error' — otherwise checkAndNotifyCompletion never + // sees a terminal state and the scheduler stalls (#4321 review-8 + // wenshao Critical refinement of review-7 SF-H2). + toolSpanRecords.length = 0; + const mockTool = new MockTool({ + name: 'mockTool', + execute: vi.fn().mockResolvedValue({ + llmContent: 'should not execute', + returnDisplay: 'should not execute', + }), + }); + const mockToolRegistry = { + getTool: () => mockTool, + ensureTool: async () => mockTool, + getFunctionDeclarations: () => [], + tools: new Map(), + discovery: {}, + registerTool: () => {}, + getToolByName: () => mockTool, + getToolByDisplayName: () => mockTool, + getTools: () => [], + discoverTools: async () => {}, + getAllTools: () => [], + getToolsByServer: () => [], + } as unknown as ToolRegistry; + // The auto-approve YOLO path doesn't call _schedule's getMessageBus + // branch, so the only getMessageBus call is the prelude one at + // _executeToolCallBody. Make that call throw. + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + getDebugMode: () => false, + getApprovalMode: () => ApprovalMode.YOLO, + getPermissionsAllow: () => [], + getContentGeneratorConfig: () => ({}), + getShellExecutionConfig: () => ({ + terminalWidth: 90, + terminalHeight: 30, + }), + storage: { getProjectTempDir: () => '/tmp' }, + getTruncateToolOutputThreshold: () => + DEFAULT_TRUNCATE_TOOL_OUTPUT_THRESHOLD, + getTruncateToolOutputLines: () => DEFAULT_TRUNCATE_TOOL_OUTPUT_LINES, + getToolRegistry: () => mockToolRegistry, + getUseModelRouter: () => false, + getGeminiClient: () => null, + getChatRecordingService: () => undefined, + getMessageBus: vi.fn(() => { + throw new Error('prelude boom — getMessageBus throws'); + }), + getDisableAllHooks: vi.fn().mockReturnValue(false), + } as unknown as Config; + const onAllToolCallsComplete = vi.fn(); + const scheduler = new CoreToolScheduler({ + config: mockConfig, + onAllToolCallsComplete, + onToolCallsUpdate: vi.fn(), + getPreferredEditor: () => 'vscode', + onEditorClose: vi.fn(), + }); + + // The prelude throw re-throws out of executeSingleToolCall → + // attemptExecutionOfScheduledCalls → _schedule. That's expected; + // the caller surfaces the error. The critical regression is + // whether the toolCall transitions out of `scheduled` BEFORE the + // throw propagates so checkAndNotifyCompletion sees a terminal + // state — without that transition the scheduler is stuck and + // onAllToolCallsComplete never fires. + await expect( + scheduler.schedule( + [ + { + callId: 'prelude-throw-1', + name: 'mockTool', + args: { input: 'x' }, + isClientInitiated: false, + prompt_id: 'prompt-prelude-throw', + }, + ], + new AbortController().signal, + ), + ).rejects.toThrow('prelude boom'); + + // onAllToolCallsComplete fired (synchronously dispatched from + // setStatusInternal → checkAndNotifyCompletion) with the call in + // 'error' status — proves the catch transitioned it out of + // 'scheduled' BEFORE re-throwing. + expect(onAllToolCallsComplete).toHaveBeenCalled(); + const completedCalls = onAllToolCallsComplete.mock.calls.at( + -1, + )?.[0] as ToolCall[]; + expect(completedCalls[0].status).toBe('error'); + + // Tool span finalized with the canonical failure_kind. + const toolSpan = toolSpanRecords.find((r) => r.name === 'tool.mockTool'); + expect(toolSpan?.ended).toBe(true); + expect(toolSpan?.spanAttributes['tool.failure_kind']).toBe( + 'tool_exception', + ); + }); + it('signal.abort drains scheduler-local toolSpans + blockedSpans Maps (#4321)', async () => { // The 30-min TTL in session-tracing.ts ends underlying spans but // cannot reach the scheduler-local toolSpans/blockedSpans Maps. If diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 23fa695d412..43789a93958 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -2385,18 +2385,20 @@ export class CoreToolScheduler { ); } 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. — propagate up to this finally - // without ever calling setToolSpan*, so the span would end UNSET - // with no failure_kind AND the tool call would stay in 'executing' - // forever (checkAndNotifyCompletion never sees terminal state). - // Pre-set failure status + an error response here so the - // finalizeToolSpan in `finally` produces meaningful telemetry and - // the scheduler can complete (#4321 review-7 silent-failure-hunter - // HIGH-2). If the body's own catch already set status, the - // setStatusInternal('error', ...) below is a no-op because the - // call has already moved to a terminal status. + // 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( @@ -2404,21 +2406,15 @@ export class CoreToolScheduler { TOOL_FAILURE_KIND_TOOL_EXCEPTION, errorMessage, ); - if ( - this.toolCalls.find( - (c) => c.request.callId === callId && c.status === 'executing', - ) - ) { - this.setStatusInternal( - callId, - 'error', - createErrorResponse( - scheduledCall.request, - error instanceof Error ? error : new Error(errorMessage), - ToolErrorType.UNHANDLED_EXCEPTION, - ), - ); - } + this.setStatusInternal( + callId, + 'error', + createErrorResponse( + scheduledCall.request, + error instanceof Error ? error : new Error(errorMessage), + ToolErrorType.UNHANDLED_EXCEPTION, + ), + ); throw error; } finally { // _executeToolCallBody pre-sets status (OK / FAILURE / CANCELLED) via diff --git a/packages/core/src/core/toolHookTriggers.ts b/packages/core/src/core/toolHookTriggers.ts index 7e5e07afadd..af0e3f72b0a 100644 --- a/packages/core/src/core/toolHookTriggers.ts +++ b/packages/core/src/core/toolHookTriggers.ts @@ -129,8 +129,12 @@ export async function firePreToolUseHook( // `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). + // `??` not `||`: a runner returning `{ error: { message: "" } }` + // is unhelpful but still IS a message — only synthesize the + // sentinel when the message is truly absent (#4321 review-8 + // wenshao Suggestion). const message = - response.error?.message || + response.error?.message ?? `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { shouldProceed: true, hookError: message }; } @@ -232,8 +236,12 @@ export async function firePostToolUseHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. + // `??` not `||`: a runner returning `{ error: { message: "" } }` + // is unhelpful but still IS a message — only synthesize the + // sentinel when the message is truly absent (#4321 review-8 + // wenshao Suggestion). const message = - response.error?.message || + response.error?.message ?? `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { shouldStop: false, hookError: message }; } @@ -315,8 +323,12 @@ export async function firePostToolUseFailureHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. + // `??` not `||`: a runner returning `{ error: { message: "" } }` + // is unhelpful but still IS a message — only synthesize the + // sentinel when the message is truly absent (#4321 review-8 + // wenshao Suggestion). const message = - response.error?.message || + response.error?.message ?? `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { hookError: message }; } diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index f36d38a0af4..1422483fc07 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -1020,5 +1020,29 @@ describe('session-tracing', () => { 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); + // And the result must be valid UTF-16 (no orphan surrogates). + expect(() => Buffer.from(truncated, 'utf16le')).not.toThrow(); + }); }); }); diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index 569e95ecb50..e4d5b14a2f6 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -218,9 +218,16 @@ const SPAN_ERROR_MAX_CHARS = 1024; * the encoder cost on every endXSpan (review-4 follow-up). */ export function truncateSpanError(s: string): string { - return s.length > SPAN_ERROR_MAX_CHARS - ? s.slice(0, SPAN_ERROR_MAX_CHARS) + '…[truncated]' - : s; + 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() { From a1d1190bbb3e736c1cbf864be765476f775be710 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Thu, 21 May 2026 10:18:23 +0800 Subject: [PATCH 20/21] fix(telemetry): adopt 3 wenshao /review round-9 findings on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit [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) --- packages/core/src/core/coreToolScheduler.ts | 31 ++++++++++++--- packages/core/src/core/toolHookTriggers.ts | 39 ++++++++++++------- .../src/telemetry/session-tracing.test.ts | 8 +++- 3 files changed, 55 insertions(+), 23 deletions(-) diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 43789a93958..4d26c66bec8 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -1997,12 +1997,19 @@ export class CoreToolScheduler { payload, ); } catch (error) { - // Defensive: any throw from originalOnConfirm / modifyWithEditor / - // _applyInlineModify / attemptExecutionOfScheduledCalls would - // otherwise leave the blocked + tool spans open until the 30-min + // 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. + // 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 @@ -2034,6 +2041,15 @@ export class CoreToolScheduler { ); 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( @@ -2177,7 +2193,10 @@ export class CoreToolScheduler { : '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). } /** diff --git a/packages/core/src/core/toolHookTriggers.ts b/packages/core/src/core/toolHookTriggers.ts index af0e3f72b0a..85981eaf557 100644 --- a/packages/core/src/core/toolHookTriggers.ts +++ b/packages/core/src/core/toolHookTriggers.ts @@ -129,12 +129,15 @@ export async function firePreToolUseHook( // `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). - // `??` not `||`: a runner returning `{ error: { message: "" } }` - // is unhelpful but still IS a message — only synthesize the - // sentinel when the message is truly absent (#4321 review-8 - // wenshao Suggestion). + // `||` (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 ?? + response.error?.message || `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { shouldProceed: true, hookError: message }; } @@ -236,12 +239,15 @@ export async function firePostToolUseHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. - // `??` not `||`: a runner returning `{ error: { message: "" } }` - // is unhelpful but still IS a message — only synthesize the - // sentinel when the message is truly absent (#4321 review-8 - // wenshao Suggestion). + // `||` (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 ?? + response.error?.message || `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { shouldStop: false, hookError: message }; } @@ -323,12 +329,15 @@ export async function firePostToolUseFailureHook( if (!response.success || !response.output) { // See firePreToolUseHook for the rationale. - // `??` not `||`: a runner returning `{ error: { message: "" } }` - // is unhelpful but still IS a message — only synthesize the - // sentinel when the message is truly absent (#4321 review-8 - // wenshao Suggestion). + // `||` (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 ?? + response.error?.message || `hook runner returned ${response.success ? 'no output' : 'success: false'} without error detail`; return { hookError: message }; } diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index 1422483fc07..5e7114d5898 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -1041,8 +1041,12 @@ describe('session-tracing', () => { lastBeforeSentinel.length - 1, ); expect(lastCharCode).not.toBeGreaterThanOrEqual(0xd800); - // And the result must be valid UTF-16 (no orphan surrogates). - expect(() => Buffer.from(truncated, 'utf16le')).not.toThrow(); + // 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])/); }); }); }); From ac7597e8b787187e40a56fe6aa3e08be94491543 Mon Sep 17 00:00:00 2001 From: doudouOUC Date: Thu, 21 May 2026 11:07:22 +0800 Subject: [PATCH 21/21] test(telemetry): pin empty-string runner error sentinel behavior on PR #4321 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit [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) --- .../core/src/core/toolHookTriggers.test.ts | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) diff --git a/packages/core/src/core/toolHookTriggers.test.ts b/packages/core/src/core/toolHookTriggers.test.ts index df3a6ae7501..165dfe8a942 100644 --- a/packages/core/src/core/toolHookTriggers.test.ts +++ b/packages/core/src/core/toolHookTriggers.test.ts @@ -80,6 +80,32 @@ describe('toolHookTriggers', () => { 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).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 () => { const mockMessageBus = createMockMessageBus(); (mockMessageBus.request as ReturnType).mockResolvedValue({ @@ -264,6 +290,28 @@ describe('toolHookTriggers', () => { 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).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 () => { const mockMessageBus = createMockMessageBus(); (mockMessageBus.request as ReturnType).mockResolvedValue({ @@ -388,6 +436,26 @@ describe('toolHookTriggers', () => { 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).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 () => { const mockMessageBus = createMockMessageBus(); (mockMessageBus.request as ReturnType).mockResolvedValue({