diff --git a/docs/telemetry.md b/docs/telemetry.md index c91aed05c2..562e065769 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -194,6 +194,7 @@ Logs are timestamped records of specific events. The following events are logged - `decision` (string: "accept", "reject", "auto_accept", or "modify", if applicable) - `error` (if applicable) - `error_type` (if applicable) + - `content_length` (int, if applicable) - `metadata` (if applicable, dictionary of string -> any) - `gemini_cli.file_operation`: This event occurs for each file operation. @@ -238,6 +239,15 @@ Logs are timestamped records of specific events. The following events are logged - `response_text` (if applicable) - `auth_type` +- `gemini_cli.tool_output_truncated`: This event occurs when the output of a tool call is too large and gets truncated. + - **Attributes**: + - `tool_name` (string) + - `original_content_length` (int) + - `truncated_content_length` (int) + - `threshold` (int) + - `lines` (int) + - `prompt_id` (string) + - `gemini_cli.malformed_json_response`: This event occurs when a `generateJson` response from Gemini API cannot be parsed as a json. - **Attributes**: - `model` diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index c4f337dae4..090da42b9a 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -25,6 +25,8 @@ import { ToolErrorType, ToolCallEvent, ShellTool, + logToolOutputTruncated, + ToolOutputTruncatedEvent, } from '../index.js'; import type { Part, PartListUnion } from '@google/genai'; import { getResponseTextFromParts } from '../utils/generateContentResponseUtilities.js'; @@ -245,6 +247,7 @@ const createErrorResponse = ( ], resultDisplay: error.message, errorType, + contentLength: error.message.length, }); export async function truncateAndSaveToFile( @@ -461,6 +464,7 @@ export class CoreToolScheduler { } } + const errorMessage = `[Operation Cancelled] Reason: ${auxiliaryData}`; return { request: currentCall.request, tool: toolInstance, @@ -474,7 +478,7 @@ export class CoreToolScheduler { id: currentCall.request.callId, name: currentCall.request.name, response: { - error: `[Operation Cancelled] Reason: ${auxiliaryData}`, + error: errorMessage, }, }, }, @@ -482,6 +486,7 @@ export class CoreToolScheduler { resultDisplay, error: undefined, errorType: undefined, + contentLength: errorMessage.length, }, durationMs, outcome, @@ -975,6 +980,8 @@ export class CoreToolScheduler { if (toolResult.error === undefined) { let content = toolResult.llmContent; let outputFile: string | undefined = undefined; + const contentLength = + typeof content === 'string' ? content.length : undefined; if ( typeof content === 'string' && toolName === ShellTool.Name && @@ -982,13 +989,34 @@ export class CoreToolScheduler { this.config.getTruncateToolOutputThreshold() > 0 && this.config.getTruncateToolOutputLines() > 0 ) { - ({ content, outputFile } = await truncateAndSaveToFile( + const originalContentLength = content.length; + const threshold = this.config.getTruncateToolOutputThreshold(); + const lines = this.config.getTruncateToolOutputLines(); + const truncatedResult = await truncateAndSaveToFile( content, callId, this.config.storage.getProjectTempDir(), - this.config.getTruncateToolOutputThreshold(), - this.config.getTruncateToolOutputLines(), - )); + threshold, + lines, + ); + content = truncatedResult.content; + outputFile = truncatedResult.outputFile; + + if (outputFile) { + logToolOutputTruncated( + this.config, + new ToolOutputTruncatedEvent( + scheduledCall.request.prompt_id, + { + toolName, + originalContentLength, + truncatedContentLength: content.length, + threshold, + lines, + }, + ), + ); + } } const response = convertToFunctionResponse( @@ -1003,6 +1031,7 @@ export class CoreToolScheduler { error: undefined, errorType: undefined, outputFile, + contentLength, }; this.setStatusInternal(callId, 'success', successResponse); } else { diff --git a/packages/core/src/core/nonInteractiveToolExecutor.test.ts b/packages/core/src/core/nonInteractiveToolExecutor.test.ts index 864b78a9cf..8682158166 100644 --- a/packages/core/src/core/nonInteractiveToolExecutor.test.ts +++ b/packages/core/src/core/nonInteractiveToolExecutor.test.ts @@ -88,6 +88,10 @@ describe('executeToolCall', () => { errorType: undefined, outputFile: undefined, resultDisplay: 'Success!', + contentLength: + typeof toolResult.llmContent === 'string' + ? toolResult.llmContent.length + : undefined, responseParts: [ { functionResponse: { @@ -127,6 +131,7 @@ describe('executeToolCall', () => { error: new Error(expectedErrorMessage), errorType: ToolErrorType.TOOL_NOT_REGISTERED, resultDisplay: expectedErrorMessage, + contentLength: expectedErrorMessage.length, responseParts: [ { functionResponse: { @@ -176,6 +181,7 @@ describe('executeToolCall', () => { }, ], resultDisplay: 'Invalid parameters', + contentLength: 'Invalid parameters'.length, }); }); @@ -219,6 +225,7 @@ describe('executeToolCall', () => { }, ], resultDisplay: 'Execution failed', + contentLength: 'Execution failed'.length, }); }); @@ -246,6 +253,7 @@ describe('executeToolCall', () => { error: new Error('Something went very wrong'), errorType: ToolErrorType.UNHANDLED_EXCEPTION, resultDisplay: 'Something went very wrong', + contentLength: 'Something went very wrong'.length, responseParts: [ { functionResponse: { @@ -288,6 +296,7 @@ describe('executeToolCall', () => { errorType: undefined, outputFile: undefined, resultDisplay: 'Image processed', + contentLength: undefined, responseParts: [ { functionResponse: { @@ -302,4 +311,56 @@ describe('executeToolCall', () => { ], }); }); + + it('should calculate contentLength for a string llmContent', async () => { + const request: ToolCallRequestInfo = { + callId: 'call7', + name: 'testTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-id-7', + }; + const toolResult: ToolResult = { + llmContent: 'This is a test string.', + returnDisplay: 'String returned', + }; + vi.mocked(mockToolRegistry.getTool).mockReturnValue(mockTool); + mockTool.executeFn.mockReturnValue(toolResult); + + const response = await executeToolCall( + mockConfig, + request, + abortController.signal, + ); + + expect(response.contentLength).toBe( + typeof toolResult.llmContent === 'string' + ? toolResult.llmContent.length + : undefined, + ); + }); + + it('should have undefined contentLength for array llmContent with no string parts', async () => { + const request: ToolCallRequestInfo = { + callId: 'call8', + name: 'testTool', + args: {}, + isClientInitiated: false, + prompt_id: 'prompt-id-8', + }; + const toolResult: ToolResult = { + llmContent: [{ inlineData: { mimeType: 'image/png', data: 'fakedata' } }], + returnDisplay: 'Image data returned', + }; + vi.mocked(mockToolRegistry.getTool).mockReturnValue(mockTool); + mockTool.executeFn.mockReturnValue(toolResult); + + const response = await executeToolCall( + mockConfig, + request, + abortController.signal, + ); + + expect(response.contentLength).toBeUndefined(); + }); }); diff --git a/packages/core/src/core/turn.ts b/packages/core/src/core/turn.ts index 5ca3ee05cc..66e7801448 100644 --- a/packages/core/src/core/turn.ts +++ b/packages/core/src/core/turn.ts @@ -92,6 +92,7 @@ export interface ToolCallResponseInfo { error: Error | undefined; errorType: ToolErrorType | undefined; outputFile?: string | undefined; + contentLength?: number; } export interface ServerToolCallConfirmationDetails { diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts index 7cd25e8cf8..ec2120ba2d 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts @@ -25,6 +25,7 @@ import type { ContentRetryEvent, ContentRetryFailureEvent, ExtensionInstallEvent, + ToolOutputTruncatedEvent, } from '../types.js'; import { EventMetadataKey } from './event-metadata-key.js'; import type { Config } from '../../config/config.js'; @@ -58,6 +59,7 @@ export enum EventNames { CONTENT_RETRY = 'content_retry', CONTENT_RETRY_FAILURE = 'content_retry_failure', EXTENSION_INSTALL = 'extension_install', + TOOL_OUTPUT_TRUNCATED = 'tool_output_truncated', } export interface LogResponse { @@ -464,6 +466,10 @@ export class ClearcutLogger { gemini_cli_key: EventMetadataKey.GEMINI_CLI_TOOL_TYPE, value: JSON.stringify(event.tool_type), }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_TOOL_CALL_CONTENT_LENGTH, + value: JSON.stringify(event.content_length), + }, ]; if (event.metadata) { @@ -861,6 +867,39 @@ export class ClearcutLogger { this.flushIfNeeded(); } + logToolOutputTruncatedEvent(event: ToolOutputTruncatedEvent): void { + const data: EventValue[] = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_TOOL_CALL_NAME, + value: JSON.stringify(event.tool_name), + }, + { + gemini_cli_key: + EventMetadataKey.GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_ORIGINAL_LENGTH, + value: JSON.stringify(event.original_content_length), + }, + { + gemini_cli_key: + EventMetadataKey.GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_TRUNCATED_LENGTH, + value: JSON.stringify(event.truncated_content_length), + }, + { + gemini_cli_key: + EventMetadataKey.GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_THRESHOLD, + value: JSON.stringify(event.threshold), + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_LINES, + value: JSON.stringify(event.lines), + }, + ]; + + this.enqueueLogEvent( + this.createLogEvent(EventNames.TOOL_OUTPUT_TRUNCATED, data), + ); + this.flushIfNeeded(); + } + /** * Adds default fields to data, and returns a new data array. This fields * should exist on all log events. diff --git a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts index 2351c085ed..4a15d6e294 100644 --- a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts +++ b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts @@ -77,6 +77,9 @@ export enum EventMetadataKey { // Logs the tool call error type, if any. GEMINI_CLI_TOOL_CALL_ERROR_TYPE = 19, + // Logs the length of tool output + GEMINI_CLI_TOOL_CALL_CONTENT_LENGTH = 93, + // ========================================================================== // GenAI API Request Event Keys // =========================================================================== @@ -347,4 +350,20 @@ export enum EventMetadataKey { // Logs the status of the extension install. GEMINI_CLI_EXTENSION_INSTALL_STATUS = 88, + + // ========================================================================== + // Tool Output Truncated Event Keys + // =========================================================================== + + // Logs the original length of the tool output. + GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_ORIGINAL_LENGTH = 89, + + // Logs the truncated length of the tool output. + GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_TRUNCATED_LENGTH = 90, + + // Logs the threshold at which the tool output was truncated. + GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_THRESHOLD = 91, + + // Logs the number of lines the tool output was truncated to. + GEMINI_CLI_TOOL_OUTPUT_TRUNCATED_LINES = 92, } diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index f0953d9d1a..01317afcce 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -30,6 +30,7 @@ export { logConversationFinishedEvent, logKittySequenceOverflow, logChatCompression, + logToolOutputTruncated, } from './loggers.js'; export type { SlashCommandEvent, ChatCompressionEvent } from './types.js'; export { @@ -44,6 +45,7 @@ export { ToolCallEvent, ConversationFinishedEvent, KittySequenceOverflowEvent, + ToolOutputTruncatedEvent, } from './types.js'; export { makeSlashCommandEvent, makeChatCompressionEvent } from './types.js'; export type { TelemetryEvent } from './types.js'; diff --git a/packages/core/src/telemetry/loggers.test.ts b/packages/core/src/telemetry/loggers.test.ts index 817f5fda37..77c9f219e9 100644 --- a/packages/core/src/telemetry/loggers.test.ts +++ b/packages/core/src/telemetry/loggers.test.ts @@ -44,6 +44,7 @@ import { logMalformedJsonResponse, logFileOperation, logRipgrepFallback, + logToolOutputTruncated, } from './loggers.js'; import { ToolCallDecision } from './tool-call-decision.js'; import { @@ -57,6 +58,7 @@ import { MalformedJsonResponseEvent, makeChatCompressionEvent, FileOperationEvent, + ToolOutputTruncatedEvent, } from './types.js'; import * as metrics from './metrics.js'; import { FileOperation } from './metrics.js'; @@ -601,6 +603,7 @@ describe('loggers', () => { }, error: undefined, errorType: undefined, + contentLength: 13, }, tool, invocation: {} as AnyToolInvocation, @@ -634,6 +637,7 @@ describe('loggers', () => { tool_type: 'native', error: undefined, error_type: undefined, + metadata: { model_added_lines: 1, model_removed_lines: 2, @@ -644,6 +648,7 @@ describe('loggers', () => { user_added_chars: 7, user_removed_chars: 8, }, + content_length: 13, }, }); @@ -681,6 +686,7 @@ describe('loggers', () => { resultDisplay: undefined, error: undefined, errorType: undefined, + contentLength: undefined, }, durationMs: 100, outcome: ToolConfirmationOutcome.Cancel, @@ -713,6 +719,7 @@ describe('loggers', () => { error: undefined, error_type: undefined, metadata: undefined, + content_length: undefined, }, }); @@ -751,6 +758,7 @@ describe('loggers', () => { resultDisplay: undefined, error: undefined, errorType: undefined, + contentLength: 13, }, outcome: ToolConfirmationOutcome.ModifyWithEditor, tool: new EditTool(mockConfig), @@ -785,6 +793,7 @@ describe('loggers', () => { error: undefined, error_type: undefined, metadata: undefined, + content_length: 13, }, }); @@ -823,6 +832,7 @@ describe('loggers', () => { resultDisplay: undefined, error: undefined, errorType: undefined, + contentLength: 13, }, tool: new EditTool(mockConfig), invocation: {} as AnyToolInvocation, @@ -856,6 +866,7 @@ describe('loggers', () => { error: undefined, error_type: undefined, metadata: undefined, + content_length: 13, }, }); @@ -876,6 +887,7 @@ describe('loggers', () => { }); it('should log a failed tool call with an error', () => { + const errorMessage = 'test-error'; const call: ErroredToolCall = { status: 'error', request: { @@ -892,11 +904,9 @@ describe('loggers', () => { callId: 'test-call-id', responseParts: [{ text: 'test-response' }], resultDisplay: undefined, - error: { - name: 'test-error-type', - message: 'test-error', - }, + error: new Error(errorMessage), errorType: ToolErrorType.UNKNOWN, + contentLength: errorMessage.length, }, durationMs: 100, }; @@ -930,6 +940,7 @@ describe('loggers', () => { tool_type: 'native', decision: undefined, metadata: undefined, + content_length: errorMessage.length, }, }); @@ -1035,4 +1046,40 @@ describe('loggers', () => { ); }); }); + + describe('logToolOutputTruncated', () => { + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + } as unknown as Config; + + it('should log a tool output truncated event', () => { + const event = new ToolOutputTruncatedEvent('prompt-id-1', { + toolName: 'test-tool', + originalContentLength: 1000, + truncatedContentLength: 100, + threshold: 500, + lines: 10, + }); + + logToolOutputTruncated(mockConfig, event); + + expect(mockLogger.emit).toHaveBeenCalledWith({ + body: 'Tool output truncated for test-tool.', + attributes: { + 'session.id': 'test-session-id', + 'user.email': 'test-user@example.com', + 'event.name': 'tool_output_truncated', + 'event.timestamp': '2025-01-01T00:00:00.000Z', + eventName: 'tool_output_truncated', + prompt_id: 'prompt-id-1', + tool_name: 'test-tool', + original_content_length: 1000, + truncated_content_length: 100, + threshold: 500, + lines: 10, + }, + }); + }); + }); }); diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index 30f8e8d6bc..6b8e503fa7 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -50,6 +50,7 @@ import type { ContentRetryEvent, ContentRetryFailureEvent, RipgrepFallbackEvent, + ToolOutputTruncatedEvent, } from './types.js'; import { recordApiErrorMetrics, @@ -185,6 +186,28 @@ export function logToolCall(config: Config, event: ToolCallEvent): void { ); } +export function logToolOutputTruncated( + config: Config, + event: ToolOutputTruncatedEvent, +): void { + ClearcutLogger.getInstance(config)?.logToolOutputTruncatedEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': 'tool_output_truncated', + 'event.timestamp': new Date().toISOString(), + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `Tool output truncated for ${event.tool_name}.`, + attributes, + }; + logger.emit(logRecord); +} + export function logFileOperation( config: Config, event: FileOperationEvent, diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index bdc48bbef7..8d24d71c11 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -136,6 +136,7 @@ export class ToolCallEvent implements BaseTelemetryEvent { error_type?: string; prompt_id: string; tool_type: 'native' | 'mcp'; + content_length?: number; // eslint-disable-next-line @typescript-eslint/no-explicit-any metadata?: { [key: string]: any }; @@ -156,6 +157,7 @@ export class ToolCallEvent implements BaseTelemetryEvent { typeof call.tool !== 'undefined' && call.tool instanceof DiscoveredMCPTool ? 'mcp' : 'native'; + this.content_length = call.response.contentLength; if ( call.status === 'success' && @@ -535,7 +537,8 @@ export type TelemetryEvent = | InvalidChunkEvent | ContentRetryEvent | ContentRetryFailureEvent - | ExtensionInstallEvent; + | ExtensionInstallEvent + | ToolOutputTruncatedEvent; export class ExtensionInstallEvent implements BaseTelemetryEvent { 'event.name': 'extension_install'; @@ -559,3 +562,34 @@ export class ExtensionInstallEvent implements BaseTelemetryEvent { this.status = status; } } + +export class ToolOutputTruncatedEvent implements BaseTelemetryEvent { + readonly eventName = 'tool_output_truncated'; + readonly 'event.timestamp' = new Date().toISOString(); + 'event.name': string; + tool_name: string; + original_content_length: number; + truncated_content_length: number; + threshold: number; + lines: number; + prompt_id: string; + + constructor( + prompt_id: string, + details: { + toolName: string; + originalContentLength: number; + truncatedContentLength: number; + threshold: number; + lines: number; + }, + ) { + this['event.name'] = this.eventName; + this.prompt_id = prompt_id; + this.tool_name = details.toolName; + this.original_content_length = details.originalContentLength; + this.truncated_content_length = details.truncatedContentLength; + this.threshold = details.threshold; + this.lines = details.lines; + } +}