feat(core): add telemetry for subagent execution (#10456)

This commit is contained in:
Abhi
2025-10-08 15:42:33 -04:00
committed by GitHub
parent b45bd5ff7b
commit c0552ceb22
11 changed files with 608 additions and 20 deletions
+114 -7
View File
@@ -6,13 +6,6 @@
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
import { AgentExecutor, type ActivityCallback } from './executor.js'; 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 { makeFakeConfig } from '../test-utils/config.js';
import { ToolRegistry } from '../tools/tool-registry.js'; import { ToolRegistry } from '../tools/tool-registry.js';
import { LSTool } from '../tools/ls.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 { MockTool } from '../test-utils/mock-tool.js';
import { getDirectoryContextString } from '../utils/environmentContext.js'; import { getDirectoryContextString } from '../utils/environmentContext.js';
import { z } from 'zod'; 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(() => ({ const { mockSendMessageStream, mockExecuteToolCall } = vi.hoisted(() => ({
mockSendMessageStream: vi.fn(), mockSendMessageStream: vi.fn(),
@@ -54,8 +57,29 @@ vi.mock('../core/nonInteractiveToolExecutor.js', () => ({
vi.mock('../utils/environmentContext.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<typeof import('../utils/promptIdContext.js')>();
return {
...actual,
promptIdContext: {
...actual.promptIdContext,
getStore: vi.fn(),
run: vi.fn((_id, fn) => fn()),
},
};
});
const MockedGeminiChat = vi.mocked(GeminiChat); const MockedGeminiChat = vi.mocked(GeminiChat);
const mockedGetDirectoryContextString = vi.mocked(getDirectoryContextString); const mockedGetDirectoryContextString = vi.mocked(getDirectoryContextString);
const mockedPromptIdContext = vi.mocked(promptIdContext);
const mockedLogAgentStart = vi.mocked(logAgentStart);
const mockedLogAgentFinish = vi.mocked(logAgentFinish);
// Constants for testing // Constants for testing
const TASK_COMPLETE_TOOL_NAME = 'complete_task'; const TASK_COMPLETE_TOOL_NAME = 'complete_task';
@@ -160,6 +184,10 @@ describe('AgentExecutor', () => {
vi.resetAllMocks(); vi.resetAllMocks();
mockSendMessageStream.mockReset(); mockSendMessageStream.mockReset();
mockExecuteToolCall.mockReset(); mockExecuteToolCall.mockReset();
mockedLogAgentStart.mockReset();
mockedLogAgentFinish.mockReset();
mockedPromptIdContext.getStore.mockReset();
mockedPromptIdContext.run.mockImplementation((_id, fn) => fn());
MockedGeminiChat.mockImplementation( MockedGeminiChat.mockImplementation(
() => () =>
@@ -229,9 +257,52 @@ describe('AgentExecutor', () => {
expect(agentRegistry.getAllToolNames()).toHaveLength(2); expect(agentRegistry.getAllToolNames()).toHaveLength(2);
expect(agentRegistry.getTool(MOCK_TOOL_NOT_ALLOWED.name)).toBeUndefined(); 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)', () => { 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 () => { it('should execute successfully when model calls complete_task with output (Happy Path with Output)', async () => {
const definition = createTestDefinition(); const definition = createTestDefinition();
const executor = await AgentExecutor.create( const executor = await AgentExecutor.create(
@@ -312,6 +383,34 @@ describe('AgentExecutor', () => {
expect(output.result).toBe('Found file1.txt'); expect(output.result).toBe('Found file1.txt');
expect(output.terminate_reason).toBe(AgentTerminateMode.GOAL); 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(activities).toEqual(
expect.arrayContaining([ expect.arrayContaining([
expect.objectContaining({ expect.objectContaining({
@@ -425,6 +524,14 @@ describe('AgentExecutor', () => {
expect(output.terminate_reason).toBe(AgentTerminateMode.ERROR); expect(output.terminate_reason).toBe(AgentTerminateMode.ERROR);
expect(output.result).toBe(expectedError); expect(output.result).toBe(expectedError);
// Telemetry check for error
expect(mockedLogAgentFinish).toHaveBeenCalledWith(
mockConfig,
expect.objectContaining({
terminate_reason: AgentTerminateMode.ERROR,
}),
);
expect(activities).toContainEqual( expect(activities).toContainEqual(
expect.objectContaining({ expect.objectContaining({
type: 'ERROR', type: 'ERROR',
+35 -10
View File
@@ -28,6 +28,9 @@ import { MemoryTool } from '../tools/memoryTool.js';
import { ReadFileTool } from '../tools/read-file.js'; import { ReadFileTool } from '../tools/read-file.js';
import { ReadManyFilesTool } from '../tools/read-many-files.js'; import { ReadManyFilesTool } from '../tools/read-many-files.js';
import { WebSearchTool } from '../tools/web-search.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 { import type {
AgentDefinition, AgentDefinition,
AgentInputs, AgentInputs,
@@ -104,10 +107,14 @@ export class AgentExecutor<TOutput extends z.ZodTypeAny> {
await AgentExecutor.validateTools(agentToolRegistry, definition.name); await AgentExecutor.validateTools(agentToolRegistry, definition.name);
} }
// Get the parent prompt ID from context
const parentPromptId = promptIdContext.getStore();
return new AgentExecutor( return new AgentExecutor(
definition, definition,
runtimeContext, runtimeContext,
agentToolRegistry, agentToolRegistry,
parentPromptId,
onActivity, onActivity,
); );
} }
@@ -122,6 +129,7 @@ export class AgentExecutor<TOutput extends z.ZodTypeAny> {
definition: AgentDefinition<TOutput>, definition: AgentDefinition<TOutput>,
runtimeContext: Config, runtimeContext: Config,
toolRegistry: ToolRegistry, toolRegistry: ToolRegistry,
parentPromptId: string | undefined,
onActivity?: ActivityCallback, onActivity?: ActivityCallback,
) { ) {
this.definition = definition; this.definition = definition;
@@ -130,7 +138,10 @@ export class AgentExecutor<TOutput extends z.ZodTypeAny> {
this.onActivity = onActivity; this.onActivity = onActivity;
const randomIdPart = Math.random().toString(36).slice(2, 8); 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<TOutput extends z.ZodTypeAny> {
async run(inputs: AgentInputs, signal: AbortSignal): Promise<OutputObject> { async run(inputs: AgentInputs, signal: AbortSignal): Promise<OutputObject> {
const startTime = Date.now(); const startTime = Date.now();
let turnCounter = 0; let turnCounter = 0;
let terminateReason: AgentTerminateMode = AgentTerminateMode.ERROR;
let finalResult: string | null = null;
logAgentStart(
this.runtimeContext,
new AgentStartEvent(this.agentId, this.definition.name),
);
try { try {
const chat = await this.createChatObject(inputs); const chat = await this.createChatObject(inputs);
const tools = this.prepareToolsList(); const tools = this.prepareToolsList();
let terminateReason = AgentTerminateMode.ERROR;
let finalResult: string | null = null;
const query = this.definition.promptConfig.query const query = this.definition.promptConfig.query
? templateString(this.definition.promptConfig.query, inputs) ? templateString(this.definition.promptConfig.query, inputs)
@@ -167,14 +183,12 @@ export class AgentExecutor<TOutput extends z.ZodTypeAny> {
break; break;
} }
// Call model const promptId = `${this.agentId}#${turnCounter++}`;
const promptId = `${this.runtimeContext.getSessionId()}#${this.agentId}#${turnCounter++}`;
const { functionCalls } = await this.callModel( const { functionCalls } = await promptIdContext.run(
chat,
currentMessage,
tools,
signal,
promptId, promptId,
async () =>
this.callModel(chat, currentMessage, tools, signal, promptId),
); );
if (signal.aborted) { if (signal.aborted) {
@@ -220,6 +234,17 @@ export class AgentExecutor<TOutput extends z.ZodTypeAny> {
} catch (error) { } catch (error) {
this.emitActivity('ERROR', { error: String(error) }); this.emitActivity('ERROR', { error: String(error) });
throw error; // Re-throw the error for the parent context to handle. 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,
),
);
} }
} }
@@ -29,7 +29,10 @@ import {
makeChatCompressionEvent, makeChatCompressionEvent,
ModelRoutingEvent, ModelRoutingEvent,
ToolCallEvent, ToolCallEvent,
AgentStartEvent,
AgentFinishEvent,
} from '../types.js'; } from '../types.js';
import { AgentTerminateMode } from '../../agents/types.js';
import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js'; import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js';
import { UserAccountManager } from '../../utils/userAccountManager.js'; import { UserAccountManager } from '../../utils/userAccountManager.js';
import { InstallationManager } from '../../utils/installationManager.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', () => { describe('logToolCallEvent', () => {
it('logs an event with all diff metadata', () => { it('logs an event with all diff metadata', () => {
const { logger } = setup(); const { logger } = setup();
@@ -33,6 +33,8 @@ import type {
ExtensionDisableEvent, ExtensionDisableEvent,
SmartEditStrategyEvent, SmartEditStrategyEvent,
SmartEditCorrectionEvent, SmartEditCorrectionEvent,
AgentStartEvent,
AgentFinishEvent,
} from '../types.js'; } from '../types.js';
import { EventMetadataKey } from './event-metadata-key.js'; import { EventMetadataKey } from './event-metadata-key.js';
import type { Config } from '../../config/config.js'; import type { Config } from '../../config/config.js';
@@ -79,6 +81,8 @@ export enum EventNames {
MODEL_SLASH_COMMAND = 'model_slash_command', MODEL_SLASH_COMMAND = 'model_slash_command',
SMART_EDIT_STRATEGY = 'smart_edit_strategy', SMART_EDIT_STRATEGY = 'smart_edit_strategy',
SMART_EDIT_CORRECTION = 'smart_edit_correction', SMART_EDIT_CORRECTION = 'smart_edit_correction',
AGENT_START = 'agent_start',
AGENT_FINISH = 'agent_finish',
} }
export interface LogResponse { export interface LogResponse {
@@ -1063,6 +1067,50 @@ export class ClearcutLogger {
this.flushIfNeeded(); 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 * Adds default fields to data, and returns a new data array. This fields
* should exist on all log events. * should exist on all log events.
@@ -426,4 +426,23 @@ export enum EventMetadataKey {
// Logs an event when the user uses the /model command. // Logs an event when the user uses the /model command.
GEMINI_CLI_MODEL_SLASH_COMMAND = 108, 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,
} }
+4
View File
@@ -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_MODEL_ROUTING = 'gemini_cli.model_routing';
export const EVENT_SMART_EDIT_CORRECTION = 'gemini_cli.smart_edit.correction'; 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 // Performance Events
export const EVENT_STARTUP_PERFORMANCE = 'gemini_cli.startup.performance'; export const EVENT_STARTUP_PERFORMANCE = 'gemini_cli.startup.performance';
export const EVENT_MEMORY_USAGE = 'gemini_cli.memory.usage'; export const EVENT_MEMORY_USAGE = 'gemini_cli.memory.usage';
@@ -38,6 +38,8 @@ import {
EVENT_EXTENSION_INSTALL, EVENT_EXTENSION_INSTALL,
EVENT_EXTENSION_UNINSTALL, EVENT_EXTENSION_UNINSTALL,
EVENT_TOOL_OUTPUT_TRUNCATED, EVENT_TOOL_OUTPUT_TRUNCATED,
EVENT_AGENT_START,
EVENT_AGENT_FINISH,
} from './constants.js'; } from './constants.js';
import { import {
logApiRequest, logApiRequest,
@@ -56,6 +58,8 @@ import {
logExtensionDisable, logExtensionDisable,
logExtensionInstallEvent, logExtensionInstallEvent,
logExtensionUninstall, logExtensionUninstall,
logAgentStart,
logAgentFinish,
} from './loggers.js'; } from './loggers.js';
import { ToolCallDecision } from './tool-call-decision.js'; import { ToolCallDecision } from './tool-call-decision.js';
import { import {
@@ -75,6 +79,8 @@ import {
ExtensionDisableEvent, ExtensionDisableEvent,
ExtensionInstallEvent, ExtensionInstallEvent,
ExtensionUninstallEvent, ExtensionUninstallEvent,
AgentStartEvent,
AgentFinishEvent,
} from './types.js'; } from './types.js';
import * as metrics from './metrics.js'; import * as metrics from './metrics.js';
import { import {
@@ -93,6 +99,7 @@ import * as uiTelemetry from './uiTelemetry.js';
import { makeFakeConfig } from '../test-utils/config.js'; import { makeFakeConfig } from '../test-utils/config.js';
import { ClearcutLogger } from './clearcut-logger/clearcut-logger.js'; import { ClearcutLogger } from './clearcut-logger/clearcut-logger.js';
import { UserAccountManager } from '../utils/userAccountManager.js'; import { UserAccountManager } from '../utils/userAccountManager.js';
import { AgentTerminateMode } from '../agents/types.js';
describe('loggers', () => { describe('loggers', () => {
const mockLogger = { 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,
);
});
});
}); });
+43
View File
@@ -37,6 +37,8 @@ import {
EVENT_EXTENSION_DISABLE, EVENT_EXTENSION_DISABLE,
EVENT_SMART_EDIT_STRATEGY, EVENT_SMART_EDIT_STRATEGY,
EVENT_SMART_EDIT_CORRECTION, EVENT_SMART_EDIT_CORRECTION,
EVENT_AGENT_START,
EVENT_AGENT_FINISH,
} from './constants.js'; } from './constants.js';
import type { import type {
ApiErrorEvent, ApiErrorEvent,
@@ -69,6 +71,8 @@ import type {
ModelSlashCommandEvent, ModelSlashCommandEvent,
SmartEditStrategyEvent, SmartEditStrategyEvent,
SmartEditCorrectionEvent, SmartEditCorrectionEvent,
AgentStartEvent,
AgentFinishEvent,
} from './types.js'; } from './types.js';
import { import {
recordApiErrorMetrics, recordApiErrorMetrics,
@@ -83,6 +87,7 @@ import {
getConventionAttributes, getConventionAttributes,
recordTokenUsageMetrics, recordTokenUsageMetrics,
recordApiResponseMetrics, recordApiResponseMetrics,
recordAgentRunMetrics,
} from './metrics.js'; } from './metrics.js';
import { isTelemetrySdkInitialized } from './sdk.js'; import { isTelemetrySdkInitialized } from './sdk.js';
import type { UiEvent } from './uiTelemetry.js'; import type { UiEvent } from './uiTelemetry.js';
@@ -863,3 +868,41 @@ export function logSmartEditCorrectionEvent(
}; };
logger.emit(logRecord); 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);
}
+58 -1
View File
@@ -20,7 +20,8 @@ import {
ApiRequestPhase, ApiRequestPhase,
} from './metrics.js'; } from './metrics.js';
import { makeFakeConfig } from '../test-utils/config.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< const mockCounterAddFn: Mock<
(value: number, attributes?: Attributes, context?: Context) => void (value: number, attributes?: Attributes, context?: Context) => void
@@ -89,6 +90,7 @@ describe('Telemetry Metrics', () => {
let recordBaselineComparisonModule: typeof import('./metrics.js').recordBaselineComparison; let recordBaselineComparisonModule: typeof import('./metrics.js').recordBaselineComparison;
let recordGenAiClientTokenUsageModule: typeof import('./metrics.js').recordGenAiClientTokenUsage; let recordGenAiClientTokenUsageModule: typeof import('./metrics.js').recordGenAiClientTokenUsage;
let recordGenAiClientOperationDurationModule: typeof import('./metrics.js').recordGenAiClientOperationDuration; let recordGenAiClientOperationDurationModule: typeof import('./metrics.js').recordGenAiClientOperationDuration;
let recordAgentRunMetricsModule: typeof import('./metrics.js').recordAgentRunMetrics;
beforeEach(async () => { beforeEach(async () => {
vi.resetModules(); vi.resetModules();
@@ -121,6 +123,7 @@ describe('Telemetry Metrics', () => {
metricsJsModule.recordGenAiClientTokenUsage; metricsJsModule.recordGenAiClientTokenUsage;
recordGenAiClientOperationDurationModule = recordGenAiClientOperationDurationModule =
metricsJsModule.recordGenAiClientOperationDuration; metricsJsModule.recordGenAiClientOperationDuration;
recordAgentRunMetricsModule = metricsJsModule.recordAgentRunMetrics;
const otelApiModule = await import('@opentelemetry/api'); 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', () => { describe('OpenTelemetry GenAI Semantic Convention Metrics', () => {
const mockConfig = { const mockConfig = {
getSessionId: () => 'test-session-id', getSessionId: () => 'test-session-id',
+71 -1
View File
@@ -8,7 +8,11 @@ import type { Attributes, Meter, Counter, Histogram } from '@opentelemetry/api';
import { diag, metrics, ValueType } from '@opentelemetry/api'; import { diag, metrics, ValueType } from '@opentelemetry/api';
import { SERVICE_NAME, EVENT_CHAT_COMPRESSION } from './constants.js'; import { SERVICE_NAME, EVENT_CHAT_COMPRESSION } from './constants.js';
import type { Config } from '../config/config.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'; import { AuthType } from '../core/contentGenerator.js';
const TOOL_CALL_COUNT = 'gemini_cli.tool.call.count'; 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 = const MODEL_SLASH_COMMAND_CALL_COUNT =
'gemini_cli.slash_command.model.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 // OpenTelemetry GenAI Semantic Convention Metrics
const GEN_AI_CLIENT_TOKEN_USAGE = 'gen_ai.client.token.usage'; const GEN_AI_CLIENT_TOKEN_USAGE = 'gen_ai.client.token.usage';
const GEN_AI_CLIENT_OPERATION_DURATION = 'gen_ai.client.operation.duration'; const GEN_AI_CLIENT_OPERATION_DURATION = 'gen_ai.client.operation.duration';
@@ -144,6 +153,15 @@ const COUNTER_DEFINITIONS = {
tokens_after: number; 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; } as const;
const HISTOGRAM_DEFINITIONS = { const HISTOGRAM_DEFINITIONS = {
@@ -175,6 +193,24 @@ const HISTOGRAM_DEFINITIONS = {
'routing.decision_source': string; '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]: { [GEN_AI_CLIENT_TOKEN_USAGE]: {
description: 'Number of input and output tokens used.', description: 'Number of input and output tokens used.',
unit: 'token', unit: 'token',
@@ -405,6 +441,9 @@ let contentRetryFailureCounter: Counter | undefined;
let modelRoutingLatencyHistogram: Histogram | undefined; let modelRoutingLatencyHistogram: Histogram | undefined;
let modelRoutingFailureCounter: Counter | undefined; let modelRoutingFailureCounter: Counter | undefined;
let modelSlashCommandCallCounter: Counter | undefined; let modelSlashCommandCallCounter: Counter | undefined;
let agentRunCounter: Counter | undefined;
let agentDurationHistogram: Histogram | undefined;
let agentTurnsHistogram: Histogram | undefined;
// OpenTelemetry GenAI Semantic Convention Metrics // OpenTelemetry GenAI Semantic Convention Metrics
let genAiClientTokenUsageHistogram: Histogram | undefined; 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 // OpenTelemetry GenAI Semantic Convention Recording Functions
export function recordGenAiClientTokenUsage( export function recordGenAiClientTokenUsage(
+44 -1
View File
@@ -19,6 +19,7 @@ import type { FileOperation } from './metrics.js';
export { ToolCallDecision }; export { ToolCallDecision };
import type { ToolRegistry } from '../tools/tool-registry.js'; import type { ToolRegistry } from '../tools/tool-registry.js';
import type { OutputFormat } from '../output/types.js'; import type { OutputFormat } from '../output/types.js';
import type { AgentTerminateMode } from '../agents/types.js';
export interface BaseTelemetryEvent { export interface BaseTelemetryEvent {
'event.name': string; 'event.name': string;
@@ -687,7 +688,9 @@ export type TelemetryEvent =
| ExtensionUninstallEvent | ExtensionUninstallEvent
| ModelRoutingEvent | ModelRoutingEvent
| ToolOutputTruncatedEvent | ToolOutputTruncatedEvent
| ModelSlashCommandEvent; | ModelSlashCommandEvent
| AgentStartEvent
| AgentFinishEvent;
export class ExtensionDisableEvent implements BaseTelemetryEvent { export class ExtensionDisableEvent implements BaseTelemetryEvent {
'event.name': 'extension_disable'; 'event.name': 'extension_disable';
@@ -726,3 +729,43 @@ export class SmartEditCorrectionEvent implements BaseTelemetryEvent {
this.correction = correction; 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;
}
}