From ff10b9fded58531d3a79d49a924eb87642314c9a Mon Sep 17 00:00:00 2001 From: "mingholy.lmh" Date: Fri, 10 Oct 2025 20:32:57 +0800 Subject: [PATCH 1/2] fix: add missing trace info and cancellation events --- packages/cli/src/ui/hooks/useGeminiStream.ts | 23 +++++- packages/core/src/core/coreToolScheduler.ts | 21 ++++- .../core/openaiContentGenerator/pipeline.ts | 6 ++ packages/core/src/telemetry/constants.ts | 1 + packages/core/src/telemetry/index.ts | 4 + packages/core/src/telemetry/loggers.ts | 24 ++++++ .../telemetry/qwen-logger/qwen-logger.test.ts | 81 +++++++++++++++++++ .../src/telemetry/qwen-logger/qwen-logger.ts | 19 +++++ packages/core/src/telemetry/types.ts | 30 ++++++- 9 files changed, 206 insertions(+), 3 deletions(-) diff --git a/packages/cli/src/ui/hooks/useGeminiStream.ts b/packages/cli/src/ui/hooks/useGeminiStream.ts index 5bac2c4109..8e654bae61 100644 --- a/packages/cli/src/ui/hooks/useGeminiStream.ts +++ b/packages/cli/src/ui/hooks/useGeminiStream.ts @@ -31,6 +31,9 @@ import { ConversationFinishedEvent, ApprovalMode, parseAndFormatApiError, + logUserCancellation, + UserCancellationEvent, + UserCancellationType, } from '@qwen-code/qwen-code-core'; import { type Part, type PartListUnion, FinishReason } from '@google/genai'; import type { @@ -448,6 +451,17 @@ export const useGeminiStream = ( if (turnCancelledRef.current) { return; } + + // Log user cancellation event + const prompt_id = config.getSessionId() + '########' + getPromptCount(); + const cancellationEvent = new UserCancellationEvent( + UserCancellationType.REQUEST_CANCELLED, + { + prompt_id, + }, + ); + logUserCancellation(config, cancellationEvent); + if (pendingHistoryItemRef.current) { if (pendingHistoryItemRef.current.type === 'tool_group') { const updatedTools = pendingHistoryItemRef.current.tools.map( @@ -475,7 +489,14 @@ export const useGeminiStream = ( setIsResponding(false); setThought(null); // Reset thought when user cancels }, - [addItem, pendingHistoryItemRef, setPendingHistoryItem, setThought], + [ + addItem, + pendingHistoryItemRef, + setPendingHistoryItem, + setThought, + config, + getPromptCount, + ], ); const handleErrorEvent = useCallback( diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 60e2b04f72..855bd06e29 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -23,6 +23,9 @@ import { logToolCall, ToolErrorType, ToolCallEvent, + logUserCancellation, + UserCancellationEvent, + UserCancellationType, } from '../index.js'; import type { Part, PartListUnion } from '@google/genai'; import { getResponseTextFromParts } from '../utils/generateContentResponseUtilities.js'; @@ -401,7 +404,7 @@ export class CoreToolScheduler { } } - return { + const cancelledCall = { request: currentCall.request, tool: toolInstance, invocation, @@ -426,6 +429,11 @@ export class CoreToolScheduler { durationMs, outcome, } as CancelledToolCall; + + // Log the tool call cancellation + this.logToolCallCancellation(cancelledCall); + + return cancelledCall; } case 'validating': return { @@ -1011,6 +1019,17 @@ export class CoreToolScheduler { } } + private logToolCallCancellation(toolCall: ToolCall): void { + const cancellationEvent = new UserCancellationEvent( + UserCancellationType.TOOL_CALL_CANCELLED, + { + prompt_id: toolCall.request.prompt_id, + tool_name: toolCall.request.name, + }, + ); + logUserCancellation(this.config, cancellationEvent); + } + private setToolCallOutcome(callId: string, outcome: ToolConfirmationOutcome) { this.toolCalls = this.toolCalls.map((call) => { if (call.request.callId !== callId) return call; diff --git a/packages/core/src/core/openaiContentGenerator/pipeline.ts b/packages/core/src/core/openaiContentGenerator/pipeline.ts index a911936c6e..2829496783 100644 --- a/packages/core/src/core/openaiContentGenerator/pipeline.ts +++ b/packages/core/src/core/openaiContentGenerator/pipeline.ts @@ -221,6 +221,12 @@ export class ContentGenerationPipeline { mergedResponse.usageMetadata = lastResponse.usageMetadata; } + // Copy other essential properties from the current response + mergedResponse.responseId = response.responseId; + mergedResponse.createTime = response.createTime; + mergedResponse.modelVersion = response.modelVersion; + mergedResponse.promptFeedback = response.promptFeedback; + // Update the collected responses with the merged response collectedGeminiResponses[collectedGeminiResponses.length - 1] = mergedResponse; diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 8cc69ce529..496818b1f5 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -25,6 +25,7 @@ export const EVENT_CONVERSATION_FINISHED = 'qwen-code.conversation_finished'; export const EVENT_MALFORMED_JSON_RESPONSE = 'qwen-code.malformed_json_response'; export const EVENT_SUBAGENT_EXECUTION = 'qwen-code.subagent_execution'; +export const EVENT_USER_CANCELLATION = 'qwen-code.user_cancellation'; export const METRIC_TOOL_CALL_COUNT = 'qwen-code.tool.call.count'; export const METRIC_TOOL_CALL_LATENCY = 'qwen-code.tool.call.latency'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index e70e2f6494..68720bdd41 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -26,6 +26,7 @@ export { logKittySequenceOverflow, logSlashCommand, logToolCall, + logUserCancellation, logUserPrompt, } from './loggers.js'; export { @@ -46,6 +47,8 @@ export { SlashCommandStatus, StartSessionEvent, ToolCallEvent, + UserCancellationEvent, + UserCancellationType, UserPromptEvent, } from './types.js'; export type { @@ -54,4 +57,5 @@ export type { TelemetryEvent, } from './types.js'; export * from './uiTelemetry.js'; +export { QwenLogger } from './qwen-logger/qwen-logger.js'; export { DEFAULT_OTLP_ENDPOINT, DEFAULT_TELEMETRY_TARGET }; diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index 627ac86d18..b58140a106 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -26,6 +26,7 @@ import { EVENT_SLASH_COMMAND, EVENT_SUBAGENT_EXECUTION, EVENT_TOOL_CALL, + EVENT_USER_CANCELLATION, EVENT_USER_PROMPT, SERVICE_NAME, } from './constants.js'; @@ -62,6 +63,7 @@ import type { StartSessionEvent, SubagentExecutionEvent, ToolCallEvent, + UserCancellationEvent, UserPromptEvent, } from './types.js'; import { type UiEvent, uiTelemetryService } from './uiTelemetry.js'; @@ -591,3 +593,25 @@ export function logSubagentExecution( event.terminate_reason, ); } + +export function logUserCancellation( + config: Config, + event: UserCancellationEvent, +): void { + QwenLogger.getInstance(config)?.logUserCancellationEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_USER_CANCELLATION, + 'event.timestamp': new Date().toISOString(), + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `User cancellation: ${event.cancellation_type}.`, + attributes, + }; + logger.emit(logRecord); +} diff --git a/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts b/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts index 0aa44d98f4..804d699250 100644 --- a/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts +++ b/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts @@ -21,6 +21,8 @@ import { IdeConnectionEvent, KittySequenceOverflowEvent, IdeConnectionType, + UserCancellationEvent, + UserCancellationType, } from '../types.js'; import type { RumEvent } from './event-types.js'; @@ -318,6 +320,85 @@ describe('QwenLogger', () => { expect(flushSpy).toHaveBeenCalled(); }); + + it('should log user cancellation events for request cancellation', () => { + const logger = QwenLogger.getInstance(mockConfig)!; + const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); + + const event = new UserCancellationEvent( + UserCancellationType.REQUEST_CANCELLED, + { + prompt_id: 'test-prompt-123', + }, + ); + + logger.logUserCancellationEvent(event); + + expect(enqueueSpy).toHaveBeenCalledWith( + expect.objectContaining({ + event_type: 'action', + type: 'cancellation', + name: 'user_cancellation', + properties: { + cancellation_type: UserCancellationType.REQUEST_CANCELLED, + prompt_id: 'test-prompt-123', + tool_name: undefined, + }, + }), + ); + }); + + it('should log user cancellation events for tool call cancellation', () => { + const logger = QwenLogger.getInstance(mockConfig)!; + const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); + + const event = new UserCancellationEvent( + UserCancellationType.TOOL_CALL_CANCELLED, + { + prompt_id: 'test-prompt-456', + tool_name: 'read_file', + }, + ); + + logger.logUserCancellationEvent(event); + + expect(enqueueSpy).toHaveBeenCalledWith( + expect.objectContaining({ + event_type: 'action', + type: 'cancellation', + name: 'user_cancellation', + properties: { + cancellation_type: UserCancellationType.TOOL_CALL_CANCELLED, + prompt_id: 'test-prompt-456', + tool_name: 'read_file', + }, + }), + ); + }); + + it('should log user cancellation events with minimal data', () => { + const logger = QwenLogger.getInstance(mockConfig)!; + const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); + + const event = new UserCancellationEvent( + UserCancellationType.REQUEST_CANCELLED, + ); + + logger.logUserCancellationEvent(event); + + expect(enqueueSpy).toHaveBeenCalledWith( + expect.objectContaining({ + event_type: 'action', + type: 'cancellation', + name: 'user_cancellation', + properties: { + cancellation_type: UserCancellationType.REQUEST_CANCELLED, + prompt_id: undefined, + tool_name: undefined, + }, + }), + ); + }); }); describe('flush timing', () => { diff --git a/packages/core/src/telemetry/qwen-logger/qwen-logger.ts b/packages/core/src/telemetry/qwen-logger/qwen-logger.ts index 215e6d95bf..75a2f6f268 100644 --- a/packages/core/src/telemetry/qwen-logger/qwen-logger.ts +++ b/packages/core/src/telemetry/qwen-logger/qwen-logger.ts @@ -687,6 +687,25 @@ export class QwenLogger { this.flushIfNeeded(); } + logUserCancellationEvent( + event: import('../types.js').UserCancellationEvent, + ): void { + const rumEvent = this.createActionEvent( + 'cancellation', + 'user_cancellation', + { + properties: { + cancellation_type: event.cancellation_type, + prompt_id: event.prompt_id, + tool_name: event.tool_name, + }, + }, + ); + + this.enqueueLogEvent(rumEvent); + this.flushIfNeeded(); + } + logEndSessionEvent(_event: EndSessionEvent): void { const applicationEvent = this.createViewEvent('session', 'session_end', {}); diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index 400fcc0986..b17273020c 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -535,6 +535,33 @@ export class SubagentExecutionEvent implements BaseTelemetryEvent { } } +export enum UserCancellationType { + REQUEST_CANCELLED = 'request_cancelled', + TOOL_CALL_CANCELLED = 'tool_call_cancelled', +} + +export class UserCancellationEvent implements BaseTelemetryEvent { + 'event.name': 'user_cancellation'; + 'event.timestamp': string; + cancellation_type: UserCancellationType; + prompt_id?: string; + tool_name?: string; + + constructor( + cancellation_type: UserCancellationType, + options?: { + prompt_id?: string; + tool_name?: string; + }, + ) { + this['event.name'] = 'user_cancellation'; + this['event.timestamp'] = new Date().toISOString(); + this.cancellation_type = cancellation_type; + this.prompt_id = options?.prompt_id; + this.tool_name = options?.tool_name; + } +} + export type TelemetryEvent = | StartSessionEvent | EndSessionEvent @@ -555,4 +582,5 @@ export type TelemetryEvent = | InvalidChunkEvent | ContentRetryEvent | ContentRetryFailureEvent - | SubagentExecutionEvent; + | SubagentExecutionEvent + | UserCancellationEvent; From ad6543787f2c681c462db11328c809029b42dc21 Mon Sep 17 00:00:00 2001 From: "mingholy.lmh" Date: Mon, 13 Oct 2025 19:25:15 +0800 Subject: [PATCH 2/2] fix: re-organize tool/request cancellation logging --- .../cli/src/ui/hooks/useGeminiStream.test.tsx | 6 ++ packages/cli/src/ui/hooks/useGeminiStream.ts | 36 +++----- .../cli/src/zed-integration/zedIntegration.ts | 2 + packages/core/src/core/coreToolScheduler.ts | 17 ---- packages/core/src/core/turn.ts | 8 ++ packages/core/src/subagents/subagent.ts | 9 ++ packages/core/src/telemetry/constants.ts | 2 +- packages/core/src/telemetry/index.ts | 5 +- packages/core/src/telemetry/loggers.test.ts | 5 + packages/core/src/telemetry/loggers.ts | 52 ++++++----- .../telemetry/qwen-logger/qwen-logger.test.ts | 81 ----------------- .../src/telemetry/qwen-logger/qwen-logger.ts | 34 +++---- packages/core/src/telemetry/types.ts | 55 +++++------ .../core/src/telemetry/uiTelemetry.test.ts | 91 ++++++++++++++++++- 14 files changed, 204 insertions(+), 199 deletions(-) diff --git a/packages/cli/src/ui/hooks/useGeminiStream.test.tsx b/packages/cli/src/ui/hooks/useGeminiStream.test.tsx index 57da20c138..4cbf676c23 100644 --- a/packages/cli/src/ui/hooks/useGeminiStream.test.tsx +++ b/packages/cli/src/ui/hooks/useGeminiStream.test.tsx @@ -54,7 +54,11 @@ const MockedGeminiClientClass = vi.hoisted(() => const MockedUserPromptEvent = vi.hoisted(() => vi.fn().mockImplementation(() => {}), ); +const MockedApiCancelEvent = vi.hoisted(() => + vi.fn().mockImplementation(() => {}), +); const mockParseAndFormatApiError = vi.hoisted(() => vi.fn()); +const mockLogApiCancel = vi.hoisted(() => vi.fn()); // Vision auto-switch mocks (hoisted) const mockHandleVisionSwitch = vi.hoisted(() => @@ -71,7 +75,9 @@ vi.mock('@qwen-code/qwen-code-core', async (importOriginal) => { GitService: vi.fn(), GeminiClient: MockedGeminiClientClass, UserPromptEvent: MockedUserPromptEvent, + ApiCancelEvent: MockedApiCancelEvent, parseAndFormatApiError: mockParseAndFormatApiError, + logApiCancel: mockLogApiCancel, }; }); diff --git a/packages/cli/src/ui/hooks/useGeminiStream.ts b/packages/cli/src/ui/hooks/useGeminiStream.ts index 8e654bae61..760adb9182 100644 --- a/packages/cli/src/ui/hooks/useGeminiStream.ts +++ b/packages/cli/src/ui/hooks/useGeminiStream.ts @@ -31,9 +31,8 @@ import { ConversationFinishedEvent, ApprovalMode, parseAndFormatApiError, - logUserCancellation, - UserCancellationEvent, - UserCancellationType, + logApiCancel, + ApiCancelEvent, } from '@qwen-code/qwen-code-core'; import { type Part, type PartListUnion, FinishReason } from '@google/genai'; import type { @@ -226,6 +225,16 @@ export const useGeminiStream = ( turnCancelledRef.current = true; isSubmittingQueryRef.current = false; abortControllerRef.current?.abort(); + + // Log API cancellation + const prompt_id = config.getSessionId() + '########' + getPromptCount(); + const cancellationEvent = new ApiCancelEvent( + config.getModel(), + prompt_id, + config.getContentGeneratorConfig()?.authType, + ); + logApiCancel(config, cancellationEvent); + if (pendingHistoryItemRef.current) { addItem(pendingHistoryItemRef.current, Date.now()); } @@ -245,6 +254,8 @@ export const useGeminiStream = ( setPendingHistoryItem, onCancelSubmit, pendingHistoryItemRef, + config, + getPromptCount, ]); useKeypress( @@ -452,16 +463,6 @@ export const useGeminiStream = ( return; } - // Log user cancellation event - const prompt_id = config.getSessionId() + '########' + getPromptCount(); - const cancellationEvent = new UserCancellationEvent( - UserCancellationType.REQUEST_CANCELLED, - { - prompt_id, - }, - ); - logUserCancellation(config, cancellationEvent); - if (pendingHistoryItemRef.current) { if (pendingHistoryItemRef.current.type === 'tool_group') { const updatedTools = pendingHistoryItemRef.current.tools.map( @@ -489,14 +490,7 @@ export const useGeminiStream = ( setIsResponding(false); setThought(null); // Reset thought when user cancels }, - [ - addItem, - pendingHistoryItemRef, - setPendingHistoryItem, - setThought, - config, - getPromptCount, - ], + [addItem, pendingHistoryItemRef, setPendingHistoryItem, setThought], ); const handleErrorEvent = useCallback( diff --git a/packages/cli/src/zed-integration/zedIntegration.ts b/packages/cli/src/zed-integration/zedIntegration.ts index 8e39d3f077..66968b1b98 100644 --- a/packages/cli/src/zed-integration/zedIntegration.ts +++ b/packages/cli/src/zed-integration/zedIntegration.ts @@ -365,6 +365,7 @@ class Session { function_name: fc.name ?? '', function_args: args, duration_ms: durationMs, + status: 'error', success: false, error: error.message, tool_type: @@ -483,6 +484,7 @@ class Session { function_name: fc.name, function_args: args, duration_ms: durationMs, + status: 'success', success: true, prompt_id: promptId, tool_type: diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 855bd06e29..fc83cf9ec8 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -23,9 +23,6 @@ import { logToolCall, ToolErrorType, ToolCallEvent, - logUserCancellation, - UserCancellationEvent, - UserCancellationType, } from '../index.js'; import type { Part, PartListUnion } from '@google/genai'; import { getResponseTextFromParts } from '../utils/generateContentResponseUtilities.js'; @@ -430,9 +427,6 @@ export class CoreToolScheduler { outcome, } as CancelledToolCall; - // Log the tool call cancellation - this.logToolCallCancellation(cancelledCall); - return cancelledCall; } case 'validating': @@ -1019,17 +1013,6 @@ export class CoreToolScheduler { } } - private logToolCallCancellation(toolCall: ToolCall): void { - const cancellationEvent = new UserCancellationEvent( - UserCancellationType.TOOL_CALL_CANCELLED, - { - prompt_id: toolCall.request.prompt_id, - tool_name: toolCall.request.name, - }, - ); - logUserCancellation(this.config, cancellationEvent); - } - private setToolCallOutcome(callId: string, outcome: ToolConfirmationOutcome) { this.toolCalls = this.toolCalls.map((call) => { if (call.request.callId !== callId) return call; diff --git a/packages/core/src/core/turn.ts b/packages/core/src/core/turn.ts index ad6f83195e..70d7188692 100644 --- a/packages/core/src/core/turn.ts +++ b/packages/core/src/core/turn.ts @@ -84,6 +84,7 @@ export interface ToolCallRequestInfo { args: Record; isClientInitiated: boolean; prompt_id: string; + response_id?: string; } export interface ToolCallResponseInfo { @@ -202,6 +203,7 @@ export class Turn { readonly pendingToolCalls: ToolCallRequestInfo[]; private debugResponses: GenerateContentResponse[]; finishReason: FinishReason | undefined; + private currentResponseId?: string; constructor( private readonly chat: GeminiChat, @@ -247,6 +249,11 @@ export class Turn { this.debugResponses.push(resp); + // Track the current response ID for tool call correlation + if (resp.responseId) { + this.currentResponseId = resp.responseId; + } + const thoughtPart = resp.candidates?.[0]?.content?.parts?.[0]; if (thoughtPart?.thought) { // Thought always has a bold "subject" part enclosed in double asterisks @@ -346,6 +353,7 @@ export class Turn { args, isClientInitiated: false, prompt_id: this.prompt_id, + response_id: this.currentResponseId, }; this.pendingToolCalls.push(toolCallRequest); diff --git a/packages/core/src/subagents/subagent.ts b/packages/core/src/subagents/subagent.ts index 19636b3c0b..0f4e884353 100644 --- a/packages/core/src/subagents/subagent.ts +++ b/packages/core/src/subagents/subagent.ts @@ -381,6 +381,7 @@ export class SubAgentScope { let roundText = ''; let lastUsage: GenerateContentResponseUsageMetadata | undefined = undefined; + let currentResponseId: string | undefined = undefined; for await (const streamEvent of responseStream) { if (abortController.signal.aborted) { this.terminateMode = SubagentTerminateMode.CANCELLED; @@ -395,6 +396,10 @@ export class SubAgentScope { // Handle chunk events if (streamEvent.type === 'chunk') { const resp = streamEvent.value; + // Track the response ID for tool call correlation + if (resp.responseId) { + currentResponseId = resp.responseId; + } if (resp.functionCalls) functionCalls.push(...resp.functionCalls); const content = resp.candidates?.[0]?.content; const parts = content?.parts || []; @@ -455,6 +460,7 @@ export class SubAgentScope { abortController, promptId, turnCounter, + currentResponseId, ); } else { // No tool calls — treat this as the model's final answer. @@ -543,6 +549,7 @@ export class SubAgentScope { * @param {FunctionCall[]} functionCalls - An array of `FunctionCall` objects to process. * @param {ToolRegistry} toolRegistry - The tool registry to look up and execute tools. * @param {AbortController} abortController - An `AbortController` to signal cancellation of tool executions. + * @param {string} responseId - Optional API response ID for correlation with tool calls. * @returns {Promise} A promise that resolves to an array of `Content` parts representing the tool responses, * which are then used to update the chat history. */ @@ -551,6 +558,7 @@ export class SubAgentScope { abortController: AbortController, promptId: string, currentRound: number, + responseId?: string, ): Promise { const toolResponseParts: Part[] = []; @@ -704,6 +712,7 @@ export class SubAgentScope { args, isClientInitiated: true, prompt_id: promptId, + response_id: responseId, }; const description = this.getToolDescription(toolName, args); diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 496818b1f5..0f8337cb4c 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -10,6 +10,7 @@ export const EVENT_USER_PROMPT = 'qwen-code.user_prompt'; export const EVENT_TOOL_CALL = 'qwen-code.tool_call'; export const EVENT_API_REQUEST = 'qwen-code.api_request'; export const EVENT_API_ERROR = 'qwen-code.api_error'; +export const EVENT_API_CANCEL = 'qwen-code.api_cancel'; export const EVENT_API_RESPONSE = 'qwen-code.api_response'; export const EVENT_CLI_CONFIG = 'qwen-code.config'; export const EVENT_FLASH_FALLBACK = 'qwen-code.flash_fallback'; @@ -25,7 +26,6 @@ export const EVENT_CONVERSATION_FINISHED = 'qwen-code.conversation_finished'; export const EVENT_MALFORMED_JSON_RESPONSE = 'qwen-code.malformed_json_response'; export const EVENT_SUBAGENT_EXECUTION = 'qwen-code.subagent_execution'; -export const EVENT_USER_CANCELLATION = 'qwen-code.user_cancellation'; export const METRIC_TOOL_CALL_COUNT = 'qwen-code.tool.call.count'; export const METRIC_TOOL_CALL_LATENCY = 'qwen-code.tool.call.latency'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index 68720bdd41..366eb34113 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -17,6 +17,7 @@ export { SpanStatusCode, ValueType } from '@opentelemetry/api'; export { SemanticAttributes } from '@opentelemetry/semantic-conventions'; export { logApiError, + logApiCancel, logApiRequest, logApiResponse, logChatCompression, @@ -26,7 +27,6 @@ export { logKittySequenceOverflow, logSlashCommand, logToolCall, - logUserCancellation, logUserPrompt, } from './loggers.js'; export { @@ -36,6 +36,7 @@ export { } from './sdk.js'; export { ApiErrorEvent, + ApiCancelEvent, ApiRequestEvent, ApiResponseEvent, ConversationFinishedEvent, @@ -47,8 +48,6 @@ export { SlashCommandStatus, StartSessionEvent, ToolCallEvent, - UserCancellationEvent, - UserCancellationType, UserPromptEvent, } from './types.js'; export type { diff --git a/packages/core/src/telemetry/loggers.test.ts b/packages/core/src/telemetry/loggers.test.ts index 0fde948f0c..8a0d8161b1 100644 --- a/packages/core/src/telemetry/loggers.test.ts +++ b/packages/core/src/telemetry/loggers.test.ts @@ -550,6 +550,7 @@ describe('loggers', () => { 2, ), duration_ms: 100, + status: 'success', success: true, decision: ToolCallDecision.ACCEPT, prompt_id: 'prompt-id-1', @@ -619,6 +620,7 @@ describe('loggers', () => { 2, ), duration_ms: 100, + status: 'error', success: false, decision: ToolCallDecision.REJECT, prompt_id: 'prompt-id-2', @@ -691,6 +693,7 @@ describe('loggers', () => { 2, ), duration_ms: 100, + status: 'success', success: true, decision: ToolCallDecision.MODIFY, prompt_id: 'prompt-id-3', @@ -762,6 +765,7 @@ describe('loggers', () => { 2, ), duration_ms: 100, + status: 'success', success: true, prompt_id: 'prompt-id-4', tool_type: 'native', @@ -834,6 +838,7 @@ describe('loggers', () => { 2, ), duration_ms: 100, + status: 'error', success: false, error: 'test-error', 'error.message': 'test-error', diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index b58140a106..7976b098d9 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -12,6 +12,7 @@ import { safeJsonStringify } from '../utils/safeJsonStringify.js'; import { UserAccountManager } from '../utils/userAccountManager.js'; import { EVENT_API_ERROR, + EVENT_API_CANCEL, EVENT_API_REQUEST, EVENT_API_RESPONSE, EVENT_CHAT_COMPRESSION, @@ -26,7 +27,6 @@ import { EVENT_SLASH_COMMAND, EVENT_SUBAGENT_EXECUTION, EVENT_TOOL_CALL, - EVENT_USER_CANCELLATION, EVENT_USER_PROMPT, SERVICE_NAME, } from './constants.js'; @@ -46,6 +46,7 @@ import { QwenLogger } from './qwen-logger/qwen-logger.js'; import { isTelemetrySdkInitialized } from './sdk.js'; import type { ApiErrorEvent, + ApiCancelEvent, ApiRequestEvent, ApiResponseEvent, ChatCompressionEvent, @@ -63,7 +64,6 @@ import type { StartSessionEvent, SubagentExecutionEvent, ToolCallEvent, - UserCancellationEvent, UserPromptEvent, } from './types.js'; import { type UiEvent, uiTelemetryService } from './uiTelemetry.js'; @@ -284,6 +284,32 @@ export function logApiError(config: Config, event: ApiErrorEvent): void { ); } +export function logApiCancel(config: Config, event: ApiCancelEvent): void { + const uiEvent = { + ...event, + 'event.name': EVENT_API_CANCEL, + 'event.timestamp': new Date().toISOString(), + } as UiEvent; + uiTelemetryService.addEvent(uiEvent); + QwenLogger.getInstance(config)?.logApiCancelEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_API_CANCEL, + 'event.timestamp': new Date().toISOString(), + model_name: event.model, + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `API request cancelled for ${event.model}.`, + attributes, + }; + logger.emit(logRecord); +} + export function logApiResponse(config: Config, event: ApiResponseEvent): void { const uiEvent = { ...event, @@ -593,25 +619,3 @@ export function logSubagentExecution( event.terminate_reason, ); } - -export function logUserCancellation( - config: Config, - event: UserCancellationEvent, -): void { - QwenLogger.getInstance(config)?.logUserCancellationEvent(event); - if (!isTelemetrySdkInitialized()) return; - - const attributes: LogAttributes = { - ...getCommonAttributes(config), - ...event, - 'event.name': EVENT_USER_CANCELLATION, - 'event.timestamp': new Date().toISOString(), - }; - - const logger = logs.getLogger(SERVICE_NAME); - const logRecord: LogRecord = { - body: `User cancellation: ${event.cancellation_type}.`, - attributes, - }; - logger.emit(logRecord); -} diff --git a/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts b/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts index 804d699250..0aa44d98f4 100644 --- a/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts +++ b/packages/core/src/telemetry/qwen-logger/qwen-logger.test.ts @@ -21,8 +21,6 @@ import { IdeConnectionEvent, KittySequenceOverflowEvent, IdeConnectionType, - UserCancellationEvent, - UserCancellationType, } from '../types.js'; import type { RumEvent } from './event-types.js'; @@ -320,85 +318,6 @@ describe('QwenLogger', () => { expect(flushSpy).toHaveBeenCalled(); }); - - it('should log user cancellation events for request cancellation', () => { - const logger = QwenLogger.getInstance(mockConfig)!; - const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); - - const event = new UserCancellationEvent( - UserCancellationType.REQUEST_CANCELLED, - { - prompt_id: 'test-prompt-123', - }, - ); - - logger.logUserCancellationEvent(event); - - expect(enqueueSpy).toHaveBeenCalledWith( - expect.objectContaining({ - event_type: 'action', - type: 'cancellation', - name: 'user_cancellation', - properties: { - cancellation_type: UserCancellationType.REQUEST_CANCELLED, - prompt_id: 'test-prompt-123', - tool_name: undefined, - }, - }), - ); - }); - - it('should log user cancellation events for tool call cancellation', () => { - const logger = QwenLogger.getInstance(mockConfig)!; - const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); - - const event = new UserCancellationEvent( - UserCancellationType.TOOL_CALL_CANCELLED, - { - prompt_id: 'test-prompt-456', - tool_name: 'read_file', - }, - ); - - logger.logUserCancellationEvent(event); - - expect(enqueueSpy).toHaveBeenCalledWith( - expect.objectContaining({ - event_type: 'action', - type: 'cancellation', - name: 'user_cancellation', - properties: { - cancellation_type: UserCancellationType.TOOL_CALL_CANCELLED, - prompt_id: 'test-prompt-456', - tool_name: 'read_file', - }, - }), - ); - }); - - it('should log user cancellation events with minimal data', () => { - const logger = QwenLogger.getInstance(mockConfig)!; - const enqueueSpy = vi.spyOn(logger, 'enqueueLogEvent'); - - const event = new UserCancellationEvent( - UserCancellationType.REQUEST_CANCELLED, - ); - - logger.logUserCancellationEvent(event); - - expect(enqueueSpy).toHaveBeenCalledWith( - expect.objectContaining({ - event_type: 'action', - type: 'cancellation', - name: 'user_cancellation', - properties: { - cancellation_type: UserCancellationType.REQUEST_CANCELLED, - prompt_id: undefined, - tool_name: undefined, - }, - }), - ); - }); }); describe('flush timing', () => { diff --git a/packages/core/src/telemetry/qwen-logger/qwen-logger.ts b/packages/core/src/telemetry/qwen-logger/qwen-logger.ts index 75a2f6f268..e464e9d9a1 100644 --- a/packages/core/src/telemetry/qwen-logger/qwen-logger.ts +++ b/packages/core/src/telemetry/qwen-logger/qwen-logger.ts @@ -15,6 +15,7 @@ import type { ApiRequestEvent, ApiResponseEvent, ApiErrorEvent, + ApiCancelEvent, FileOperationEvent, FlashFallbackEvent, LoopDetectedEvent, @@ -411,6 +412,7 @@ export class QwenLogger { { properties: { prompt_id: event.prompt_id, + response_id: event.response_id, }, snapshots: JSON.stringify({ function_name: event.function_name, @@ -427,6 +429,19 @@ export class QwenLogger { this.flushIfNeeded(); } + logApiCancelEvent(event: ApiCancelEvent): void { + const rumEvent = this.createActionEvent('api', 'api_cancel', { + properties: { + model: event.model, + prompt_id: event.prompt_id, + auth_type: event.auth_type, + }, + }); + + this.enqueueLogEvent(rumEvent); + this.flushIfNeeded(); + } + logFileOperationEvent(event: FileOperationEvent): void { const rumEvent = this.createActionEvent( 'file_operation', @@ -687,25 +702,6 @@ export class QwenLogger { this.flushIfNeeded(); } - logUserCancellationEvent( - event: import('../types.js').UserCancellationEvent, - ): void { - const rumEvent = this.createActionEvent( - 'cancellation', - 'user_cancellation', - { - properties: { - cancellation_type: event.cancellation_type, - prompt_id: event.prompt_id, - tool_name: event.tool_name, - }, - }, - ); - - this.enqueueLogEvent(rumEvent); - this.flushIfNeeded(); - } - logEndSessionEvent(_event: EndSessionEvent): void { const applicationEvent = this.createViewEvent('session', 'session_end', {}); diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index b17273020c..aa2887445e 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -127,11 +127,13 @@ export class ToolCallEvent implements BaseTelemetryEvent { function_name: string; function_args: Record; duration_ms: number; - success: boolean; + status: 'success' | 'error' | 'cancelled'; + success: boolean; // Keep for backward compatibility decision?: ToolCallDecision; error?: string; error_type?: string; prompt_id: string; + response_id?: string; tool_type: 'native' | 'mcp'; // eslint-disable-next-line @typescript-eslint/no-explicit-any metadata?: { [key: string]: any }; @@ -142,13 +144,15 @@ export class ToolCallEvent implements BaseTelemetryEvent { this.function_name = call.request.name; this.function_args = call.request.args; this.duration_ms = call.durationMs ?? 0; - this.success = call.status === 'success'; + this.status = call.status; + this.success = call.status === 'success'; // Keep for backward compatibility this.decision = call.outcome ? getDecisionFromOutcome(call.outcome) : undefined; this.error = call.response.error?.message; this.error_type = call.response.errorType; this.prompt_id = call.request.prompt_id; + this.response_id = call.request.response_id; this.tool_type = typeof call.tool !== 'undefined' && call.tool instanceof DiscoveredMCPTool ? 'mcp' @@ -224,6 +228,22 @@ export class ApiErrorEvent implements BaseTelemetryEvent { } } +export class ApiCancelEvent implements BaseTelemetryEvent { + 'event.name': 'api_cancel'; + 'event.timestamp': string; + model: string; + prompt_id: string; + auth_type?: string; + + constructor(model: string, prompt_id: string, auth_type?: string) { + this['event.name'] = 'api_cancel'; + this['event.timestamp'] = new Date().toISOString(); + this.model = model; + this.prompt_id = prompt_id; + this.auth_type = auth_type; + } +} + export class ApiResponseEvent implements BaseTelemetryEvent { 'event.name': 'api_response'; 'event.timestamp': string; // ISO 8601 @@ -535,33 +555,6 @@ export class SubagentExecutionEvent implements BaseTelemetryEvent { } } -export enum UserCancellationType { - REQUEST_CANCELLED = 'request_cancelled', - TOOL_CALL_CANCELLED = 'tool_call_cancelled', -} - -export class UserCancellationEvent implements BaseTelemetryEvent { - 'event.name': 'user_cancellation'; - 'event.timestamp': string; - cancellation_type: UserCancellationType; - prompt_id?: string; - tool_name?: string; - - constructor( - cancellation_type: UserCancellationType, - options?: { - prompt_id?: string; - tool_name?: string; - }, - ) { - this['event.name'] = 'user_cancellation'; - this['event.timestamp'] = new Date().toISOString(); - this.cancellation_type = cancellation_type; - this.prompt_id = options?.prompt_id; - this.tool_name = options?.tool_name; - } -} - export type TelemetryEvent = | StartSessionEvent | EndSessionEvent @@ -569,6 +562,7 @@ export type TelemetryEvent = | ToolCallEvent | ApiRequestEvent | ApiErrorEvent + | ApiCancelEvent | ApiResponseEvent | FlashFallbackEvent | LoopDetectedEvent @@ -582,5 +576,4 @@ export type TelemetryEvent = | InvalidChunkEvent | ContentRetryEvent | ContentRetryFailureEvent - | SubagentExecutionEvent - | UserCancellationEvent; + | SubagentExecutionEvent; diff --git a/packages/core/src/telemetry/uiTelemetry.test.ts b/packages/core/src/telemetry/uiTelemetry.test.ts index 86682a9528..da12e28dfc 100644 --- a/packages/core/src/telemetry/uiTelemetry.test.ts +++ b/packages/core/src/telemetry/uiTelemetry.test.ts @@ -15,6 +15,7 @@ import { EVENT_TOOL_CALL, } from './constants.js'; import type { + CancelledToolCall, CompletedToolCall, ErroredToolCall, SuccessfulToolCall, @@ -25,7 +26,7 @@ import { MockTool } from '../test-utils/tools.js'; const createFakeCompletedToolCall = ( name: string, - success: boolean, + success: boolean | 'cancelled', duration = 100, outcome?: ToolConfirmationOutcome, error?: Error, @@ -39,7 +40,7 @@ const createFakeCompletedToolCall = ( }; const tool = new MockTool(name); - if (success) { + if (success === true) { return { status: 'success', request, @@ -63,6 +64,30 @@ const createFakeCompletedToolCall = ( durationMs: duration, outcome, } as SuccessfulToolCall; + } else if (success === 'cancelled') { + return { + status: 'cancelled', + request, + tool, + invocation: tool.build({ param: 'test' }), + response: { + callId: request.callId, + responseParts: [ + { + functionResponse: { + id: request.callId, + name, + response: { error: 'Tool cancelled' }, + }, + }, + ], + error: new Error('Tool cancelled'), + errorType: ToolErrorType.UNKNOWN, + resultDisplay: 'Cancelled!', + }, + durationMs: duration, + outcome, + } as CancelledToolCall; } else { return { status: 'error', @@ -411,6 +436,40 @@ describe('UiTelemetryService', () => { }); }); + it('should process a single cancelled ToolCallEvent', () => { + const toolCall = createFakeCompletedToolCall( + 'test_tool', + 'cancelled', + 180, + ToolConfirmationOutcome.Cancel, + ); + service.addEvent({ + ...structuredClone(new ToolCallEvent(toolCall)), + 'event.name': EVENT_TOOL_CALL, + } as ToolCallEvent & { 'event.name': typeof EVENT_TOOL_CALL }); + + const metrics = service.getMetrics(); + const { tools } = metrics; + + expect(tools.totalCalls).toBe(1); + expect(tools.totalSuccess).toBe(0); + expect(tools.totalFail).toBe(1); + expect(tools.totalDurationMs).toBe(180); + expect(tools.totalDecisions[ToolCallDecision.REJECT]).toBe(1); + expect(tools.byName['test_tool']).toEqual({ + count: 1, + success: 0, + fail: 1, + durationMs: 180, + decisions: { + [ToolCallDecision.ACCEPT]: 0, + [ToolCallDecision.REJECT]: 1, + [ToolCallDecision.MODIFY]: 0, + [ToolCallDecision.AUTO_ACCEPT]: 0, + }, + }); + }); + it('should process a ToolCallEvent with modify decision', () => { const toolCall = createFakeCompletedToolCall( 'test_tool', @@ -637,6 +696,34 @@ describe('UiTelemetryService', () => { expect(service.getLastPromptTokenCount()).toBe(0); expect(spy).toHaveBeenCalledOnce(); }); + + it('should correctly set status field for success/error/cancelled calls', () => { + const successCall = createFakeCompletedToolCall( + 'success_tool', + true, + 100, + ); + const errorCall = createFakeCompletedToolCall('error_tool', false, 150); + const cancelledCall = createFakeCompletedToolCall( + 'cancelled_tool', + 'cancelled', + 200, + ); + + const successEvent = new ToolCallEvent(successCall); + const errorEvent = new ToolCallEvent(errorCall); + const cancelledEvent = new ToolCallEvent(cancelledCall); + + // Verify status field is correctly set + expect(successEvent.status).toBe('success'); + expect(errorEvent.status).toBe('error'); + expect(cancelledEvent.status).toBe('cancelled'); + + // Verify backward compatibility with success field + expect(successEvent.success).toBe(true); + expect(errorEvent.success).toBe(false); + expect(cancelledEvent.success).toBe(false); + }); }); describe('Tool Call Event with Line Count Metadata', () => {