From 64eb14ab1171b5522ace35c19c59e785148d8cc9 Mon Sep 17 00:00:00 2001 From: owenofbrien <86964623+owenofbrien@users.noreply.github.com> Date: Fri, 21 Nov 2025 14:44:50 -0600 Subject: [PATCH] Fix exp id logging (#13430) --- .../src/ui/components/ModelDialog.test.tsx | 1 + .../cli/src/ui/hooks/useGeminiStream.test.tsx | 1 + .../cli/src/ui/hooks/useToolScheduler.test.ts | 1 + packages/core/src/config/config.ts | 11 +++ packages/core/src/core/client.test.ts | 1 + .../core/src/core/coreToolScheduler.test.ts | 2 + .../core/nonInteractiveToolExecutor.test.ts | 1 + .../clearcut-logger/clearcut-logger.test.ts | 26 ++---- .../clearcut-logger/clearcut-logger.ts | 89 ++++++++++++++----- .../clearcut-logger/event-metadata-key.ts | 3 + packages/core/src/tools/smart-edit.test.ts | 1 + 11 files changed, 92 insertions(+), 45 deletions(-) diff --git a/packages/cli/src/ui/components/ModelDialog.test.tsx b/packages/cli/src/ui/components/ModelDialog.test.tsx index a98a3caa82..ebbf921348 100644 --- a/packages/cli/src/ui/components/ModelDialog.test.tsx +++ b/packages/cli/src/ui/components/ModelDialog.test.tsx @@ -53,6 +53,7 @@ const renderComponent = ( getUseSmartEdit: vi.fn(() => false), getProxy: vi.fn(() => undefined), isInteractive: vi.fn(() => false), + getExperiments: () => {}, // --- Spread test-specific overrides --- ...contextValue, diff --git a/packages/cli/src/ui/hooks/useGeminiStream.test.tsx b/packages/cli/src/ui/hooks/useGeminiStream.test.tsx index 8411b4ba78..b5d7b57f8c 100644 --- a/packages/cli/src/ui/hooks/useGeminiStream.test.tsx +++ b/packages/cli/src/ui/hooks/useGeminiStream.test.tsx @@ -223,6 +223,7 @@ describe('useGeminiStream', () => { .mockReturnValue(contentGeneratorConfig), getUseSmartEdit: () => false, isInteractive: () => false, + getExperiments: () => {}, } as unknown as Config; mockOnDebugMessage = vi.fn(); mockHandleSlashCommand = vi.fn().mockResolvedValue(false); diff --git a/packages/cli/src/ui/hooks/useToolScheduler.test.ts b/packages/cli/src/ui/hooks/useToolScheduler.test.ts index 9c4bfd9b8b..8c75e86683 100644 --- a/packages/cli/src/ui/hooks/useToolScheduler.test.ts +++ b/packages/cli/src/ui/hooks/useToolScheduler.test.ts @@ -80,6 +80,7 @@ const mockConfig = { getMessageBus: () => null, getPolicyEngine: () => null, isInteractive: () => false, + getExperiments: () => {}, } as unknown as Config; const mockTool = new MockTool({ diff --git a/packages/core/src/config/config.ts b/packages/core/src/config/config.ts index 2e47e4294b..ef90634134 100644 --- a/packages/core/src/config/config.ts +++ b/packages/core/src/config/config.ts @@ -689,6 +689,17 @@ export class Config { this.inFallbackMode = false; } + async getExperimentsAsync(): Promise { + if (this.experiments) { + return this.experiments; + } + const codeAssistServer = getCodeAssistServer(this); + if (codeAssistServer) { + return getExperiments(codeAssistServer); + } + return undefined; + } + getUserTier(): UserTierId | undefined { return this.contentGenerator?.userTier; } diff --git a/packages/core/src/core/client.test.ts b/packages/core/src/core/client.test.ts index 7284fe9e6f..10e954fd2e 100644 --- a/packages/core/src/core/client.test.ts +++ b/packages/core/src/core/client.test.ts @@ -241,6 +241,7 @@ describe('Gemini Client (client.ts)', () => { }, }, isInteractive: vi.fn().mockReturnValue(false), + getExperiments: () => {}, } as unknown as Config; client = new GeminiClient(mockConfig); diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 2821f182db..a5d4d39823 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -223,6 +223,7 @@ function createMockConfig(overrides: Partial = {}): Config { discoverTools: async () => {}, getAllTools: () => [], getToolsByServer: () => [], + getExperiments: () => {}, } as unknown as ToolRegistry; const baseConfig = { @@ -252,6 +253,7 @@ function createMockConfig(overrides: Partial = {}): Config { getEnableMessageBusIntegration: () => false, getMessageBus: () => null, getPolicyEngine: () => null, + getExperiments: () => {}, } as unknown as Config; return { ...baseConfig, ...overrides } as Config; diff --git a/packages/core/src/core/nonInteractiveToolExecutor.test.ts b/packages/core/src/core/nonInteractiveToolExecutor.test.ts index d74165ee5e..9ec63584d1 100644 --- a/packages/core/src/core/nonInteractiveToolExecutor.test.ts +++ b/packages/core/src/core/nonInteractiveToolExecutor.test.ts @@ -65,6 +65,7 @@ describe('executeToolCall', () => { getMessageBus: () => null, getPolicyEngine: () => null, isInteractive: () => false, + getExperiments: () => {}, } as unknown as Config; abortController = new AbortController(); 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 ee6083c739..3b8747b629 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts @@ -66,7 +66,6 @@ expect.extend({ received: LogEventEntry[], [key, value]: [EventMetadataKey, string], ) { - const { isNot } = this; const event = JSON.parse(received[0].source_extension_json) as LogEvent; const metadata = event['event_metadata'][0]; const data = metadata.find((m) => m.gemini_cli_key === key)?.value; @@ -75,8 +74,7 @@ expect.extend({ return { pass, - message: () => - `event ${received} does${isNot ? ' not' : ''} have ${value}}`, + message: () => `event ${received} should have: ${value}. Found: ${data}`, }; }, @@ -93,21 +91,6 @@ expect.extend({ `event ${received} ${isNot ? 'has' : 'does not have'} the metadata key ${key}`, }; }, - - toHaveGwsExperiments(received: LogEventEntry[], expected_exps: number[]) { - const { isNot } = this; - const exps = received[0].gws_experiment; - - const pass = - exps.length === expected_exps.length && - exps.every((value, index) => value === expected_exps[index]); - - return { - pass, - message: () => - `event ${received} ${isNot ? 'has' : 'does not have'} expected exp ids: ${expected_exps.join(',')}`, - }; - }, }); vi.mock('../../utils/userAccountManager.js'); @@ -618,7 +601,6 @@ describe('ClearcutLogger', () => { { event_time_ms: Date.now(), source_extension_json: JSON.stringify({ event_id: i }), - gws_experiment: [], }, ]); } @@ -652,7 +634,6 @@ describe('ClearcutLogger', () => { { event_time_ms: Date.now(), source_extension_json: JSON.stringify({ event_id: `failed_${i}` }), - gws_experiment: [], }, ]); } @@ -779,7 +760,10 @@ describe('ClearcutLogger', () => { const events = getEvents(logger!); expect(events.length).toBe(1); expect(events[0]).toHaveEventName(EventNames.AGENT_START); - expect(events[0]).toHaveGwsExperiments([123, 456, 789]); + expect(events[0]).toHaveMetadataValue([ + EventMetadataKey.GEMINI_CLI_EXPERIMENT_IDS, + '123,456,789', + ]); }); }); diff --git a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts index 81a4e771b4..8c3ea14da8 100644 --- a/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts +++ b/packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts @@ -103,7 +103,6 @@ export interface LogResponse { export interface LogEventEntry { event_time_ms: number; source_extension_json: string; - gws_experiment: number[]; } export interface EventValue { @@ -233,28 +232,55 @@ export class ClearcutLogger { ClearcutLogger.instance = undefined; } + enqueueHelper(event: LogEvent): void { + // Manually handle overflow for FixedDeque, which throws when full. + const wasAtCapacity = this.events.size >= MAX_EVENTS; + + if (wasAtCapacity) { + this.events.shift(); // Evict oldest element to make space. + } + + this.events.push([ + { + event_time_ms: Date.now(), + source_extension_json: safeJsonStringify(event), + }, + ]); + + if (wasAtCapacity && this.config?.getDebugMode()) { + debugLogger.debug( + `ClearcutLogger: Dropped old event to prevent memory leak (queue size: ${this.events.size})`, + ); + } + } + enqueueLogEvent(event: LogEvent): void { try { - // Manually handle overflow for FixedDeque, which throws when full. - const wasAtCapacity = this.events.size >= MAX_EVENTS; - - if (wasAtCapacity) { - this.events.shift(); // Evict oldest element to make space. + this.enqueueHelper(event); + } catch (error) { + if (this.config?.getDebugMode()) { + console.error('ClearcutLogger: Failed to enqueue log event.', error); } + } + } - this.events.push([ - { - event_time_ms: Date.now(), - source_extension_json: safeJsonStringify(event), - gws_experiment: this.config?.getExperiments()?.experimentIds ?? [], - }, - ]); + async enqueueLogEventAfterExperimentsLoadAsync( + event: LogEvent, + ): Promise { + try { + this.config?.getExperimentsAsync().then((experiments) => { + if (experiments) { + const exp_id_data: EventValue[] = [ + { + gemini_cli_key: EventMetadataKey.GEMINI_CLI_EXPERIMENT_IDS, + value: experiments.experimentIds.toString() ?? 'NA', + }, + ]; + event.event_metadata = [[...event.event_metadata[0], ...exp_id_data]]; + } - if (wasAtCapacity && this.config?.getDebugMode()) { - debugLogger.debug( - `ClearcutLogger: Dropped old event to prevent memory leak (queue size: ${this.events.size})`, - ); - } + this.enqueueHelper(event); + }); } catch (error) { if (this.config?.getDebugMode()) { console.error('ClearcutLogger: Failed to enqueue log event.', error); @@ -507,10 +533,13 @@ export class ClearcutLogger { ]; this.sessionData = data; - // Flush start event immediately - this.enqueueLogEvent(this.createLogEvent(EventNames.START_SESSION, data)); - this.flushToClearcut().catch((error) => { - debugLogger.debug('Error flushing to Clearcut:', error); + // Flush after experiments finish loading from CCPA server + this.enqueueLogEventAfterExperimentsLoadAsync( + this.createLogEvent(EventNames.START_SESSION, data), + ).then(() => { + this.flushToClearcut().catch((error) => { + debugLogger.debug('Error flushing to Clearcut:', error); + }); }); } @@ -847,8 +876,14 @@ export class ClearcutLogger { }, ]; - this.enqueueLogEvent(this.createLogEvent(EventNames.IDE_CONNECTION, data)); - this.flushIfNeeded(); + // Flush after experiments finish loading from CCPA server + this.enqueueLogEventAfterExperimentsLoadAsync( + this.createLogEvent(EventNames.START_SESSION, data), + ).then(() => { + this.flushToClearcut().catch((error) => { + debugLogger.debug('Error flushing to Clearcut:', error); + }); + }); } logConversationFinishedEvent(event: ConversationFinishedEvent): void { @@ -1357,6 +1392,12 @@ export class ClearcutLogger { value: this.config?.isInteractive().toString() ?? 'false', }, ]; + if (this.config?.getExperiments()) { + defaultLogMetadata.push({ + gemini_cli_key: EventMetadataKey.GEMINI_CLI_EXPERIMENT_IDS, + value: this.config?.getExperiments()?.experimentIds.toString() ?? 'NA', + }); + } return [...data, ...defaultLogMetadata]; } 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 fc64f8a714..333bbaf6fa 100644 --- a/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts +++ b/packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts @@ -194,6 +194,9 @@ export enum EventMetadataKey { // Logs the name of the GitHub Action workflow that triggered the session. GEMINI_CLI_GH_WORKFLOW_NAME = 130, + // Logs the active experiment IDs for the session. + GEMINI_CLI_EXPERIMENT_IDS = 131, + // ========================================================================== // Loop Detected Event Keys // =========================================================================== diff --git a/packages/core/src/tools/smart-edit.test.ts b/packages/core/src/tools/smart-edit.test.ts index 293d586c67..2a003f0b8a 100644 --- a/packages/core/src/tools/smart-edit.test.ts +++ b/packages/core/src/tools/smart-edit.test.ts @@ -116,6 +116,7 @@ describe('SmartEditTool', () => { setGeminiMdFileCount: vi.fn(), getToolRegistry: () => ({}) as any, isInteractive: () => false, + getExperiments: () => {}, } as unknown as Config; (mockConfig.getApprovalMode as Mock).mockClear();