feat(telemetry): add clearcut logging for hooks (#15405)

This commit is contained in:
Abhi
2025-12-21 16:18:42 -05:00
committed by GitHub
parent 8643d60b88
commit b923604602
6 changed files with 159 additions and 1 deletions

View File

@@ -40,6 +40,14 @@ vi.mock('../utils/events.js', () => ({
coreEvents: mockCoreEvents,
}));
vi.mock('../telemetry/clearcut-logger/clearcut-logger.js', () => ({
ClearcutLogger: {
getInstance: vi.fn().mockReturnValue({
logHookCallEvent: vi.fn(),
}),
},
}));
describe('HookEventHandler', () => {
let hookEventHandler: HookEventHandler;
let mockConfig: Config;

View File

@@ -33,6 +33,7 @@ import {
AgentStartEvent,
AgentFinishEvent,
WebFetchFallbackAttemptEvent,
HookCallEvent,
} from '../types.js';
import { AgentTerminateMode } from '../../agents/types.js';
import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js';
@@ -1102,4 +1103,44 @@ describe('ClearcutLogger', () => {
]);
});
});
describe('logHookCallEvent', () => {
it('logs an event with proper fields', () => {
const { logger } = setup();
const hookName = '/path/to/my/script.sh';
const event = new HookCallEvent(
'before-tool',
'command',
hookName,
{}, // input
150, // duration
true, // success
{}, // output
0, // exit code
);
logger?.logHookCallEvent(event);
const events = getEvents(logger!);
expect(events.length).toBe(1);
expect(events[0]).toHaveEventName(EventNames.HOOK_CALL);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_HOOK_EVENT_NAME,
'before-tool',
]);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_HOOK_DURATION_MS,
'150',
]);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_HOOK_SUCCESS,
'true',
]);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_HOOK_EXIT_CODE,
'0',
]);
});
});
});

View File

@@ -39,6 +39,7 @@ import type {
WebFetchFallbackAttemptEvent,
ExtensionUpdateEvent,
LlmLoopCheckEvent,
HookCallEvent,
} from '../types.js';
import { EventMetadataKey } from './event-metadata-key.js';
import type { Config } from '../../config/config.js';
@@ -95,6 +96,7 @@ export enum EventNames {
RECOVERY_ATTEMPT = 'recovery_attempt',
WEB_FETCH_FALLBACK_ATTEMPT = 'web_fetch_fallback_attempt',
LLM_LOOP_CHECK = 'llm_loop_check',
HOOK_CALL = 'hook_call',
}
export interface LogResponse {
@@ -1381,6 +1383,33 @@ export class ClearcutLogger {
this.flushIfNeeded();
}
logHookCallEvent(event: HookCallEvent): void {
const data: EventValue[] = [
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_HOOK_EVENT_NAME,
value: event.hook_event_name,
},
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_HOOK_DURATION_MS,
value: event.duration_ms.toString(),
},
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_HOOK_SUCCESS,
value: event.success.toString(),
},
];
if (event.exit_code !== undefined) {
data.push({
gemini_cli_key: EventMetadataKey.GEMINI_CLI_HOOK_EXIT_CODE,
value: event.exit_code.toString(),
});
}
this.enqueueLogEvent(this.createLogEvent(EventNames.HOOK_CALL, data));
this.flushIfNeeded();
}
/**
* Adds default fields to data, and returns a new data array. This fields
* should exist on all log events.

View File

@@ -7,7 +7,7 @@
// Defines valid event metadata keys for Clearcut logging.
export enum EventMetadataKey {
// Deleted enums: 24
// Next ID: 133
// Next ID: 137
GEMINI_CLI_KEY_UNKNOWN = 0,
@@ -501,4 +501,20 @@ export enum EventMetadataKey {
// Logs the model that confirmed the loop.
GEMINI_CLI_LOOP_DETECTED_CONFIRMED_BY_MODEL = 129,
// ==========================================================================
// Hook Call Event Keys
// ==========================================================================
// Logs the name of the hook event (e.g., 'BeforeTool', 'AfterModel').
GEMINI_CLI_HOOK_EVENT_NAME = 133,
// Logs the duration of the hook execution in milliseconds.
GEMINI_CLI_HOOK_DURATION_MS = 134,
// Logs whether the hook execution was successful.
GEMINI_CLI_HOOK_SUCCESS = 135,
// Logs the exit code of the hook script (if applicable).
GEMINI_CLI_HOOK_EXIT_CODE = 136,
}

View File

@@ -43,6 +43,7 @@ import {
logAgentFinish,
logWebFetchFallbackAttempt,
logExtensionUpdateEvent,
logHookCall,
} from './loggers.js';
import { ToolCallDecision } from './tool-call-decision.js';
import {
@@ -87,6 +88,8 @@ import {
WebFetchFallbackAttemptEvent,
ExtensionUpdateEvent,
EVENT_EXTENSION_UPDATE,
HookCallEvent,
EVENT_HOOK_CALL,
} from './types.js';
import * as metrics from './metrics.js';
import { FileOperation } from './metrics.js';
@@ -2101,6 +2104,66 @@ describe('loggers', () => {
});
});
});
describe('logHookCall', () => {
const mockConfig = {
getSessionId: () => 'test-session-id',
getUsageStatisticsEnabled: () => true,
isInteractive: () => false,
getTelemetryLogPromptsEnabled: () => false,
} as unknown as Config;
beforeEach(() => {
vi.spyOn(ClearcutLogger.prototype, 'logHookCallEvent');
vi.spyOn(metrics, 'recordHookCallMetrics');
});
it('should log hook call event to Clearcut and OTEL', () => {
const event = new HookCallEvent(
'before-tool',
'command',
'/path/to/script.sh',
{ arg: 'val' },
150,
true,
{ out: 'res' },
0,
);
logHookCall(mockConfig, event);
expect(ClearcutLogger.prototype.logHookCallEvent).toHaveBeenCalledWith(
event,
);
expect(mockLogger.emit).toHaveBeenCalledWith({
body: 'Hook call before-tool./path/to/script.sh succeeded in 150ms',
attributes: {
'session.id': 'test-session-id',
'user.email': 'test-user@example.com',
'installation.id': 'test-installation-id',
'event.name': EVENT_HOOK_CALL,
'event.timestamp': '2025-01-01T00:00:00.000Z',
interactive: false,
hook_event_name: 'before-tool',
hook_type: 'command',
hook_name: 'script.sh', // Sanitized because logPrompts is false
duration_ms: 150,
success: true,
exit_code: 0,
},
});
expect(metrics.recordHookCallMetrics).toHaveBeenCalledWith(
mockConfig,
'before-tool',
'/path/to/script.sh',
150,
true,
);
});
});
describe('Telemetry Buffering', () => {
it('should buffer events when SDK is not initialized', () => {
vi.spyOn(sdk, 'isTelemetrySdkInitialized').mockReturnValue(false);

View File

@@ -672,6 +672,7 @@ export function logLlmLoopCheck(
}
export function logHookCall(config: Config, event: HookCallEvent): void {
ClearcutLogger.getInstance(config)?.logHookCallEvent(event);
bufferTelemetryEvent(() => {
const logger = logs.getLogger(SERVICE_NAME);
const logRecord: LogRecord = {