From 293bb820193a41aee6f1421367a2d1fc6d836422 Mon Sep 17 00:00:00 2001 From: Shreya Keshive Date: Tue, 29 Jul 2025 16:20:37 -0400 Subject: [PATCH] Adds centralized support to log slash commands + sub commands (#5128) --- docs/telemetry.md | 5 + .../ui/hooks/slashCommandProcessor.test.ts | 94 +++++++++++++++++++ .../cli/src/ui/hooks/slashCommandProcessor.ts | 15 +++ .../clearcut-logger/clearcut-logger.ts | 21 +++++ .../clearcut-logger/event-metadata-key.ts | 10 ++ packages/core/src/telemetry/constants.ts | 1 + packages/core/src/telemetry/index.ts | 2 + packages/core/src/telemetry/loggers.ts | 23 +++++ packages/core/src/telemetry/types.ts | 17 +++- 9 files changed, 187 insertions(+), 1 deletion(-) diff --git a/docs/telemetry.md b/docs/telemetry.md index 2209ee0b..c7b88ba9 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -209,6 +209,11 @@ Logs are timestamped records of specific events. The following events are logged - **Attributes**: - `auth_type` +- `gemini_cli.slash_command`: This event occurs when a user executes a slash command. + - **Attributes**: + - `command` (string) + - `subcommand` (string, if applicable) + ### Metrics Metrics are numerical measurements of behavior over time. The following metrics are collected for Gemini CLI: diff --git a/packages/cli/src/ui/hooks/slashCommandProcessor.test.ts b/packages/cli/src/ui/hooks/slashCommandProcessor.test.ts index 42c2e277..30a14815 100644 --- a/packages/cli/src/ui/hooks/slashCommandProcessor.test.ts +++ b/packages/cli/src/ui/hooks/slashCommandProcessor.test.ts @@ -4,6 +4,21 @@ * SPDX-License-Identifier: Apache-2.0 */ +const { logSlashCommand, SlashCommandEvent } = vi.hoisted(() => ({ + logSlashCommand: vi.fn(), + SlashCommandEvent: vi.fn((command, subCommand) => ({ command, subCommand })), +})); + +vi.mock('@google/gemini-cli-core', async (importOriginal) => { + const original = + await importOriginal(); + return { + ...original, + logSlashCommand, + SlashCommandEvent, + }; +}); + const { mockProcessExit } = vi.hoisted(() => ({ mockProcessExit: vi.fn((_code?: number): never => undefined as never), })); @@ -814,4 +829,83 @@ describe('useSlashCommandProcessor', () => { expect(abortSpy).toHaveBeenCalledTimes(1); }); }); + + describe('Slash Command Logging', () => { + const mockCommandAction = vi.fn().mockResolvedValue({ type: 'handled' }); + const loggingTestCommands: SlashCommand[] = [ + createTestCommand({ + name: 'logtest', + action: mockCommandAction, + }), + createTestCommand({ + name: 'logwithsub', + subCommands: [ + createTestCommand({ + name: 'sub', + action: mockCommandAction, + }), + ], + }), + createTestCommand({ + name: 'logalias', + altNames: ['la'], + action: mockCommandAction, + }), + ]; + + beforeEach(() => { + mockCommandAction.mockClear(); + vi.mocked(logSlashCommand).mockClear(); + vi.mocked(SlashCommandEvent).mockClear(); + }); + + it('should log a simple slash command', async () => { + const result = setupProcessorHook(loggingTestCommands); + await waitFor(() => + expect(result.current.slashCommands.length).toBeGreaterThan(0), + ); + await act(async () => { + await result.current.handleSlashCommand('/logtest'); + }); + + expect(logSlashCommand).toHaveBeenCalledTimes(1); + expect(SlashCommandEvent).toHaveBeenCalledWith('logtest', undefined); + }); + + it('should log a slash command with a subcommand', async () => { + const result = setupProcessorHook(loggingTestCommands); + await waitFor(() => + expect(result.current.slashCommands.length).toBeGreaterThan(0), + ); + await act(async () => { + await result.current.handleSlashCommand('/logwithsub sub'); + }); + + expect(logSlashCommand).toHaveBeenCalledTimes(1); + expect(SlashCommandEvent).toHaveBeenCalledWith('logwithsub', 'sub'); + }); + + it('should log the command path when an alias is used', async () => { + const result = setupProcessorHook(loggingTestCommands); + await waitFor(() => + expect(result.current.slashCommands.length).toBeGreaterThan(0), + ); + await act(async () => { + await result.current.handleSlashCommand('/la'); + }); + expect(logSlashCommand).toHaveBeenCalledTimes(1); + expect(SlashCommandEvent).toHaveBeenCalledWith('logalias', undefined); + }); + + it('should not log for unknown commands', async () => { + const result = setupProcessorHook(loggingTestCommands); + await waitFor(() => + expect(result.current.slashCommands.length).toBeGreaterThan(0), + ); + await act(async () => { + await result.current.handleSlashCommand('/unknown'); + }); + expect(logSlashCommand).not.toHaveBeenCalled(); + }); + }); }); diff --git a/packages/cli/src/ui/hooks/slashCommandProcessor.ts b/packages/cli/src/ui/hooks/slashCommandProcessor.ts index be32de11..e315ba97 100644 --- a/packages/cli/src/ui/hooks/slashCommandProcessor.ts +++ b/packages/cli/src/ui/hooks/slashCommandProcessor.ts @@ -13,6 +13,8 @@ import { Config, GitService, Logger, + logSlashCommand, + SlashCommandEvent, ToolConfirmationOutcome, } from '@google/gemini-cli-core'; import { useSessionStats } from '../contexts/SessionContext.js'; @@ -233,6 +235,7 @@ export const useSlashCommandProcessor = ( let currentCommands = commands; let commandToExecute: SlashCommand | undefined; let pathIndex = 0; + const canonicalPath: string[] = []; for (const part of commandPath) { // TODO: For better performance and architectural clarity, this two-pass @@ -253,6 +256,7 @@ export const useSlashCommandProcessor = ( if (foundCommand) { commandToExecute = foundCommand; + canonicalPath.push(foundCommand.name); pathIndex++; if (foundCommand.subCommands) { currentCommands = foundCommand.subCommands; @@ -268,6 +272,17 @@ export const useSlashCommandProcessor = ( const args = parts.slice(pathIndex).join(' '); if (commandToExecute.action) { + if (config) { + const resolvedCommandPath = canonicalPath; + const event = new SlashCommandEvent( + resolvedCommandPath[0], + resolvedCommandPath.length > 1 + ? resolvedCommandPath.slice(1).join(' ') + : undefined, + ); + logSlashCommand(config, event); + } + const fullCommandContext: CommandContext = { ...commandContext, invocation: { diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts index fd5a9ab2..d221ef5e 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts @@ -19,6 +19,7 @@ import { FlashFallbackEvent, LoopDetectedEvent, FlashDecidedToContinueEvent, + SlashCommandEvent, } from '../types.js'; import { EventMetadataKey } from './event-metadata-key.js'; import { Config } from '../../config/config.js'; @@ -40,6 +41,7 @@ const end_session_event_name = 'end_session'; const flash_fallback_event_name = 'flash_fallback'; const loop_detected_event_name = 'loop_detected'; const flash_decided_to_continue_event_name = 'flash_decided_to_continue'; +const slash_command_event_name = 'slash_command'; export interface LogResponse { nextRequestWaitMs?: number; @@ -528,6 +530,25 @@ export class ClearcutLogger { this.flushIfNeeded(); } + logSlashCommandEvent(event: SlashCommandEvent): void { + const data = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_SLASH_COMMAND_NAME, + value: JSON.stringify(event.command), + }, + ]; + + if (event.subcommand) { + data.push({ + gemini_cli_key: EventMetadataKey.GEMINI_CLI_SLASH_COMMAND_SUBCOMMAND, + value: JSON.stringify(event.subcommand), + }); + } + + this.enqueueLogEvent(this.createLogEvent(slash_command_event_name, data)); + this.flushIfNeeded(); + } + logEndSessionEvent(event: EndSessionEvent): void { const data = [ { 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 b34cc6ea..9a182f67 100644 --- a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts +++ b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts @@ -163,6 +163,16 @@ export enum EventMetadataKey { // Logs the type of loop detected. GEMINI_CLI_LOOP_DETECTED_TYPE = 38, + + // ========================================================================== + // Slash Command Event Keys + // =========================================================================== + + // Logs the name of the slash command. + GEMINI_CLI_SLASH_COMMAND_NAME = 41, + + // Logs the subcommand of the slash command. + GEMINI_CLI_SLASH_COMMAND_SUBCOMMAND = 42, } export function getEventMetadataKey( diff --git a/packages/core/src/telemetry/constants.ts b/packages/core/src/telemetry/constants.ts index 316e827f..42572228 100644 --- a/packages/core/src/telemetry/constants.ts +++ b/packages/core/src/telemetry/constants.ts @@ -15,6 +15,7 @@ export const EVENT_CLI_CONFIG = 'gemini_cli.config'; export const EVENT_FLASH_FALLBACK = 'gemini_cli.flash_fallback'; export const EVENT_FLASH_DECIDED_TO_CONTINUE = 'gemini_cli.flash_decided_to_continue'; +export const EVENT_SLASH_COMMAND = 'gemini_cli.slash_command'; export const METRIC_TOOL_CALL_COUNT = 'gemini_cli.tool.call.count'; export const METRIC_TOOL_CALL_LATENCY = 'gemini_cli.tool.call.latency'; diff --git a/packages/core/src/telemetry/index.ts b/packages/core/src/telemetry/index.ts index 8da31727..6648b229 100644 --- a/packages/core/src/telemetry/index.ts +++ b/packages/core/src/telemetry/index.ts @@ -26,6 +26,7 @@ export { logApiError, logApiResponse, logFlashFallback, + logSlashCommand, } from './loggers.js'; export { StartSessionEvent, @@ -37,6 +38,7 @@ export { ApiResponseEvent, TelemetryEvent, FlashFallbackEvent, + SlashCommandEvent, } from './types.js'; export { SpanStatusCode, ValueType } from '@opentelemetry/api'; export { SemanticAttributes } from '@opentelemetry/semantic-conventions'; diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index 073124f4..3ee806bb 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -17,6 +17,7 @@ import { EVENT_FLASH_FALLBACK, EVENT_FLASH_DECIDED_TO_CONTINUE, SERVICE_NAME, + EVENT_SLASH_COMMAND, } from './constants.js'; import { ApiErrorEvent, @@ -28,6 +29,7 @@ import { FlashFallbackEvent, FlashDecidedToContinueEvent, LoopDetectedEvent, + SlashCommandEvent, } from './types.js'; import { recordApiErrorMetrics, @@ -332,3 +334,24 @@ export function logFlashDecidedToContinue( }; logger.emit(logRecord); } + +export function logSlashCommand( + config: Config, + event: SlashCommandEvent, +): void { + ClearcutLogger.getInstance(config)?.logSlashCommandEvent(event); + if (!isTelemetrySdkInitialized()) return; + + const attributes: LogAttributes = { + ...getCommonAttributes(config), + ...event, + 'event.name': EVENT_SLASH_COMMAND, + }; + + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: `Slash command: ${event.command}.`, + attributes, + }; + logger.emit(logRecord); +} diff --git a/packages/core/src/telemetry/types.ts b/packages/core/src/telemetry/types.ts index 69dffb08..d29b97d2 100644 --- a/packages/core/src/telemetry/types.ts +++ b/packages/core/src/telemetry/types.ts @@ -278,6 +278,20 @@ export class FlashDecidedToContinueEvent { } } +export class SlashCommandEvent { + 'event.name': 'slash_command'; + 'event.timestamp': string; // ISO 8106 + command: string; + subcommand?: string; + + constructor(command: string, subcommand?: string) { + this['event.name'] = 'slash_command'; + this['event.timestamp'] = new Date().toISOString(); + this.command = command; + this.subcommand = subcommand; + } +} + export type TelemetryEvent = | StartSessionEvent | EndSessionEvent @@ -288,4 +302,5 @@ export type TelemetryEvent = | ApiResponseEvent | FlashFallbackEvent | LoopDetectedEvent - | FlashDecidedToContinueEvent; + | FlashDecidedToContinueEvent + | SlashCommandEvent;