/** * @license * Copyright 2025 Google LLC * SPDX-License-Identifier: Apache-2.0 */ import { AnyToolInvocation, AuthType, CompletedToolCall, ContentGeneratorConfig, EditTool, ErroredToolCall, GeminiClient, ToolConfirmationOutcome, ToolErrorType, ToolRegistry, } from '../index.js'; import { logs } from '@opentelemetry/api-logs'; import { SemanticAttributes } from '@opentelemetry/semantic-conventions'; import { Config } from '../config/config.js'; import { EVENT_API_REQUEST, EVENT_API_RESPONSE, EVENT_CLI_CONFIG, EVENT_TOOL_CALL, EVENT_USER_PROMPT, EVENT_FLASH_FALLBACK, } from './constants.js'; import { logApiRequest, logApiResponse, logCliConfiguration, logUserPrompt, logToolCall, logFlashFallback, } from './loggers.js'; import { ToolCallDecision } from './tool-call-decision.js'; import { ApiRequestEvent, ApiResponseEvent, StartSessionEvent, ToolCallEvent, UserPromptEvent, FlashFallbackEvent, } from './types.js'; import * as metrics from './metrics.js'; import * as sdk from './sdk.js'; import { vi, describe, beforeEach, it, expect } from 'vitest'; import { GenerateContentResponseUsageMetadata } from '@google/genai'; import * as uiTelemetry from './uiTelemetry.js'; describe('loggers', () => { const mockLogger = { emit: vi.fn(), }; const mockUiEvent = { addEvent: vi.fn(), }; beforeEach(() => { vi.spyOn(sdk, 'isTelemetrySdkInitialized').mockReturnValue(true); vi.spyOn(logs, 'getLogger').mockReturnValue(mockLogger); vi.spyOn(uiTelemetry.uiTelemetryService, 'addEvent').mockImplementation( mockUiEvent.addEvent, ); vi.useFakeTimers(); vi.setSystemTime(new Date('2025-01-01T00:00:00.000Z')); }); describe('logCliConfiguration', () => { it('should log the cli configuration', () => { const mockConfig = { getSessionId: () => 'test-session-id', getModel: () => 'test-model', getEmbeddingModel: () => 'test-embedding-model', getSandbox: () => true, getCoreTools: () => ['ls', 'read-file'], getApprovalMode: () => 'default', getContentGeneratorConfig: () => ({ model: 'test-model', apiKey: 'test-api-key', authType: AuthType.USE_VERTEX_AI, }), getTelemetryEnabled: () => true, getUsageStatisticsEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, getFileFilteringRespectGitIgnore: () => true, getFileFilteringAllowBuildArtifacts: () => false, getDebugMode: () => true, getMcpServers: () => ({ 'test-server': { command: 'test-command', }, }), getQuestion: () => 'test-question', getTargetDir: () => 'target-dir', getProxy: () => 'http://test.proxy.com:8080', } as unknown as Config; const startSessionEvent = new StartSessionEvent(mockConfig); logCliConfiguration(mockConfig, startSessionEvent); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'CLI configuration loaded.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_CLI_CONFIG, 'event.timestamp': '2025-01-01T00:00:00.000Z', model: 'test-model', embedding_model: 'test-embedding-model', sandbox_enabled: true, core_tools_enabled: 'ls,read-file', approval_mode: 'default', api_key_enabled: true, vertex_ai_enabled: true, log_user_prompts_enabled: true, file_filtering_respect_git_ignore: true, debug_mode: true, mcp_servers: 'test-server', }, }); }); }); describe('logUserPrompt', () => { const mockConfig = { getSessionId: () => 'test-session-id', getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, getUsageStatisticsEnabled: () => true, } as unknown as Config; it('should log a user prompt', () => { const event = new UserPromptEvent( 11, 'prompt-id-8', AuthType.USE_VERTEX_AI, 'test-prompt', ); logUserPrompt(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'User prompt. Length: 11.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_USER_PROMPT, 'event.timestamp': '2025-01-01T00:00:00.000Z', prompt_length: 11, prompt: 'test-prompt', }, }); }); it('should not log prompt if disabled', () => { const mockConfig = { getSessionId: () => 'test-session-id', getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => false, getTargetDir: () => 'target-dir', getUsageStatisticsEnabled: () => true, } as unknown as Config; const event = new UserPromptEvent( 11, 'test-prompt', AuthType.CLOUD_SHELL, ); logUserPrompt(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'User prompt. Length: 11.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_USER_PROMPT, 'event.timestamp': '2025-01-01T00:00:00.000Z', prompt_length: 11, }, }); }); }); describe('logApiResponse', () => { const mockConfig = { getSessionId: () => 'test-session-id', getTargetDir: () => 'target-dir', getUsageStatisticsEnabled: () => true, getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, } as Config; const mockMetrics = { recordApiResponseMetrics: vi.fn(), recordTokenUsageMetrics: vi.fn(), }; beforeEach(() => { vi.spyOn(metrics, 'recordApiResponseMetrics').mockImplementation( mockMetrics.recordApiResponseMetrics, ); vi.spyOn(metrics, 'recordTokenUsageMetrics').mockImplementation( mockMetrics.recordTokenUsageMetrics, ); }); it('should log an API response with all fields', () => { const usageData: GenerateContentResponseUsageMetadata = { promptTokenCount: 17, candidatesTokenCount: 50, cachedContentTokenCount: 10, thoughtsTokenCount: 5, toolUsePromptTokenCount: 2, }; const event = new ApiResponseEvent( 'test-model', 100, 'prompt-id-1', AuthType.LOGIN_WITH_GOOGLE, usageData, 'test-response', ); logApiResponse(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'API response from test-model. Status: 200. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_API_RESPONSE, 'event.timestamp': '2025-01-01T00:00:00.000Z', [SemanticAttributes.HTTP_STATUS_CODE]: 200, model: 'test-model', status_code: 200, duration_ms: 100, input_token_count: 17, output_token_count: 50, cached_content_token_count: 10, thoughts_token_count: 5, tool_token_count: 2, total_token_count: 0, response_text: 'test-response', prompt_id: 'prompt-id-1', auth_type: 'oauth-personal', }, }); expect(mockMetrics.recordApiResponseMetrics).toHaveBeenCalledWith( mockConfig, 'test-model', 100, 200, undefined, ); expect(mockMetrics.recordTokenUsageMetrics).toHaveBeenCalledWith( mockConfig, 'test-model', 50, 'output', ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_API_RESPONSE, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); it('should log an API response with an error', () => { const usageData: GenerateContentResponseUsageMetadata = { promptTokenCount: 17, candidatesTokenCount: 50, cachedContentTokenCount: 10, thoughtsTokenCount: 5, toolUsePromptTokenCount: 2, }; const event = new ApiResponseEvent( 'test-model', 100, 'prompt-id-1', AuthType.USE_GEMINI, usageData, 'test-response', 'test-error', ); logApiResponse(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'API response from test-model. Status: 200. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', ...event, 'event.name': EVENT_API_RESPONSE, 'event.timestamp': '2025-01-01T00:00:00.000Z', 'error.message': 'test-error', }, }); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_API_RESPONSE, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); }); describe('logApiRequest', () => { const mockConfig = { getSessionId: () => 'test-session-id', getTargetDir: () => 'target-dir', getUsageStatisticsEnabled: () => true, getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, } as Config; it('should log an API request with request_text', () => { const event = new ApiRequestEvent( 'test-model', 'prompt-id-7', 'This is a test request', ); logApiRequest(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'API request to test-model.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_API_REQUEST, 'event.timestamp': '2025-01-01T00:00:00.000Z', model: 'test-model', request_text: 'This is a test request', prompt_id: 'prompt-id-7', }, }); }); it('should log an API request without request_text', () => { const event = new ApiRequestEvent('test-model', 'prompt-id-6'); logApiRequest(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'API request to test-model.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_API_REQUEST, 'event.timestamp': '2025-01-01T00:00:00.000Z', model: 'test-model', prompt_id: 'prompt-id-6', }, }); }); }); describe('logFlashFallback', () => { const mockConfig = { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, } as unknown as Config; it('should log flash fallback event', () => { const event = new FlashFallbackEvent(AuthType.USE_VERTEX_AI); logFlashFallback(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Switching to flash as Fallback.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_FLASH_FALLBACK, 'event.timestamp': '2025-01-01T00:00:00.000Z', auth_type: 'vertex-ai', }, }); }); }); describe('logToolCall', () => { const cfg1 = { getSessionId: () => 'test-session-id', getTargetDir: () => 'target-dir', getGeminiClient: () => mockGeminiClient, } as Config; const cfg2 = { getSessionId: () => 'test-session-id', getTargetDir: () => 'target-dir', getProxy: () => 'http://test.proxy.com:8080', getContentGeneratorConfig: () => ({ model: 'test-model' }) as ContentGeneratorConfig, getModel: () => 'test-model', getEmbeddingModel: () => 'test-embedding-model', getWorkingDir: () => 'test-working-dir', getSandbox: () => true, getCoreTools: () => ['ls', 'read-file'], getApprovalMode: () => 'default', getTelemetryLogPromptsEnabled: () => true, getFileFilteringRespectGitIgnore: () => true, getFileFilteringAllowBuildArtifacts: () => false, getDebugMode: () => true, getMcpServers: () => ({ 'test-server': { command: 'test-command', }, }), getQuestion: () => 'test-question', getToolRegistry: () => new ToolRegistry(cfg1), getFullContext: () => false, getUserMemory: () => 'user-memory', } as unknown as Config; const mockGeminiClient = new GeminiClient(cfg2); const mockConfig = { getSessionId: () => 'test-session-id', getTargetDir: () => 'target-dir', getGeminiClient: () => mockGeminiClient, getUsageStatisticsEnabled: () => true, getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, } as Config; const mockMetrics = { recordToolCallMetrics: vi.fn(), }; beforeEach(() => { vi.spyOn(metrics, 'recordToolCallMetrics').mockImplementation( mockMetrics.recordToolCallMetrics, ); mockLogger.emit.mockReset(); }); it('should log a tool call with all fields', () => { const tool = new EditTool(mockConfig); const call: CompletedToolCall = { status: 'success', request: { name: 'test-function', args: { arg1: 'value1', arg2: 2, }, callId: 'test-call-id', isClientInitiated: true, prompt_id: 'prompt-id-1', }, response: { callId: 'test-call-id', responseParts: 'test-response', resultDisplay: undefined, error: undefined, errorType: undefined, }, tool, invocation: {} as AnyToolInvocation, durationMs: 100, outcome: ToolConfirmationOutcome.ProceedOnce, }; const event = new ToolCallEvent(call); logToolCall(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Tool call: test-function. Decision: accept. Success: true. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', function_name: 'test-function', function_args: JSON.stringify( { arg1: 'value1', arg2: 2, }, null, 2, ), duration_ms: 100, success: true, decision: ToolCallDecision.ACCEPT, prompt_id: 'prompt-id-1', }, }); expect(mockMetrics.recordToolCallMetrics).toHaveBeenCalledWith( mockConfig, 'test-function', 100, true, ToolCallDecision.ACCEPT, ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); it('should log a tool call with a reject decision', () => { const call: ErroredToolCall = { status: 'error', request: { name: 'test-function', args: { arg1: 'value1', arg2: 2, }, callId: 'test-call-id', isClientInitiated: true, prompt_id: 'prompt-id-2', }, response: { callId: 'test-call-id', responseParts: 'test-response', resultDisplay: undefined, error: undefined, errorType: undefined, }, durationMs: 100, outcome: ToolConfirmationOutcome.Cancel, }; const event = new ToolCallEvent(call); logToolCall(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Tool call: test-function. Decision: reject. Success: false. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', function_name: 'test-function', function_args: JSON.stringify( { arg1: 'value1', arg2: 2, }, null, 2, ), duration_ms: 100, success: false, decision: ToolCallDecision.REJECT, prompt_id: 'prompt-id-2', }, }); expect(mockMetrics.recordToolCallMetrics).toHaveBeenCalledWith( mockConfig, 'test-function', 100, false, ToolCallDecision.REJECT, ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); it('should log a tool call with a modify decision', () => { const call: CompletedToolCall = { status: 'success', request: { name: 'test-function', args: { arg1: 'value1', arg2: 2, }, callId: 'test-call-id', isClientInitiated: true, prompt_id: 'prompt-id-3', }, response: { callId: 'test-call-id', responseParts: 'test-response', resultDisplay: undefined, error: undefined, errorType: undefined, }, outcome: ToolConfirmationOutcome.ModifyWithEditor, tool: new EditTool(mockConfig), invocation: {} as AnyToolInvocation, durationMs: 100, }; const event = new ToolCallEvent(call); logToolCall(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Tool call: test-function. Decision: modify. Success: true. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', function_name: 'test-function', function_args: JSON.stringify( { arg1: 'value1', arg2: 2, }, null, 2, ), duration_ms: 100, success: true, decision: ToolCallDecision.MODIFY, prompt_id: 'prompt-id-3', }, }); expect(mockMetrics.recordToolCallMetrics).toHaveBeenCalledWith( mockConfig, 'test-function', 100, true, ToolCallDecision.MODIFY, ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); it('should log a tool call without a decision', () => { const call: CompletedToolCall = { status: 'success', request: { name: 'test-function', args: { arg1: 'value1', arg2: 2, }, callId: 'test-call-id', isClientInitiated: true, prompt_id: 'prompt-id-4', }, response: { callId: 'test-call-id', responseParts: 'test-response', resultDisplay: undefined, error: undefined, errorType: undefined, }, tool: new EditTool(mockConfig), invocation: {} as AnyToolInvocation, durationMs: 100, }; const event = new ToolCallEvent(call); logToolCall(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Tool call: test-function. Success: true. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', function_name: 'test-function', function_args: JSON.stringify( { arg1: 'value1', arg2: 2, }, null, 2, ), duration_ms: 100, success: true, prompt_id: 'prompt-id-4', }, }); expect(mockMetrics.recordToolCallMetrics).toHaveBeenCalledWith( mockConfig, 'test-function', 100, true, undefined, ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); it('should log a failed tool call with an error', () => { const call: ErroredToolCall = { status: 'error', request: { name: 'test-function', args: { arg1: 'value1', arg2: 2, }, callId: 'test-call-id', isClientInitiated: true, prompt_id: 'prompt-id-5', }, response: { callId: 'test-call-id', responseParts: 'test-response', resultDisplay: undefined, error: { name: 'test-error-type', message: 'test-error', }, errorType: ToolErrorType.UNKNOWN, }, durationMs: 100, }; const event = new ToolCallEvent(call); logToolCall(mockConfig, event); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'Tool call: test-function. Success: false. Duration: 100ms.', attributes: { 'session.id': 'test-session-id', 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', function_name: 'test-function', function_args: JSON.stringify( { arg1: 'value1', arg2: 2, }, null, 2, ), duration_ms: 100, success: false, error: 'test-error', 'error.message': 'test-error', error_type: ToolErrorType.UNKNOWN, 'error.type': ToolErrorType.UNKNOWN, prompt_id: 'prompt-id-5', }, }); expect(mockMetrics.recordToolCallMetrics).toHaveBeenCalledWith( mockConfig, 'test-function', 100, false, undefined, ); expect(mockUiEvent.addEvent).toHaveBeenCalledWith({ ...event, 'event.name': EVENT_TOOL_CALL, 'event.timestamp': '2025-01-01T00:00:00.000Z', }); }); }); });