abbyswag/qwen-code
1
0
Fork 0
mirror of https://github.com/QwenLM/qwen-code.git synced 2025-12-21 09:17:53 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(client/compression): Log telemetry when compressing chat context. (#6195)

Browse Source
This commit is contained in:
Richie Foreman
2025-08-18 15:59:13 -04:00
committed by GitHub
parent 1a0cc68e29
commit 71f706cf29
14 changed files with 426 additions and 123 deletions
Download Patch File Download Diff File Expand all files Collapse all files

181
packages/core/src/telemetry/clearcut-logger/clearcut-logger.test.ts
View File

@@ -4,6 +4,7 @@
* SPDX-License-Identifier: Apache-2.0
*/
import 'vitest';
import {
vi,
describe,
@@ -13,8 +14,13 @@ import {
beforeAll,
afterAll,
} from 'vitest';
import { ClearcutLogger, LogEventEntry, TEST_ONLY } from './clearcut-logger.js';
import {
ClearcutLogger,
LogEvent,
LogEventEntry,
EventNames,
TEST_ONLY,
} from './clearcut-logger.js';
import { ConfigParameters } from '../../config/config.js';
import * as userAccount from '../../utils/user_account.js';
import * as userId from '../../utils/user_id.js';
@@ -22,6 +28,48 @@ import { EventMetadataKey } from './event-metadata-key.js';
import { makeFakeConfig } from '../../test-utils/config.js';
import { http, HttpResponse } from 'msw';
import { server } from '../../mocks/msw.js';
import { makeChatCompressionEvent } from '../types.js';
interface CustomMatchers<R = unknown> {
toHaveMetadataValue: ([key, value]: [EventMetadataKey, string]) => R;
toHaveEventName: (name: EventNames) => R;
}
declare module 'vitest' {
// eslint-disable-next-line @typescript-eslint/no-explicit-any, @typescript-eslint/no-empty-object-type
interface Matchers<T = any> extends CustomMatchers<T> {}
}
expect.extend({
toHaveEventName(received: LogEventEntry[], name: EventNames) {
const { isNot } = this;
const event = JSON.parse(received[0].source_extension_json) as LogEvent;
const pass = event.event_name === (name as unknown as string);
return {
pass,
message: () =>
`event name ${event.event_name} does${isNot ? ' not ' : ''} match ${name}}`,
};
},
toHaveMetadataValue(
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;
const pass = data !== undefined && data === value;
return {
pass,
message: () =>
`event ${received} does${isNot ? ' not' : ''} have ${value}}`,
};
},
});
vi.mock('../../utils/user_account');
vi.mock('../../utils/user_id');
@@ -47,6 +95,7 @@ describe('ClearcutLogger', () => {
const CLEARCUT_URL = 'https://play.googleapis.com/log';
const MOCK_DATE = new Date('2025-01-02T00:00:00.000Z');
const EXAMPLE_RESPONSE = `["${NEXT_WAIT_MS}",null,[[["ANDROID_BACKUP",0],["BATTERY_STATS",0],["SMART_SETUP",0],["TRON",0]],-3334737594024971225],[]]`;
// A helper to get the internal events array for testing
const getEvents = (l: ClearcutLogger): LogEventEntry[][] =>
l['events'].toArray() as LogEventEntry[][];
@@ -130,7 +179,7 @@ describe('ClearcutLogger', () => {
lifetimeGoogleAccounts: 9001,
});
const event = logger?.createLogEvent('abc', []);
const event = logger?.createLogEvent(EventNames.API_ERROR, []);
expect(event?.event_metadata[0][0]).toEqual({
gemini_cli_key: EventMetadataKey.GEMINI_CLI_GOOGLE_ACCOUNTS_COUNT,
@@ -138,26 +187,13 @@ describe('ClearcutLogger', () => {
});
});
it('logs the current surface from a github action', () => {
const { logger } = setup({});
vi.stubEnv('GITHUB_SHA', '8675309');
const event = logger?.createLogEvent('abc', []);
expect(event?.event_metadata[0][1]).toEqual({
gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE,
value: 'GitHub',
});
});
it('honors the value from env.SURFACE over all others', () => {
it('logs the current surface', () => {
const { logger } = setup({});
vi.stubEnv('TERM_PROGRAM', 'vscode');
vi.stubEnv('SURFACE', 'ide-1234');
const event = logger?.createLogEvent('abc', []);
const event = logger?.createLogEvent(EventNames.API_ERROR, []);
expect(event?.event_metadata[0][1]).toEqual({
gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE,
@@ -209,7 +245,7 @@ describe('ClearcutLogger', () => {
vi.stubEnv(key, value);
}
vi.stubEnv('TERM_PROGRAM', 'vscode');
const event = logger?.createLogEvent('abc', []);
const event = logger?.createLogEvent(EventNames.API_ERROR, []);
expect(event?.event_metadata[0][1]).toEqual({
gemini_cli_key: EventMetadataKey.GEMINI_CLI_SURFACE,
value: expectedValue,
@@ -218,10 +254,34 @@ describe('ClearcutLogger', () => {
);
});
describe('logChatCompressionEvent', () => {
it('logs an event with proper fields', () => {
const { logger } = setup();
logger?.logChatCompressionEvent(
makeChatCompressionEvent({
tokens_before: 9001,
tokens_after: 8000,
}),
);
const events = getEvents(logger!);
expect(events.length).toBe(1);
expect(events[0]).toHaveEventName(EventNames.CHAT_COMPRESSION);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_BEFORE,
'9001',
]);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_AFTER,
'8000',
]);
});
});
describe('enqueueLogEvent', () => {
it('should add events to the queue', () => {
const { logger } = setup();
logger!.enqueueLogEvent({ test: 'event1' });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
expect(getEventsSize(logger!)).toBe(1);
});
@@ -229,27 +289,43 @@ describe('ClearcutLogger', () => {
const { logger } = setup();
for (let i = 0; i < TEST_ONLY.MAX_EVENTS; i++) {
logger!.enqueueLogEvent({ event_id: i });
logger!.enqueueLogEvent(
logger!.createLogEvent(EventNames.API_ERROR, [
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES,
value: `${i}`,
},
]),
);
}
expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_EVENTS);
const firstEvent = JSON.parse(
getEvents(logger!)[0][0].source_extension_json,
);
expect(firstEvent.event_id).toBe(0);
let events = getEvents(logger!);
expect(events.length).toBe(TEST_ONLY.MAX_EVENTS);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES,
'0',
]);
// This should push out the first event
logger!.enqueueLogEvent({ event_id: TEST_ONLY.MAX_EVENTS });
logger!.enqueueLogEvent(
logger!.createLogEvent(EventNames.API_ERROR, [
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES,
value: `${TEST_ONLY.MAX_EVENTS}`,
},
]),
);
events = getEvents(logger!);
expect(events.length).toBe(TEST_ONLY.MAX_EVENTS);
expect(events[0]).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES,
'1',
]);
expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_EVENTS);
const newFirstEvent = JSON.parse(
getEvents(logger!)[0][0].source_extension_json,
);
expect(newFirstEvent.event_id).toBe(1);
const lastEvent = JSON.parse(
getEvents(logger!)[TEST_ONLY.MAX_EVENTS - 1][0].source_extension_json,
);
expect(lastEvent.event_id).toBe(TEST_ONLY.MAX_EVENTS);
expect(events.at(TEST_ONLY.MAX_EVENTS - 1)).toHaveMetadataValue([
EventMetadataKey.GEMINI_CLI_AI_ADDED_LINES,
`${TEST_ONLY.MAX_EVENTS}`,
]);
});
});
@@ -261,7 +337,7 @@ describe('ClearcutLogger', () => {
},
});
logger!.enqueueLogEvent({ event_id: 1 });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
const response = await logger!.flushToClearcut();
@@ -271,7 +347,7 @@ describe('ClearcutLogger', () => {
it('should clear events on successful flush', async () => {
const { logger } = setup();
logger!.enqueueLogEvent({ event_id: 1 });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
const response = await logger!.flushToClearcut();
expect(getEvents(logger!)).toEqual([]);
@@ -282,8 +358,8 @@ describe('ClearcutLogger', () => {
const { logger } = setup();
server.resetHandlers(http.post(CLEARCUT_URL, () => HttpResponse.error()));
logger!.enqueueLogEvent({ event_id: 1 });
logger!.enqueueLogEvent({ event_id: 2 });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_REQUEST));
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
expect(getEventsSize(logger!)).toBe(2);
const x = logger!.flushToClearcut();
@@ -291,7 +367,9 @@ describe('ClearcutLogger', () => {
expect(getEventsSize(logger!)).toBe(2);
const events = getEvents(logger!);
expect(JSON.parse(events[0][0].source_extension_json).event_id).toBe(1);
expect(events.length).toBe(2);
expect(events[0]).toHaveEventName(EventNames.API_REQUEST);
});
it('should handle an HTTP error and requeue events', async () => {
@@ -310,23 +388,22 @@ describe('ClearcutLogger', () => {
),
);
logger!.enqueueLogEvent({ event_id: 1 });
logger!.enqueueLogEvent({ event_id: 2 });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_REQUEST));
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
expect(getEvents(logger!).length).toBe(2);
await logger!.flushToClearcut();
expect(getEvents(logger!).length).toBe(2);
const events = getEvents(logger!);
expect(JSON.parse(events[0][0].source_extension_json).event_id).toBe(1);
expect(events[0]).toHaveEventName(EventNames.API_REQUEST);
});
});
describe('requeueFailedEvents logic', () => {
it('should limit the number of requeued events to max_retry_events', () => {
const { logger } = setup();
const maxRetryEvents = TEST_ONLY.MAX_RETRY_EVENTS;
const eventsToLogCount = maxRetryEvents + 5;
const eventsToLogCount = TEST_ONLY.MAX_RETRY_EVENTS + 5;
const eventsToSend: LogEventEntry[][] = [];
for (let i = 0; i < eventsToLogCount; i++) {
eventsToSend.push([
@@ -339,13 +416,13 @@ describe('ClearcutLogger', () => {
requeueFailedEvents(logger!, eventsToSend);
expect(getEventsSize(logger!)).toBe(maxRetryEvents);
expect(getEventsSize(logger!)).toBe(TEST_ONLY.MAX_RETRY_EVENTS);
const firstRequeuedEvent = JSON.parse(
getEvents(logger!)[0][0].source_extension_json,
);
) as { event_id: string };
// The last `maxRetryEvents` are kept. The oldest of those is at index `eventsToLogCount - maxRetryEvents`.
expect(firstRequeuedEvent.event_id).toBe(
eventsToLogCount - maxRetryEvents,
eventsToLogCount - TEST_ONLY.MAX_RETRY_EVENTS,
);
});
@@ -355,7 +432,7 @@ describe('ClearcutLogger', () => {
const spaceToLeave = 5;
const initialEventCount = maxEvents - spaceToLeave;
for (let i = 0; i < initialEventCount; i++) {
logger!.enqueueLogEvent({ event_id: `initial_${i}` });
logger!.enqueueLogEvent(logger!.createLogEvent(EventNames.API_ERROR));
}
expect(getEventsSize(logger!)).toBe(initialEventCount);
@@ -382,7 +459,7 @@ describe('ClearcutLogger', () => {
// The first element in the deque is the one with id 'failed_5'.
const firstRequeuedEvent = JSON.parse(
getEvents(logger!)[0][0].source_extension_json,
);
) as { event_id: string };
expect(firstRequeuedEvent.event_id).toBe('failed_5');
});
});

85
packages/core/src/telemetry/clearcut-logger/clearcut-logger.ts
View File

@@ -20,6 +20,7 @@ import {
MalformedJsonResponseEvent,
IdeConnectionEvent,
KittySequenceOverflowEvent,
ChatCompressionEvent,
} from '../types.js';
import { EventMetadataKey } from './event-metadata-key.js';
import { Config } from '../../config/config.js';
@@ -33,20 +34,23 @@ import { FixedDeque } from 'mnemonist';
import { GIT_COMMIT_INFO, CLI_VERSION } from '../../generated/git-commit.js';
import { DetectedIde, detectIde } from '../../ide/detect-ide.js';
const start_session_event_name = 'start_session';
const new_prompt_event_name = 'new_prompt';
const tool_call_event_name = 'tool_call';
const api_request_event_name = 'api_request';
const api_response_event_name = 'api_response';
const api_error_event_name = 'api_error';
const end_session_event_name = 'end_session';
const flash_fallback_event_name = 'flash_fallback';
const loop_detected_event_name = 'loop_detected';
const next_speaker_check_event_name = 'next_speaker_check';
const slash_command_event_name = 'slash_command';
const malformed_json_response_event_name = 'malformed_json_response';
const ide_connection_event_name = 'ide_connection';
const kitty_sequence_overflow_event_name = 'kitty_sequence_overflow';
export enum EventNames {
START_SESSION = 'start_session',
NEW_PROMPT = 'new_prompt',
TOOL_CALL = 'tool_call',
API_REQUEST = 'api_request',
API_RESPONSE = 'api_response',
API_ERROR = 'api_error',
END_SESSION = 'end_session',
FLASH_FALLBACK = 'flash_fallback',
LOOP_DETECTED = 'loop_detected',
NEXT_SPEAKER_CHECK = 'next_speaker_check',
SLASH_COMMAND = 'slash_command',
MALFORMED_JSON_RESPONSE = 'malformed_json_response',
IDE_CONNECTION = 'ide_connection',
KITTY_SEQUENCE_OVERFLOW = 'kitty_sequence_overflow',
CHAT_COMPRESSION = 'chat_compression',
}
export interface LogResponse {
nextRequestWaitMs?: number;
@@ -58,7 +62,7 @@ export interface LogEventEntry {
}
export interface EventValue {
gemini_cli_key: EventMetadataKey | string;
gemini_cli_key: EventMetadataKey;
value: string;
}
@@ -168,7 +172,7 @@ export class ClearcutLogger {
ClearcutLogger.instance = undefined;
}
enqueueLogEvent(event: object): void {
enqueueLogEvent(event: LogEvent): void {
try {
// Manually handle overflow for FixedDeque, which throws when full.
const wasAtCapacity = this.events.size >= MAX_EVENTS;
@@ -196,7 +200,7 @@ export class ClearcutLogger {
}
}
createLogEvent(name: string, data: EventValue[]): LogEvent {
createLogEvent(eventName: EventNames, data: EventValue[] = []): LogEvent {
const email = getCachedGoogleAccount();
data = addDefaultFields(data);
@@ -204,7 +208,7 @@ export class ClearcutLogger {
const logEvent: LogEvent = {
console_type: 'GEMINI_CLI',
application: 102, // GEMINI_CLI
event_name: name,
event_name: eventName as string,
event_metadata: [data],
};
@@ -386,7 +390,7 @@ export class ClearcutLogger {
];
// Flush start event immediately
this.enqueueLogEvent(this.createLogEvent(start_session_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.START_SESSION, data));
this.flushToClearcut().catch((error) => {
console.debug('Error flushing to Clearcut:', error);
});
@@ -412,7 +416,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(new_prompt_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.NEW_PROMPT, data));
this.flushIfNeeded();
}
@@ -466,7 +470,7 @@ export class ClearcutLogger {
}
}
const logEvent = this.createLogEvent(tool_call_event_name, data);
const logEvent = this.createLogEvent(EventNames.TOOL_CALL, data);
this.enqueueLogEvent(logEvent);
this.flushIfNeeded();
}
@@ -483,7 +487,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(api_request_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.API_REQUEST, data));
this.flushIfNeeded();
}
@@ -540,7 +544,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(api_response_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.API_RESPONSE, data));
this.flushIfNeeded();
}
@@ -572,10 +576,27 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(api_error_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.API_ERROR, data));
this.flushIfNeeded();
}
logChatCompressionEvent(event: ChatCompressionEvent): void {
const data: EventValue[] = [
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_BEFORE,
value: `${event.tokens_before}`,
},
{
gemini_cli_key: EventMetadataKey.GEMINI_CLI_COMPRESSION_TOKENS_AFTER,
value: `${event.tokens_after}`,
},
];
this.enqueueLogEvent(
this.createLogEvent(EventNames.CHAT_COMPRESSION, data),
);
}
logFlashFallbackEvent(event: FlashFallbackEvent): void {
const data: EventValue[] = [
{
@@ -588,7 +609,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(flash_fallback_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.FLASH_FALLBACK, data));
this.flushToClearcut().catch((error) => {
console.debug('Error flushing to Clearcut:', error);
});
@@ -606,7 +627,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(loop_detected_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.LOOP_DETECTED, data));
this.flushIfNeeded();
}
@@ -631,7 +652,7 @@ export class ClearcutLogger {
];
this.enqueueLogEvent(
this.createLogEvent(next_speaker_check_event_name, data),
this.createLogEvent(EventNames.NEXT_SPEAKER_CHECK, data),
);
this.flushIfNeeded();
}
@@ -658,7 +679,7 @@ export class ClearcutLogger {
});
}
this.enqueueLogEvent(this.createLogEvent(slash_command_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.SLASH_COMMAND, data));
this.flushIfNeeded();
}
@@ -672,7 +693,7 @@ export class ClearcutLogger {
];
this.enqueueLogEvent(
this.createLogEvent(malformed_json_response_event_name, data),
this.createLogEvent(EventNames.MALFORMED_JSON_RESPONSE, data),
);
this.flushIfNeeded();
}
@@ -685,7 +706,7 @@ export class ClearcutLogger {
},
];
this.enqueueLogEvent(this.createLogEvent(ide_connection_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.IDE_CONNECTION, data));
this.flushIfNeeded();
}
@@ -702,7 +723,7 @@ export class ClearcutLogger {
];
this.enqueueLogEvent(
this.createLogEvent(kitty_sequence_overflow_event_name, data),
this.createLogEvent(EventNames.KITTY_SEQUENCE_OVERFLOW, data),
);
this.flushIfNeeded();
}
@@ -716,7 +737,7 @@ export class ClearcutLogger {
];
// Flush immediately on session end.
this.enqueueLogEvent(this.createLogEvent(end_session_event_name, data));
this.enqueueLogEvent(this.createLogEvent(EventNames.END_SESSION, data));
this.flushToClearcut().catch((error) => {
console.debug('Error flushing to Clearcut:', error);
});

15
packages/core/src/telemetry/clearcut-logger/event-metadata-key.ts
View File

@@ -228,17 +228,10 @@ export enum EventMetadataKey {
// Logs the length of the kitty sequence that overflowed.
GEMINI_CLI_KITTY_SEQUENCE_LENGTH = 53,
}
export function getEventMetadataKey(
keyName: string,
): EventMetadataKey | undefined {
// Access the enum member by its string name
const key = EventMetadataKey[keyName as keyof typeof EventMetadataKey];
// Logs the number of tokens before context window compression.
GEMINI_CLI_COMPRESSION_TOKENS_BEFORE = 60,
// Check if the result is a valid enum member (not undefined and is a number)
if (typeof key === 'number') {
return key;
}
return undefined;
// Logs the number of tokens after context window compression.
GEMINI_CLI_COMPRESSION_TOKENS_AFTER = 61,
}