From c0552ceb2274f9f5e53bf37eb6ead2b2ab388cc2 Mon Sep 17 00:00:00 2001 From: Abhi <43648792+abhipatel12@users.noreply.github.com> Date: Wed, 8 Oct 2025 15:42:33 -0400 Subject: [PATCH] feat(core): add telemetry for subagent execution (#10456) --- packages/core/src/agents/executor.test.ts | 121 +++++++++++++++++- packages/core/src/agents/executor.ts | 45 +++++-- .../clearcut-logger/clearcut-logger.test.ts | 84 ++++++++++++ .../clearcut-logger/clearcut-logger.ts | 48 +++++++ .../clearcut-logger/event-metadata-key.ts | 19 +++ packages/core/src/telemetry/constants.ts | 4 + packages/core/src/telemetry/loggers.test.ts | 88 +++++++++++++ packages/core/src/telemetry/loggers.ts | 43 +++++++ packages/core/src/telemetry/metrics.test.ts | 59 ++++++++- packages/core/src/telemetry/metrics.ts | 72 ++++++++++- packages/core/src/telemetry/types.ts | 45 ++++++- 11 files changed, 608 insertions(+), 20 deletions(-) diff --git a/packages/core/src/agents/executor.test.ts b/packages/core/src/agents/executor.test.ts index ba186e5bb5..e4f442c5f3 100644 --- a/packages/core/src/agents/executor.test.ts +++ b/packages/core/src/agents/executor.test.ts @@ -6,13 +6,6 @@ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { AgentExecutor, type ActivityCallback } from './executor.js'; -import type { - AgentDefinition, - AgentInputs, - SubagentActivityEvent, - OutputConfig, -} from './types.js'; -import { AgentTerminateMode } from './types.js'; import { makeFakeConfig } from '../test-utils/config.js'; import { ToolRegistry } from '../tools/tool-registry.js'; import { LSTool } from '../tools/ls.js'; @@ -32,6 +25,16 @@ import type { Config } from '../config/config.js'; import { MockTool } from '../test-utils/mock-tool.js'; import { getDirectoryContextString } from '../utils/environmentContext.js'; import { z } from 'zod'; +import { promptIdContext } from '../utils/promptIdContext.js'; +import { logAgentStart, logAgentFinish } from '../telemetry/loggers.js'; +import { AgentStartEvent, AgentFinishEvent } from '../telemetry/types.js'; +import type { + AgentDefinition, + AgentInputs, + SubagentActivityEvent, + OutputConfig, +} from './types.js'; +import { AgentTerminateMode } from './types.js'; const { mockSendMessageStream, mockExecuteToolCall } = vi.hoisted(() => ({ mockSendMessageStream: vi.fn(), @@ -54,8 +57,29 @@ vi.mock('../core/nonInteractiveToolExecutor.js', () => ({ vi.mock('../utils/environmentContext.js'); +vi.mock('../telemetry/loggers.js', () => ({ + logAgentStart: vi.fn(), + logAgentFinish: vi.fn(), +})); + +vi.mock('../utils/promptIdContext.js', async (importOriginal) => { + const actual = + await importOriginal(); + return { + ...actual, + promptIdContext: { + ...actual.promptIdContext, + getStore: vi.fn(), + run: vi.fn((_id, fn) => fn()), + }, + }; +}); + const MockedGeminiChat = vi.mocked(GeminiChat); const mockedGetDirectoryContextString = vi.mocked(getDirectoryContextString); +const mockedPromptIdContext = vi.mocked(promptIdContext); +const mockedLogAgentStart = vi.mocked(logAgentStart); +const mockedLogAgentFinish = vi.mocked(logAgentFinish); // Constants for testing const TASK_COMPLETE_TOOL_NAME = 'complete_task'; @@ -160,6 +184,10 @@ describe('AgentExecutor', () => { vi.resetAllMocks(); mockSendMessageStream.mockReset(); mockExecuteToolCall.mockReset(); + mockedLogAgentStart.mockReset(); + mockedLogAgentFinish.mockReset(); + mockedPromptIdContext.getStore.mockReset(); + mockedPromptIdContext.run.mockImplementation((_id, fn) => fn()); MockedGeminiChat.mockImplementation( () => @@ -229,9 +257,52 @@ describe('AgentExecutor', () => { expect(agentRegistry.getAllToolNames()).toHaveLength(2); expect(agentRegistry.getTool(MOCK_TOOL_NOT_ALLOWED.name)).toBeUndefined(); }); + + it('should use parentPromptId from context to create agentId', async () => { + const parentId = 'parent-id'; + mockedPromptIdContext.getStore.mockReturnValue(parentId); + + const definition = createTestDefinition(); + const executor = await AgentExecutor.create( + definition, + mockConfig, + onActivity, + ); + + expect(executor['agentId']).toMatch( + new RegExp(`^${parentId}-${definition.name}-`), + ); + }); }); describe('run (Execution Loop and Logic)', () => { + it('should log AgentFinish with error if run throws', async () => { + const definition = createTestDefinition(); + // Make the definition invalid to cause an error during run + definition.inputConfig.inputs = { + goal: { type: 'string', required: true, description: 'goal' }, + }; + const executor = await AgentExecutor.create( + definition, + mockConfig, + onActivity, + ); + + // Run without inputs to trigger validation error + await expect(executor.run({}, signal)).rejects.toThrow( + /Missing required input parameters/, + ); + + expect(mockedLogAgentStart).toHaveBeenCalledTimes(1); + expect(mockedLogAgentFinish).toHaveBeenCalledTimes(1); + expect(mockedLogAgentFinish).toHaveBeenCalledWith( + mockConfig, + expect.objectContaining({ + terminate_reason: AgentTerminateMode.ERROR, + }), + ); + }); + it('should execute successfully when model calls complete_task with output (Happy Path with Output)', async () => { const definition = createTestDefinition(); const executor = await AgentExecutor.create( @@ -312,6 +383,34 @@ describe('AgentExecutor', () => { expect(output.result).toBe('Found file1.txt'); expect(output.terminate_reason).toBe(AgentTerminateMode.GOAL); + // Telemetry checks + expect(mockedLogAgentStart).toHaveBeenCalledTimes(1); + expect(mockedLogAgentStart).toHaveBeenCalledWith( + mockConfig, + expect.any(AgentStartEvent), + ); + expect(mockedLogAgentFinish).toHaveBeenCalledTimes(1); + expect(mockedLogAgentFinish).toHaveBeenCalledWith( + mockConfig, + expect.any(AgentFinishEvent), + ); + const finishEvent = mockedLogAgentFinish.mock.calls[0][1]; + expect(finishEvent.terminate_reason).toBe(AgentTerminateMode.GOAL); + + // Context checks + expect(mockedPromptIdContext.run).toHaveBeenCalledTimes(2); // Two turns + const agentId = executor['agentId']; + expect(mockedPromptIdContext.run).toHaveBeenNthCalledWith( + 1, + `${agentId}#0`, + expect.any(Function), + ); + expect(mockedPromptIdContext.run).toHaveBeenNthCalledWith( + 2, + `${agentId}#1`, + expect.any(Function), + ); + expect(activities).toEqual( expect.arrayContaining([ expect.objectContaining({ @@ -425,6 +524,14 @@ describe('AgentExecutor', () => { expect(output.terminate_reason).toBe(AgentTerminateMode.ERROR); expect(output.result).toBe(expectedError); + // Telemetry check for error + expect(mockedLogAgentFinish).toHaveBeenCalledWith( + mockConfig, + expect.objectContaining({ + terminate_reason: AgentTerminateMode.ERROR, + }), + ); + expect(activities).toContainEqual( expect.objectContaining({ type: 'ERROR', diff --git a/packages/core/src/agents/executor.ts b/packages/core/src/agents/executor.ts index 2ba2dc88c2..32aea912b1 100644 --- a/packages/core/src/agents/executor.ts +++ b/packages/core/src/agents/executor.ts @@ -28,6 +28,9 @@ import { MemoryTool } from '../tools/memoryTool.js'; import { ReadFileTool } from '../tools/read-file.js'; import { ReadManyFilesTool } from '../tools/read-many-files.js'; import { WebSearchTool } from '../tools/web-search.js'; +import { promptIdContext } from '../utils/promptIdContext.js'; +import { logAgentStart, logAgentFinish } from '../telemetry/loggers.js'; +import { AgentStartEvent, AgentFinishEvent } from '../telemetry/types.js'; import type { AgentDefinition, AgentInputs, @@ -104,10 +107,14 @@ export class AgentExecutor { await AgentExecutor.validateTools(agentToolRegistry, definition.name); } + // Get the parent prompt ID from context + const parentPromptId = promptIdContext.getStore(); + return new AgentExecutor( definition, runtimeContext, agentToolRegistry, + parentPromptId, onActivity, ); } @@ -122,6 +129,7 @@ export class AgentExecutor { definition: AgentDefinition, runtimeContext: Config, toolRegistry: ToolRegistry, + parentPromptId: string | undefined, onActivity?: ActivityCallback, ) { this.definition = definition; @@ -130,7 +138,10 @@ export class AgentExecutor { this.onActivity = onActivity; const randomIdPart = Math.random().toString(36).slice(2, 8); - this.agentId = `${this.definition.name}-${randomIdPart}`; + // parentPromptId will be undefined if this agent is invoked directly + // (top-level), rather than as a sub-agent. + const parentPrefix = parentPromptId ? `${parentPromptId}-` : ''; + this.agentId = `${parentPrefix}${this.definition.name}-${randomIdPart}`; } /** @@ -143,12 +154,17 @@ export class AgentExecutor { async run(inputs: AgentInputs, signal: AbortSignal): Promise { const startTime = Date.now(); let turnCounter = 0; + let terminateReason: AgentTerminateMode = AgentTerminateMode.ERROR; + let finalResult: string | null = null; + + logAgentStart( + this.runtimeContext, + new AgentStartEvent(this.agentId, this.definition.name), + ); try { const chat = await this.createChatObject(inputs); const tools = this.prepareToolsList(); - let terminateReason = AgentTerminateMode.ERROR; - let finalResult: string | null = null; const query = this.definition.promptConfig.query ? templateString(this.definition.promptConfig.query, inputs) @@ -167,14 +183,12 @@ export class AgentExecutor { break; } - // Call model - const promptId = `${this.runtimeContext.getSessionId()}#${this.agentId}#${turnCounter++}`; - const { functionCalls } = await this.callModel( - chat, - currentMessage, - tools, - signal, + const promptId = `${this.agentId}#${turnCounter++}`; + + const { functionCalls } = await promptIdContext.run( promptId, + async () => + this.callModel(chat, currentMessage, tools, signal, promptId), ); if (signal.aborted) { @@ -220,6 +234,17 @@ export class AgentExecutor { } catch (error) { this.emitActivity('ERROR', { error: String(error) }); throw error; // Re-throw the error for the parent context to handle. + } finally { + logAgentFinish( + this.runtimeContext, + new AgentFinishEvent( + this.agentId, + this.definition.name, + Date.now() - startTime, + turnCounter, + terminateReason, + ), + ); } } diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts index ba9ffa7ce8..28ce2576fb 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts @@ -29,7 +29,10 @@ import { makeChatCompressionEvent, ModelRoutingEvent, ToolCallEvent, + AgentStartEvent, + AgentFinishEvent, } from '../types.js'; +import { AgentTerminateMode } from '../../agents/types.js'; import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js'; import { UserAccountManager } from '../../utils/userAccountManager.js'; import { InstallationManager } from '../../utils/installationManager.js'; @@ -721,6 +724,87 @@ describe('ClearcutLogger', () => { }); }); + describe('logAgentStartEvent', () => { + it('logs an event with proper fields', () => { + const { logger } = setup(); + const event = new AgentStartEvent('agent-123', 'TestAgent'); + + logger?.logAgentStartEvent(event); + + const events = getEvents(logger!); + expect(events.length).toBe(1); + expect(events[0]).toHaveEventName(EventNames.AGENT_START); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_ID, + 'agent-123', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_NAME, + 'TestAgent', + ]); + }); + }); + + describe('logAgentFinishEvent', () => { + it('logs an event with proper fields (success)', () => { + const { logger } = setup(); + const event = new AgentFinishEvent( + 'agent-123', + 'TestAgent', + 1000, + 5, + AgentTerminateMode.GOAL, + ); + + logger?.logAgentFinishEvent(event); + + const events = getEvents(logger!); + expect(events.length).toBe(1); + expect(events[0]).toHaveEventName(EventNames.AGENT_FINISH); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_ID, + 'agent-123', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_NAME, + 'TestAgent', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_DURATION_MS, + '1000', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_TURN_COUNT, + '5', + ]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_TERMINATE_REASON, + 'GOAL', + ]); + }); + + it('logs an event with proper fields (error)', () => { + const { logger } = setup(); + const event = new AgentFinishEvent( + 'agent-123', + 'TestAgent', + 500, + 2, + AgentTerminateMode.ERROR, + ); + + logger?.logAgentFinishEvent(event); + + const events = getEvents(logger!); + expect(events.length).toBe(1); + expect(events[0]).toHaveEventName(EventNames.AGENT_FINISH); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_AGENT_TERMINATE_REASON, + 'ERROR', + ]); + }); + }); + describe('logToolCallEvent', () => { it('logs an event with all diff metadata', () => { const { logger } = setup(); diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts index 355130be7a..5fe283648d 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts @@ -33,6 +33,8 @@ import type { ExtensionDisableEvent, SmartEditStrategyEvent, SmartEditCorrectionEvent, + AgentStartEvent, + AgentFinishEvent, } from '../types.js'; import { EventMetadataKey } from './event-metadata-key.js'; import type { Config } from '../../config/config.js'; @@ -79,6 +81,8 @@ export enum EventNames { MODEL_SLASH_COMMAND = 'model_slash_command', SMART_EDIT_STRATEGY = 'smart_edit_strategy', SMART_EDIT_CORRECTION = 'smart_edit_correction', + AGENT_START = 'agent_start', + AGENT_FINISH = 'agent_finish', } export interface LogResponse { @@ -1063,6 +1067,50 @@ export class ClearcutLogger { this.flushIfNeeded(); } + logAgentStartEvent(event: AgentStartEvent): void { + const data: EventValue[] = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_ID, + value: event.agent_id, + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_NAME, + value: event.agent_name, + }, + ]; + + this.enqueueLogEvent(this.createLogEvent(EventNames.AGENT_START, data)); + this.flushIfNeeded(); + } + + logAgentFinishEvent(event: AgentFinishEvent): void { + const data: EventValue[] = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_ID, + value: event.agent_id, + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_NAME, + value: event.agent_name, + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_DURATION_MS, + value: event.duration_ms.toString(), + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_TURN_COUNT, + value: event.turn_count.toString(), + }, + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_AGENT_TERMINATE_REASON, + value: event.terminate_reason, + }, + ]; + + this.enqueueLogEvent(this.createLogEvent(EventNames.AGENT_FINISH, 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 891cf50737..2e0da3a0c2 100644 --- a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts +++ b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts @@ -426,4 +426,23 @@ export enum EventMetadataKey { // Logs an event when the user uses the /model command. GEMINI_CLI_MODEL_SLASH_COMMAND = 108, + + // ========================================================================== + // Agent Event Keys + // ========================================================================== + + // Logs the name of the agent. + GEMINI_CLI_AGENT_NAME = 111, + + // Logs the unique ID of the agent instance. + GEMINI_CLI_AGENT_ID = 112, + + // Logs the duration of the agent execution in milliseconds. + GEMINI_CLI_AGENT_DURATION_MS = 113, + + // Logs the number of turns the agent took. + GEMINI_CLI_AGENT_TURN_COUNT = 114, + + // Logs the reason for agent termination. + GEMINI_CLI_AGENT_TERMINATE_REASON = 115, } diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index f6fd14ed34..083ecdb677 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -36,6 +36,10 @@ export const EVENT_SMART_EDIT_STRATEGY = 'gemini_cli.smart_edit.strategy'; export const EVENT_MODEL_ROUTING = 'gemini_cli.model_routing'; export const EVENT_SMART_EDIT_CORRECTION = 'gemini_cli.smart_edit.correction'; +// Agent Events +export const EVENT_AGENT_START = 'gemini_cli.agent.start'; +export const EVENT_AGENT_FINISH = 'gemini_cli.agent.finish'; + // Performance Events export const EVENT_STARTUP_PERFORMANCE = 'gemini_cli.startup.performance'; export const EVENT_MEMORY_USAGE = 'gemini_cli.memory.usage'; diff --git a/packages/core/src/telemetry/loggers.test.ts b/packages/core/src/telemetry/loggers.test.ts index 6ec5c4588a..127c6d7e3c 100644 --- a/packages/core/src/telemetry/loggers.test.ts +++ b/packages/core/src/telemetry/loggers.test.ts @@ -38,6 +38,8 @@ import { EVENT_EXTENSION_INSTALL, EVENT_EXTENSION_UNINSTALL, EVENT_TOOL_OUTPUT_TRUNCATED, + EVENT_AGENT_START, + EVENT_AGENT_FINISH, } from './constants.js'; import { logApiRequest, @@ -56,6 +58,8 @@ import { logExtensionDisable, logExtensionInstallEvent, logExtensionUninstall, + logAgentStart, + logAgentFinish, } from './loggers.js'; import { ToolCallDecision } from './tool-call-decision.js'; import { @@ -75,6 +79,8 @@ import { ExtensionDisableEvent, ExtensionInstallEvent, ExtensionUninstallEvent, + AgentStartEvent, + AgentFinishEvent, } from './types.js'; import * as metrics from './metrics.js'; import { @@ -93,6 +99,7 @@ import * as uiTelemetry from './uiTelemetry.js'; import { makeFakeConfig } from '../test-utils/config.js'; import { ClearcutLogger } from './clearcut-logger/clearcut-logger.js'; import { UserAccountManager } from '../utils/userAccountManager.js'; +import { AgentTerminateMode } from '../agents/types.js'; describe('loggers', () => { const mockLogger = { @@ -1406,4 +1413,85 @@ describe('loggers', () => { }); }); }); + + describe('logAgentStart', () => { + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + } as unknown as Config; + + beforeEach(() => { + vi.spyOn(ClearcutLogger.prototype, 'logAgentStartEvent'); + }); + + it('should log agent start event', () => { + const event = new AgentStartEvent('agent-123', 'TestAgent'); + + logAgentStart(mockConfig, event); + + expect(ClearcutLogger.prototype.logAgentStartEvent).toHaveBeenCalledWith( + event, + ); + + expect(mockLogger.emit).toHaveBeenCalledWith({ + body: 'Agent TestAgent started. ID: agent-123', + attributes: { + 'session.id': 'test-session-id', + 'user.email': 'test-user@example.com', + 'event.name': EVENT_AGENT_START, + 'event.timestamp': '2025-01-01T00:00:00.000Z', + agent_id: 'agent-123', + agent_name: 'TestAgent', + }, + }); + }); + }); + + describe('logAgentFinish', () => { + const mockConfig = { + getSessionId: () => 'test-session-id', + getUsageStatisticsEnabled: () => true, + } as unknown as Config; + + beforeEach(() => { + vi.spyOn(ClearcutLogger.prototype, 'logAgentFinishEvent'); + vi.spyOn(metrics, 'recordAgentRunMetrics'); + }); + + it('should log agent finish event and record metrics', () => { + const event = new AgentFinishEvent( + 'agent-123', + 'TestAgent', + 1000, + 5, + AgentTerminateMode.GOAL, + ); + + logAgentFinish(mockConfig, event); + + expect(ClearcutLogger.prototype.logAgentFinishEvent).toHaveBeenCalledWith( + event, + ); + + expect(mockLogger.emit).toHaveBeenCalledWith({ + body: 'Agent TestAgent finished. Reason: GOAL. Duration: 1000ms. Turns: 5.', + attributes: { + 'session.id': 'test-session-id', + 'user.email': 'test-user@example.com', + 'event.name': EVENT_AGENT_FINISH, + 'event.timestamp': '2025-01-01T00:00:00.000Z', + agent_id: 'agent-123', + agent_name: 'TestAgent', + duration_ms: 1000, + turn_count: 5, + terminate_reason: 'GOAL', + }, + }); + + expect(metrics.recordAgentRunMetrics).toHaveBeenCalledWith( + mockConfig, + event, + ); + }); + }); }); diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index ef3294f21a..3dce516619 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -37,6 +37,8 @@ import { EVENT_EXTENSION_DISABLE, EVENT_SMART_EDIT_STRATEGY, EVENT_SMART_EDIT_CORRECTION, + EVENT_AGENT_START, + EVENT_AGENT_FINISH, } from './constants.js'; import type { ApiErrorEvent, @@ -69,6 +71,8 @@ import type { ModelSlashCommandEvent, SmartEditStrategyEvent, SmartEditCorrectionEvent, + AgentStartEvent, + AgentFinishEvent, } from './types.js'; import { recordApiErrorMetrics, @@ -83,6 +87,7 @@ import { getConventionAttributes, recordTokenUsageMetrics, recordApiResponseMetrics, + recordAgentRunMetrics, } from './metrics.js'; import { isTelemetrySdkInitialized } from './sdk.js'; import type { UiEvent } from './uiTelemetry.js'; @@ -863,3 +868,41 @@ export function logSmartEditCorrectionEvent( }; logger.emit(logRecord); } + +export function logAgentStart(config: Config, event: AgentStartEvent): void { + ClearcutLogger.getInstance(config)?.logAgentStartEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_AGENT_START, + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `Agent ${event.agent_name} started. ID: ${event.agent_id}`, + attributes, + }; + logger.emit(logRecord); +} + +export function logAgentFinish(config: Config, event: AgentFinishEvent): void { + ClearcutLogger.getInstance(config)?.logAgentFinishEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_AGENT_FINISH, + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `Agent ${event.agent_name} finished. Reason: ${event.terminate_reason}. Duration: ${event.duration_ms}ms. Turns: ${event.turn_count}.`, + attributes, + }; + logger.emit(logRecord); + + recordAgentRunMetrics(config, event); +} diff --git a/packages/core/src/telemetry/metrics.test.ts b/packages/core/src/telemetry/metrics.test.ts index d7bd447c3c..3444a591e9 100644 --- a/packages/core/src/telemetry/metrics.test.ts +++ b/packages/core/src/telemetry/metrics.test.ts @@ -20,7 +20,8 @@ import { ApiRequestPhase, } from './metrics.js'; import { makeFakeConfig } from '../test-utils/config.js'; -import { ModelRoutingEvent } from './types.js'; +import { ModelRoutingEvent, AgentFinishEvent } from './types.js'; +import { AgentTerminateMode } from '../agents/types.js'; const mockCounterAddFn: Mock< (value: number, attributes?: Attributes, context?: Context) => void @@ -89,6 +90,7 @@ describe('Telemetry Metrics', () => { let recordBaselineComparisonModule: typeof import('./metrics.js').recordBaselineComparison; let recordGenAiClientTokenUsageModule: typeof import('./metrics.js').recordGenAiClientTokenUsage; let recordGenAiClientOperationDurationModule: typeof import('./metrics.js').recordGenAiClientOperationDuration; + let recordAgentRunMetricsModule: typeof import('./metrics.js').recordAgentRunMetrics; beforeEach(async () => { vi.resetModules(); @@ -121,6 +123,7 @@ describe('Telemetry Metrics', () => { metricsJsModule.recordGenAiClientTokenUsage; recordGenAiClientOperationDurationModule = metricsJsModule.recordGenAiClientOperationDuration; + recordAgentRunMetricsModule = metricsJsModule.recordAgentRunMetrics; const otelApiModule = await import('@opentelemetry/api'); @@ -439,6 +442,60 @@ describe('Telemetry Metrics', () => { }); }); + describe('recordAgentRunMetrics', () => { + const mockConfig = { + getSessionId: () => 'test-session-id', + getTelemetryEnabled: () => true, + } as unknown as Config; + + it('should not record metrics if not initialized', () => { + const event = new AgentFinishEvent( + 'agent-123', + 'TestAgent', + 1000, + 5, + AgentTerminateMode.GOAL, + ); + recordAgentRunMetricsModule(mockConfig, event); + expect(mockCounterAddFn).not.toHaveBeenCalled(); + expect(mockHistogramRecordFn).not.toHaveBeenCalled(); + }); + + it('should record agent run metrics', () => { + initializeMetricsModule(mockConfig); + mockCounterAddFn.mockClear(); + mockHistogramRecordFn.mockClear(); + + const event = new AgentFinishEvent( + 'agent-123', + 'TestAgent', + 1000, + 5, + AgentTerminateMode.GOAL, + ); + recordAgentRunMetricsModule(mockConfig, event); + + // Verify agent run counter + expect(mockCounterAddFn).toHaveBeenCalledWith(1, { + 'session.id': 'test-session-id', + agent_name: 'TestAgent', + terminate_reason: 'GOAL', + }); + + // Verify agent duration histogram + expect(mockHistogramRecordFn).toHaveBeenCalledWith(1000, { + 'session.id': 'test-session-id', + agent_name: 'TestAgent', + }); + + // Verify agent turns histogram + expect(mockHistogramRecordFn).toHaveBeenCalledWith(5, { + 'session.id': 'test-session-id', + agent_name: 'TestAgent', + }); + }); + }); + describe('OpenTelemetry GenAI Semantic Convention Metrics', () => { const mockConfig = { getSessionId: () => 'test-session-id', diff --git a/packages/core/src/telemetry/metrics.ts b/packages/core/src/telemetry/metrics.ts index 39f7ed3ab7..54f23f5d85 100644 --- a/packages/core/src/telemetry/metrics.ts +++ b/packages/core/src/telemetry/metrics.ts @@ -8,7 +8,11 @@ import type { Attributes, Meter, Counter, Histogram } from '@opentelemetry/api'; import { diag, metrics, ValueType } from '@opentelemetry/api'; import { SERVICE_NAME, EVENT_CHAT_COMPRESSION } from './constants.js'; import type { Config } from '../config/config.js'; -import type { ModelRoutingEvent, ModelSlashCommandEvent } from './types.js'; +import type { + ModelRoutingEvent, + ModelSlashCommandEvent, + AgentFinishEvent, +} from './types.js'; import { AuthType } from '../core/contentGenerator.js'; const TOOL_CALL_COUNT = 'gemini_cli.tool.call.count'; @@ -27,6 +31,11 @@ const MODEL_ROUTING_FAILURE_COUNT = 'gemini_cli.model_routing.failure.count'; const MODEL_SLASH_COMMAND_CALL_COUNT = 'gemini_cli.slash_command.model.call_count'; +// Agent Metrics +const AGENT_RUN_COUNT = 'gemini_cli.agent.run.count'; +const AGENT_DURATION_MS = 'gemini_cli.agent.duration'; +const AGENT_TURNS = 'gemini_cli.agent.turns'; + // OpenTelemetry GenAI Semantic Convention Metrics const GEN_AI_CLIENT_TOKEN_USAGE = 'gen_ai.client.token.usage'; const GEN_AI_CLIENT_OPERATION_DURATION = 'gen_ai.client.operation.duration'; @@ -144,6 +153,15 @@ const COUNTER_DEFINITIONS = { tokens_after: number; }, }, + [AGENT_RUN_COUNT]: { + description: 'Counts agent runs, tagged by name and termination reason.', + valueType: ValueType.INT, + assign: (c: Counter) => (agentRunCounter = c), + attributes: {} as { + agent_name: string; + terminate_reason: string; + }, + }, } as const; const HISTOGRAM_DEFINITIONS = { @@ -175,6 +193,24 @@ const HISTOGRAM_DEFINITIONS = { 'routing.decision_source': string; }, }, + [AGENT_DURATION_MS]: { + description: 'Duration of agent runs in milliseconds.', + unit: 'ms', + valueType: ValueType.INT, + assign: (h: Histogram) => (agentDurationHistogram = h), + attributes: {} as { + agent_name: string; + }, + }, + [AGENT_TURNS]: { + description: 'Number of turns taken by agents.', + unit: 'turns', + valueType: ValueType.INT, + assign: (h: Histogram) => (agentTurnsHistogram = h), + attributes: {} as { + agent_name: string; + }, + }, [GEN_AI_CLIENT_TOKEN_USAGE]: { description: 'Number of input and output tokens used.', unit: 'token', @@ -405,6 +441,9 @@ let contentRetryFailureCounter: Counter | undefined; let modelRoutingLatencyHistogram: Histogram | undefined; let modelRoutingFailureCounter: Counter | undefined; let modelSlashCommandCallCounter: Counter | undefined; +let agentRunCounter: Counter | undefined; +let agentDurationHistogram: Histogram | undefined; +let agentTurnsHistogram: Histogram | undefined; // OpenTelemetry GenAI Semantic Convention Metrics let genAiClientTokenUsageHistogram: Histogram | undefined; @@ -626,6 +665,37 @@ export function recordModelRoutingMetrics( } } +export function recordAgentRunMetrics( + config: Config, + event: AgentFinishEvent, +): void { + if ( + !agentRunCounter || + !agentDurationHistogram || + !agentTurnsHistogram || + !isMetricsInitialized + ) + return; + + const commonAttributes = baseMetricDefinition.getCommonAttributes(config); + + agentRunCounter.add(1, { + ...commonAttributes, + agent_name: event.agent_name, + terminate_reason: event.terminate_reason, + }); + + agentDurationHistogram.record(event.duration_ms, { + ...commonAttributes, + agent_name: event.agent_name, + }); + + agentTurnsHistogram.record(event.turn_count, { + ...commonAttributes, + agent_name: event.agent_name, + }); +} + // OpenTelemetry GenAI Semantic Convention Recording Functions export function recordGenAiClientTokenUsage( diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index 6481847ca6..bb6c705d0a 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -19,6 +19,7 @@ import type { FileOperation } from './metrics.js'; export { ToolCallDecision }; import type { ToolRegistry } from '../tools/tool-registry.js'; import type { OutputFormat } from '../output/types.js'; +import type { AgentTerminateMode } from '../agents/types.js'; export interface BaseTelemetryEvent { 'event.name': string; @@ -687,7 +688,9 @@ export type TelemetryEvent = | ExtensionUninstallEvent | ModelRoutingEvent | ToolOutputTruncatedEvent - | ModelSlashCommandEvent; + | ModelSlashCommandEvent + | AgentStartEvent + | AgentFinishEvent; export class ExtensionDisableEvent implements BaseTelemetryEvent { 'event.name': 'extension_disable'; @@ -726,3 +729,43 @@ export class SmartEditCorrectionEvent implements BaseTelemetryEvent { this.correction = correction; } } + +export class AgentStartEvent implements BaseTelemetryEvent { + 'event.name': 'agent_start'; + 'event.timestamp': string; + agent_id: string; + agent_name: string; + + constructor(agent_id: string, agent_name: string) { + this['event.name'] = 'agent_start'; + this['event.timestamp'] = new Date().toISOString(); + this.agent_id = agent_id; + this.agent_name = agent_name; + } +} + +export class AgentFinishEvent implements BaseTelemetryEvent { + 'event.name': 'agent_finish'; + 'event.timestamp': string; + agent_id: string; + agent_name: string; + duration_ms: number; + turn_count: number; + terminate_reason: AgentTerminateMode; + + constructor( + agent_id: string, + agent_name: string, + duration_ms: number, + turn_count: number, + terminate_reason: AgentTerminateMode, + ) { + this['event.name'] = 'agent_finish'; + this['event.timestamp'] = new Date().toISOString(); + this.agent_id = agent_id; + this.agent_name = agent_name; + this.duration_ms = duration_ms; + this.turn_count = turn_count; + this.terminate_reason = terminate_reason; + } +}