From a2174751de2e25c0f8b9ea4540c15cc1fcfba9c6 Mon Sep 17 00:00:00 2001 From: Kevin Ramdass Date: Tue, 10 Feb 2026 13:01:35 -0800 Subject: [PATCH] feat(telemetry): Ensure experiment IDs are included in OpenTelemetry logs (#18747) --- packages/core/src/telemetry/loggers.test.ts | 53 ++++++++++++++++++- packages/core/src/telemetry/loggers.ts | 41 +++++++++----- packages/core/src/telemetry/sanitize.test.ts | 2 + packages/core/src/telemetry/sdk.test.ts | 3 ++ .../core/src/telemetry/telemetryAttributes.ts | 5 ++ 5 files changed, 90 insertions(+), 14 deletions(-) diff --git a/packages/core/src/telemetry/loggers.test.ts b/packages/core/src/telemetry/loggers.test.ts index 246bed694d..16da103244 100644 --- a/packages/core/src/telemetry/loggers.test.ts +++ b/packages/core/src/telemetry/loggers.test.ts @@ -187,7 +187,7 @@ describe('loggers', () => { }); describe('logCliConfiguration', () => { - it('should log the cli configuration', () => { + it('should log the cli configuration', async () => { const mockConfig = { getSessionId: () => 'test-session-id', getModel: () => 'test-model', @@ -226,11 +226,14 @@ describe('loggers', () => { }), }), isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; const startSessionEvent = new StartSessionEvent(mockConfig); logCliConfiguration(mockConfig, startSessionEvent); + await new Promise(process.nextTick); expect(mockLogger.emit).toHaveBeenCalledWith({ body: 'CLI configuration loaded.', attributes: { @@ -271,6 +274,8 @@ describe('loggers', () => { getTelemetryLogPromptsEnabled: () => true, getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; it('should log a user prompt', () => { @@ -308,6 +313,8 @@ describe('loggers', () => { getTargetDir: () => 'target-dir', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; const event = new UserPromptEvent( 11, @@ -343,6 +350,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as Config; const mockMetrics = { @@ -519,6 +528,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as Config; const mockMetrics = { @@ -651,6 +662,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getContentGeneratorConfig: () => ({ authType: AuthType.LOGIN_WITH_GOOGLE, }), @@ -727,6 +740,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, // Enabled isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getContentGeneratorConfig: () => ({ authType: AuthType.USE_GEMINI, }), @@ -814,6 +829,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => false, // Disabled isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getContentGeneratorConfig: () => ({ authType: AuthType.USE_VERTEX_AI, }), @@ -867,6 +884,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getUsageStatisticsEnabled: () => true, getContentGeneratorConfig: () => ({ authType: AuthType.USE_GEMINI, @@ -903,6 +922,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; it('should log flash fallback event', () => { @@ -930,6 +951,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1024,6 +1047,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as Config; const mockMetrics = { @@ -1595,6 +1620,8 @@ describe('loggers', () => { getTelemetryEnabled: () => true, getTelemetryLogPromptsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as Config; const mockMetrics = { @@ -1655,6 +1682,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; it('should log a tool output truncated event', () => { @@ -1692,6 +1721,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1792,6 +1823,8 @@ describe('loggers', () => { getUsageStatisticsEnabled: () => true, getContentGeneratorConfig: () => null, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1842,6 +1875,8 @@ describe('loggers', () => { getUsageStatisticsEnabled: () => true, getContentGeneratorConfig: () => null, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1894,6 +1929,8 @@ describe('loggers', () => { getUsageStatisticsEnabled: () => true, getContentGeneratorConfig: () => null, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1938,6 +1975,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -1983,6 +2022,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -2028,6 +2069,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -2064,6 +2107,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -2115,6 +2160,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; beforeEach(() => { @@ -2150,6 +2197,8 @@ describe('loggers', () => { getSessionId: () => 'test-session-id', getUsageStatisticsEnabled: () => true, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getTelemetryLogPromptsEnabled: () => false, } as unknown as Config; @@ -2205,7 +2254,7 @@ describe('loggers', () => { }); describe('Telemetry Buffering', () => { - it('should buffer events when SDK is not initialized', () => { + it('should buffer events when SDK is not initialized', async () => { vi.spyOn(sdk, 'isTelemetrySdkInitialized').mockReturnValue(false); const bufferSpy = vi .spyOn(sdk, 'bufferTelemetryEvent') diff --git a/packages/core/src/telemetry/loggers.ts b/packages/core/src/telemetry/loggers.ts index c3d1dbf6c6..4699d50d70 100644 --- a/packages/core/src/telemetry/loggers.ts +++ b/packages/core/src/telemetry/loggers.ts @@ -81,6 +81,7 @@ import { bufferTelemetryEvent } from './sdk.js'; import type { UiEvent } from './uiTelemetry.js'; import { uiTelemetryService } from './uiTelemetry.js'; import { ClearcutLogger } from './clearcut-logger/clearcut-logger.js'; +import { debugLogger } from '../utils/debugLogger.js'; export function logCliConfiguration( config: Config, @@ -88,12 +89,20 @@ export function logCliConfiguration( ): void { void ClearcutLogger.getInstance(config)?.logStartSessionEvent(event); bufferTelemetryEvent(() => { - const logger = logs.getLogger(SERVICE_NAME); - const logRecord: LogRecord = { - body: event.toLogBody(), - attributes: event.toOpenTelemetryAttributes(config), - }; - logger.emit(logRecord); + // Wait for experiments to load before emitting so we capture experimentIds + void config + .getExperimentsAsync() + .then(() => { + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: event.toLogBody(), + attributes: event.toOpenTelemetryAttributes(config), + }; + logger.emit(logRecord); + }) + .catch((e: unknown) => { + debugLogger.error('Failed to log telemetry event', e); + }); }); } @@ -780,11 +789,19 @@ export function logStartupStats( event: StartupStatsEvent, ): void { bufferTelemetryEvent(() => { - const logger = logs.getLogger(SERVICE_NAME); - const logRecord: LogRecord = { - body: event.toLogBody(), - attributes: event.toOpenTelemetryAttributes(config), - }; - logger.emit(logRecord); + // Wait for experiments to load before emitting so we capture experimentIds + void config + .getExperimentsAsync() + .then(() => { + const logger = logs.getLogger(SERVICE_NAME); + const logRecord: LogRecord = { + body: event.toLogBody(), + attributes: event.toOpenTelemetryAttributes(config), + }; + logger.emit(logRecord); + }) + .catch((e: unknown) => { + debugLogger.error('Failed to log telemetry event', e); + }); }); } diff --git a/packages/core/src/telemetry/sanitize.test.ts b/packages/core/src/telemetry/sanitize.test.ts index d60dc3bd78..9e179c7552 100644 --- a/packages/core/src/telemetry/sanitize.test.ts +++ b/packages/core/src/telemetry/sanitize.test.ts @@ -26,6 +26,8 @@ function createMockConfig(logPromptsEnabled: boolean): Config { return { getTelemetryLogPromptsEnabled: () => logPromptsEnabled, getSessionId: () => 'test-session-id', + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, getModel: () => 'gemini-1.5-flash', isInteractive: () => true, getUserEmail: () => undefined, diff --git a/packages/core/src/telemetry/sdk.test.ts b/packages/core/src/telemetry/sdk.test.ts index bf9ed83a44..020fee4738 100644 --- a/packages/core/src/telemetry/sdk.test.ts +++ b/packages/core/src/telemetry/sdk.test.ts @@ -75,6 +75,8 @@ describe('Telemetry SDK', () => { getSessionId: () => 'test-session', getTelemetryUseCliAuth: () => false, isInteractive: () => false, + getExperiments: () => undefined, + getExperimentsAsync: async () => undefined, } as unknown as Config; }); @@ -353,6 +355,7 @@ describe('Telemetry SDK', () => { expect(callback).not.toHaveBeenCalled(); await initializeTelemetry(mockConfig); + await new Promise((resolve) => setTimeout(resolve, 10)); expect(callback).toHaveBeenCalled(); }); }); diff --git a/packages/core/src/telemetry/telemetryAttributes.ts b/packages/core/src/telemetry/telemetryAttributes.ts index 83593021f9..576f2ee13f 100644 --- a/packages/core/src/telemetry/telemetryAttributes.ts +++ b/packages/core/src/telemetry/telemetryAttributes.ts @@ -14,10 +14,15 @@ const installationManager = new InstallationManager(); export function getCommonAttributes(config: Config): Attributes { const email = userAccountManager.getCachedGoogleAccount(); + const experiments = config.getExperiments(); return { 'session.id': config.getSessionId(), 'installation.id': installationManager.getInstallationId(), interactive: config.isInteractive(), ...(email && { 'user.email': email }), + ...(experiments && + experiments.experimentIds.length > 0 && { + 'experiments.ids': experiments.experimentIds, + }), }; }