feat(telemetry): persist date of the last tool call. (#2705)

The state file is now loaded into memory and stored within
ClearcutLogger. At each tool call it checks whether it's been more than
one day since the recorded value in the state file, and if so, log the
last tool active, and update the state file.

Regarding the state file's format, lastToolCall is not exactly the very
last one, but rather the last one that was **logged**. This is the same
with the existing lastActive timestamp (i.e. it's not the last timestamp
when the server is active, but rather the last timestamp when the active
status is logged). So here we keep the definitions consistent.

A caveat for future improvement: arguably the loadState() and
writeState() and everything in between should be a atomic unit (there
might be multiple mcp servers running), but I think it's probably good
enough for now. If we see weirdness we can make that happen.

I also added format guards to loadState() so we don't have to try and
catch everywhere else when de-serializing the string. We should actually
just deserialize in loadState() but let me do this in a follow-up CL.
This commit is contained in:
yulunz
2026-09-09 14:54:26 +00:00
committed by GitHub
parent d7d6d31db3
commit c54a49383a
5 changed files with 349 additions and 77 deletions
+78 -21
View File
@@ -44,6 +44,33 @@ function detectOsType(): OsType {
}
}
function isSameDay(d1: Date, d2: Date): boolean {
return (
d1.getUTCFullYear() === d2.getUTCFullYear() &&
d1.getUTCMonth() === d2.getUTCMonth() &&
d1.getUTCDate() === d2.getUTCDate()
);
}
function shouldLogDailyActive(state: LocalState): boolean {
if (!state.lastActive) {
return true;
}
return !isSameDay(new Date(state.lastActive), new Date());
}
function calculateDaysSince(
lastDateString?: string,
now: Date = new Date(),
): number {
if (!lastDateString) {
return -1;
}
const lastDate = new Date(lastDateString);
const diffTime = Math.abs(now.getTime() - lastDate.getTime());
return Math.ceil(diffTime / MS_PER_DAY);
}
export interface ClearcutLoggerOptions {
appVersion: string;
persistence: Persistence;
@@ -61,6 +88,7 @@ export class ClearcutLogger {
#persistence: Persistence;
#watchdog: WatchdogClient;
#mcpClient: McpClient;
#state?: LocalState;
static initialize(options: ClearcutLoggerOptions): ClearcutLogger {
if (_clearcut_logger_instance) {
@@ -92,6 +120,15 @@ export class ClearcutLogger {
clearcutIncludePidHeader: options.clearcutIncludePidHeader,
});
this.#mcpClient = McpClient.MCP_CLIENT_UNSPECIFIED;
void this.#persistence
.loadState()
.then(state => {
this.#state = state;
})
.catch(error => {
this.#state = undefined;
logger?.('Failed to load telemetry state:', error);
});
}
setClientName(clientName: string): void {
@@ -132,6 +169,10 @@ export class ClearcutLogger {
devToolsData?: DevToolsData;
pageUrl?: string;
}): Promise<void> {
void this.#logToolActiveIfNeeded().catch(error => {
logger?.('Error in logToolActiveIfNeeded:', error);
});
const context = buildContext(args.devToolsData, args.pageUrl);
const sanitizedToolName = stripUnderscoreBeforeNumber(args.toolName);
const tool_invocation: ToolInvocation = {
@@ -174,16 +215,10 @@ export class ClearcutLogger {
async logDailyActiveIfNeeded(): Promise<void> {
try {
const state = await this.#persistence.loadState();
this.#state = await this.#persistence.loadState();
if (this.#shouldLogDailyActive(state)) {
let daysSince = -1;
if (state.lastActive) {
const lastActiveDate = new Date(state.lastActive);
const now = new Date();
const diffTime = Math.abs(now.getTime() - lastActiveDate.getTime());
daysSince = Math.ceil(diffTime / MS_PER_DAY);
}
if (shouldLogDailyActive(this.#state)) {
const daysSince = calculateDaysSince(this.#state.lastActive);
this.#watchdog.send({
type: WatchdogMessageType.LOG_EVENT,
@@ -195,8 +230,8 @@ export class ClearcutLogger {
},
});
state.lastActive = new Date().toISOString();
await this.#persistence.saveState(state);
this.#state.lastActive = new Date().toISOString();
await this.#persistence.saveState(this.#state);
}
} catch (err) {
logger?.('Error in logDailyActiveIfNeeded:', err);
@@ -221,19 +256,41 @@ export class ClearcutLogger {
});
}
#shouldLogDailyActive(state: LocalState): boolean {
if (!state.lastActive) {
return true;
async #logToolActiveIfNeeded(): Promise<void> {
// Expect state loaded at first tool call, if not, just skip logging.
if (!this.#state) {
return;
}
const lastActiveDate = new Date(state.lastActive);
// Don't log tool active if it has already been logged today.
const now = new Date();
if (
this.#state.lastToolCall &&
isSameDay(now, new Date(this.#state.lastToolCall))
) {
return;
}
// Compare UTC dates
const isSameDay =
lastActiveDate.getUTCFullYear() === now.getUTCFullYear() &&
lastActiveDate.getUTCMonth() === now.getUTCMonth() &&
lastActiveDate.getUTCDate() === now.getUTCDate();
// Refresh state in case it now contains more recent value, and test again.
const state = await this.#persistence.loadState();
this.#state = state;
if (state.lastToolCall && isSameDay(now, new Date(state.lastToolCall))) {
return;
}
return !isSameDay;
const daysSinceToolCall = calculateDaysSince(state.lastToolCall, now);
this.#watchdog.send({
type: WatchdogMessageType.LOG_EVENT,
payload: {
mcp_client: this.#mcpClient,
tool_active: {
days_since_last_tool_call: bucketizeDaysSince(daysSinceToolCall),
},
},
});
this.#state.lastToolCall = now.toISOString();
await this.#persistence.saveState(this.#state);
}
}
+22 -8
View File
@@ -15,7 +15,22 @@ import {ClearcutLogger} from './ClearcutLogger.js';
import {ErrorCode} from './errors.js';
export interface LocalState {
lastActive: string; // ISO 8601 UTC date string
lastActive?: string; // ISO 8601 UTC date string
lastToolCall?: string; // ISO 8601 UTC date string
}
function isValidTime(time?: unknown): boolean {
if (time === undefined) {
return true;
}
if (typeof time !== 'string' || time === '') {
return false;
}
return !Number.isNaN(new Date(time).getTime());
}
function isContextValid(state: LocalState): boolean {
return isValidTime(state.lastActive) && isValidTime(state.lastToolCall);
}
const STATE_FILE_NAME = 'telemetry_state.json';
@@ -58,23 +73,22 @@ export class FilePersistence implements Persistence {
await fs.access(filePath);
} catch {
// File doesn't exist. Not an error because new users do not have the state file.
return {
lastActive: '',
};
return {};
}
let state;
try {
const content = await fs.readFile(filePath, 'utf-8');
return JSON.parse(content) as LocalState;
state = JSON.parse(content) as LocalState;
} catch (error) {
logger?.(`Failed to read telemetry state from ${filePath}:`, error);
void ClearcutLogger.get()?.logServerError({
errorCode: ErrorCode.ERROR_CODE_PERSISTENCE_FILE_READ_FAILED,
});
return {
lastActive: '',
};
return {};
}
return isContextValid(state) ? state : {};
}
async saveState(state: LocalState): Promise<void> {
+5
View File
@@ -17,6 +17,7 @@ export interface ChromeDevToolsMcpExtension {
daily_active?: DailyActive;
server_shutdown?: ServerShutdown;
server_error?: ServerError;
tool_active?: ToolActive;
}
export interface ServerError {
@@ -53,6 +54,10 @@ export interface DailyActive {
days_since_last_active: number;
}
export interface ToolActive {
days_since_last_tool_call: number;
}
export type FlagUsage = Record<string, boolean | string | number | undefined>;
// Clearcut API interfaces
+188 -31
View File
@@ -25,9 +25,7 @@ describe('ClearcutLogger', () => {
beforeEach(() => {
ClearcutLogger.resetForTesting();
mockPersistence = sinon.createStubInstance(FilePersistence, {
loadState: Promise.resolve({
lastActive: '',
}),
loadState: Promise.resolve({}),
});
mockWatchdogClient = sinon.createStubInstance(WatchdogClient);
});
@@ -52,7 +50,7 @@ describe('ClearcutLogger', () => {
latencyMs: 123,
});
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.strictEqual(msg.payload.tool_invocation?.tool_name, 'test_tool');
@@ -77,7 +75,7 @@ describe('ClearcutLogger', () => {
pageUrl: 'https://example.com',
});
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.deepStrictEqual(msg.payload.tool_invocation?.context, {
@@ -113,7 +111,7 @@ describe('ClearcutLogger', () => {
latencyMs: 123,
});
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.deepStrictEqual(msg.payload.tool_invocation?.tool_params, {
@@ -154,10 +152,15 @@ describe('ClearcutLogger', () => {
logger.setClientName(name);
await logger.logServerStart({headless: true});
assert(mockWatchdogClient.send.calledOnce);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.strictEqual(msg.payload.mcp_client, expected);
sinon.assert.calledOnceWithExactly(mockWatchdogClient.send, {
type: WatchdogMessageType.LOG_EVENT,
payload: {
mcp_client: expected,
server_start: {
flag_usage: {headless: true},
},
},
});
});
}
});
@@ -175,9 +178,7 @@ describe('ClearcutLogger', () => {
errorCode: ErrorCode.ERROR_CODE_UNSPECIFIED,
});
assert(mockWatchdogClient.send.calledOnce);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.deepStrictEqual(msg, {
sinon.assert.calledOnceWithExactly(mockWatchdogClient.send, {
type: WatchdogMessageType.LOG_EVENT,
payload: {
mcp_client: McpClient.MCP_CLIENT_UNSPECIFIED,
@@ -200,9 +201,7 @@ describe('ClearcutLogger', () => {
errorCode: ErrorCode.ERROR_CODE_UNSPECIFIED,
});
assert(mockWatchdogClient.send.calledOnce);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.deepStrictEqual(msg, {
sinon.assert.calledOnceWithExactly(mockWatchdogClient.send, {
type: WatchdogMessageType.LOG_EVENT,
payload: {
mcp_client: McpClient.MCP_CLIENT_UNSPECIFIED,
@@ -225,10 +224,15 @@ describe('ClearcutLogger', () => {
await logger.logServerStart({headless: true});
assert(mockWatchdogClient.send.calledOnce);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.strictEqual(msg.payload.server_start?.flag_usage?.headless, true);
sinon.assert.calledOnceWithExactly(mockWatchdogClient.send, {
type: WatchdogMessageType.LOG_EVENT,
payload: {
mcp_client: McpClient.MCP_CLIENT_UNSPECIFIED,
server_start: {
flag_usage: {headless: true},
},
},
});
});
});
@@ -249,13 +253,13 @@ describe('ClearcutLogger', () => {
await logger.logDailyActiveIfNeeded();
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.ok(msg.payload.daily_active);
assert.ok(msg.payload.daily_active.days_since_last_active !== undefined);
assert(mockPersistence.saveState.called);
sinon.assert.called(mockPersistence.saveState);
});
it('caps days_since_last_active at 31 if lastActive was > 30 days ago', async () => {
@@ -273,11 +277,11 @@ describe('ClearcutLogger', () => {
await logger.logDailyActiveIfNeeded();
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.strictEqual(msg.payload.daily_active?.days_since_last_active, 31);
assert(mockPersistence.saveState.called);
sinon.assert.called(mockPersistence.saveState);
});
it('does not log daily active if not needed (today)', async () => {
@@ -293,14 +297,12 @@ describe('ClearcutLogger', () => {
await logger.logDailyActiveIfNeeded();
assert(mockWatchdogClient.send.notCalled);
assert(mockPersistence.saveState.notCalled);
sinon.assert.notCalled(mockWatchdogClient.send);
sinon.assert.notCalled(mockPersistence.saveState);
});
it('logs daily active with -1 if lastActive is missing', async () => {
mockPersistence.loadState.resolves({
lastActive: '',
});
mockPersistence.loadState.resolves({});
const logger = ClearcutLogger.initialize({
persistence: mockPersistence,
@@ -310,11 +312,166 @@ describe('ClearcutLogger', () => {
await logger.logDailyActiveIfNeeded();
assert(mockWatchdogClient.send.calledOnce);
sinon.assert.calledOnce(mockWatchdogClient.send);
const msg = mockWatchdogClient.send.firstCall.args[0];
assert.strictEqual(msg.type, WatchdogMessageType.LOG_EVENT);
assert.strictEqual(msg.payload.daily_active?.days_since_last_active, -1);
assert(mockPersistence.saveState.called);
sinon.assert.called(mockPersistence.saveState);
});
});
describe('tool_active logging', () => {
it('logs tool active with -1 on first tool call when lastToolCall is not set', async () => {
mockPersistence.loadState.resolves({});
const logger = ClearcutLogger.initialize({
persistence: mockPersistence,
appVersion: '1.0.0',
watchdogClient: mockWatchdogClient,
});
// Wait for initial loadState to populate #state
await Promise.resolve();
await logger.logToolInvocation({
toolName: 'test_tool',
params: {},
schema: {},
success: true,
latencyMs: 100,
});
await new Promise(resolve => setTimeout(resolve, 10));
sinon.assert.callCount(mockWatchdogClient.send, 2);
const activeCall = mockWatchdogClient.send.args.find(
args => args[0].payload.tool_active !== undefined,
);
assert.ok(activeCall);
assert.strictEqual(
activeCall[0].payload.tool_active?.days_since_last_tool_call,
-1,
);
const invocationCall = mockWatchdogClient.send.args.find(
args => args[0].payload.tool_invocation !== undefined,
);
assert.ok(invocationCall);
assert.strictEqual(
invocationCall[0].payload.tool_invocation?.tool_name,
'test_tool',
);
sinon.assert.calledOnce(mockPersistence.saveState);
const savedState = mockPersistence.saveState.firstCall.args[0];
assert.ok(savedState.lastToolCall);
});
it('does not log tool active on subsequent tool calls on the same day', async () => {
mockPersistence.loadState.resolves({
lastToolCall: new Date().toISOString(),
});
const logger = ClearcutLogger.initialize({
persistence: mockPersistence,
appVersion: '1.0.0',
watchdogClient: mockWatchdogClient,
});
await Promise.resolve();
await logger.logToolInvocation({
toolName: 'test_tool',
params: {},
schema: {},
success: true,
latencyMs: 100,
});
await new Promise(resolve => setTimeout(resolve, 10));
sinon.assert.calledOnce(mockWatchdogClient.send);
assert.strictEqual(
mockWatchdogClient.send.firstCall.args[0].payload.tool_invocation
?.tool_name,
'test_tool',
);
sinon.assert.notCalled(mockPersistence.saveState);
});
it('caps days_since_last_tool_call at 31 if lastToolCall was > 30 days ago', async () => {
const fortyDaysAgo = new Date();
fortyDaysAgo.setDate(fortyDaysAgo.getDate() - 40);
mockPersistence.loadState.resolves({
lastToolCall: fortyDaysAgo.toISOString(),
});
const logger = ClearcutLogger.initialize({
persistence: mockPersistence,
appVersion: '1.0.0',
watchdogClient: mockWatchdogClient,
});
await Promise.resolve();
await logger.logToolInvocation({
toolName: 'test_tool',
params: {},
schema: {},
success: true,
latencyMs: 100,
});
await new Promise(resolve => setTimeout(resolve, 10));
sinon.assert.callCount(mockWatchdogClient.send, 2);
const activeCall = mockWatchdogClient.send.args.find(
args => args[0].payload.tool_active !== undefined,
);
assert.ok(activeCall);
assert.strictEqual(
activeCall[0].payload.tool_active?.days_since_last_tool_call,
31,
);
});
it('deduplicates when another process updated the state file to today', async () => {
const yesterday = new Date();
yesterday.setDate(yesterday.getDate() - 1);
mockPersistence.loadState.onFirstCall().resolves({
lastToolCall: yesterday.toISOString(),
});
mockPersistence.loadState.onSecondCall().resolves({
lastToolCall: new Date().toISOString(),
});
const logger = ClearcutLogger.initialize({
persistence: mockPersistence,
appVersion: '1.0.0',
watchdogClient: mockWatchdogClient,
});
await Promise.resolve();
await logger.logToolInvocation({
toolName: 'test_tool',
params: {},
schema: {},
success: true,
latencyMs: 100,
});
await new Promise(resolve => setTimeout(resolve, 10));
sinon.assert.calledOnce(mockWatchdogClient.send);
assert.strictEqual(
mockWatchdogClient.send.firstCall.args[0].payload.tool_invocation
?.tool_name,
'test_tool',
);
sinon.assert.notCalled(mockPersistence.saveState);
});
});
+56 -17
View File
@@ -49,10 +49,8 @@ describe('FilePersistence', () => {
it('returns default state and does NOT log telemetry if file does not exist (ENOENT)', async () => {
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {
lastActive: '',
});
assert(logServerErrorStub.notCalled);
assert.deepStrictEqual(state, {});
sinon.assert.notCalled(logServerErrorStub);
});
it('returns default state and LOGS telemetry if load fails due to corruption', async () => {
@@ -62,11 +60,8 @@ describe('FilePersistence', () => {
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {
lastActive: '',
});
assert(logServerErrorStub.calledOnce);
assert.deepStrictEqual(logServerErrorStub.firstCall.args[0], {
assert.deepStrictEqual(state, {});
sinon.assert.calledOnceWithExactly(logServerErrorStub, {
errorCode: ErrorCode.ERROR_CODE_PERSISTENCE_FILE_READ_FAILED,
});
});
@@ -82,20 +77,64 @@ describe('FilePersistence', () => {
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {
lastActive: '',
});
assert(logServerErrorStub.calledOnce);
assert.deepStrictEqual(logServerErrorStub.firstCall.args[0], {
assert.deepStrictEqual(state, {});
sinon.assert.calledOnceWithExactly(logServerErrorStub, {
errorCode: ErrorCode.ERROR_CODE_PERSISTENCE_FILE_READ_FAILED,
});
readFileStub.restore();
});
it('returns default state and LOGS telemetry if state file is empty', async () => {
const filePath = path.join(tmpDir, 'telemetry_state.json');
await fs.writeFile(filePath, '', 'utf-8');
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {});
sinon.assert.calledOnceWithExactly(logServerErrorStub, {
errorCode: ErrorCode.ERROR_CODE_PERSISTENCE_FILE_READ_FAILED,
});
});
it('returns default state if lastActive is invalid date string', async () => {
const filePath = path.join(tmpDir, 'telemetry_state.json');
await fs.writeFile(
filePath,
JSON.stringify({lastActive: 'invalid-date'}),
'utf-8',
);
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {});
sinon.assert.notCalled(logServerErrorStub);
});
it('returns default state if lastToolCall is invalid date string', async () => {
const filePath = path.join(tmpDir, 'telemetry_state.json');
await fs.writeFile(
filePath,
JSON.stringify({
lastActive: '2023-01-01T00:00:00.000Z',
lastToolCall: 'invalid-date',
}),
'utf-8',
);
const filePersistence = new persistence.FilePersistence(tmpDir);
const state = await filePersistence.loadState();
assert.deepStrictEqual(state, {});
sinon.assert.notCalled(logServerErrorStub);
});
it('returns stored state if file exists', async () => {
const expectedState = {
lastActive: '2023-01-01T00:00:00.000Z',
lastToolCall: '2023-01-01T12:00:00.000Z',
};
await fs.writeFile(
path.join(tmpDir, 'telemetry_state.json'),
@@ -112,6 +151,7 @@ describe('FilePersistence', () => {
it('saves state to file', async () => {
const state = {
lastActive: '2023-01-01T00:00:00.000Z',
lastToolCall: '2023-01-01T12:00:00.000Z',
};
const filePersistence = new persistence.FilePersistence(tmpDir);
await filePersistence.saveState(state);
@@ -121,7 +161,7 @@ describe('FilePersistence', () => {
'utf-8',
);
assert.deepStrictEqual(JSON.parse(content), state);
assert(logServerErrorStub.notCalled);
sinon.assert.notCalled(logServerErrorStub);
});
it('logs telemetry when failing to save to file', async () => {
@@ -135,8 +175,7 @@ describe('FilePersistence', () => {
};
await filePersistence.saveState(state);
assert(logServerErrorStub.calledOnce);
assert.deepStrictEqual(logServerErrorStub.firstCall.args[0], {
sinon.assert.calledOnceWithExactly(logServerErrorStub, {
errorCode: ErrorCode.ERROR_CODE_PERSISTENCE_FILE_SAVE_FAILED,
});
});