From f5d0b4fd497bdf214450d96fb3b83d57136e93f8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Max=20Paulus=20=F0=9F=A5=AA?= Date: Wed, 3 Jun 2026 08:46:16 -0700 Subject: [PATCH] add migration telemetry --- apps/vscode/src/sdk/SdkController.ts | 1 + apps/vscode/src/sdk/sdk-task-history.test.ts | 104 ++++++++++++- apps/vscode/src/sdk/sdk-task-history.ts | 108 ++++++++++--- .../services/telemetry/TelemetryService.ts | 145 ++++++++++++++++++ .../TelemetryService.metrics.test.ts | 43 ++++++ 5 files changed, 378 insertions(+), 23 deletions(-) diff --git a/apps/vscode/src/sdk/SdkController.ts b/apps/vscode/src/sdk/SdkController.ts index 4bfab328f3..c000c43ea0 100644 --- a/apps/vscode/src/sdk/SdkController.ts +++ b/apps/vscode/src/sdk/SdkController.ts @@ -309,6 +309,7 @@ export class Controller { this.taskHistory = new SdkTaskHistory({ mcpHub: this.mcpHub, sessions: this.sessions, + telemetry: telemetryService, // History rendering mints ids from the shared authority so regenerated history ids // never overlap live-session ids. getMinter: () => this.messageTranslatorState.getMinter(), diff --git a/apps/vscode/src/sdk/sdk-task-history.test.ts b/apps/vscode/src/sdk/sdk-task-history.test.ts index f85a945fe8..2eee8761ec 100644 --- a/apps/vscode/src/sdk/sdk-task-history.test.ts +++ b/apps/vscode/src/sdk/sdk-task-history.test.ts @@ -2,6 +2,7 @@ import type { SessionHistoryRecord } from "@cline/core" import type { HistoryItem } from "@shared/HistoryItem" import { afterEach, beforeEach, describe, expect, it, vi } from "vitest" import type { McpHub } from "@/services/mcp/McpHub" +import type { TelemetryService } from "@/services/telemetry/TelemetryService" import { sdkMessagesToClineMessages } from "./message-translator" import type { SdkSessionLifecycle } from "./sdk-session-lifecycle" import { SdkTaskHistory, sessionHistoryRecordToHistoryItem } from "./sdk-task-history" @@ -26,6 +27,11 @@ vi.mock("@/utils/fs", () => ({ fileExistsAtPath: vi.fn(() => Promise.resolve(false)), })) +const legacyStateReaderMock = vi.hoisted(() => ({ + taskHistory: [] as HistoryItem[], + apiConversationHistory: [] as unknown[], +})) + vi.mock("@/shared/services/Logger", () => ({ Logger: { error: vi.fn(), @@ -34,8 +40,20 @@ vi.mock("@/shared/services/Logger", () => ({ }, })) +vi.mock("./legacy-state-reader", () => ({ + readTaskHistory: vi.fn(() => legacyStateReaderMock.taskHistory), + readApiConversationHistory: vi.fn(() => legacyStateReaderMock.apiConversationHistory), +})) + +vi.mock("./cline-session-factory", async (importOriginal) => ({ + ...(await importOriginal()), + buildSessionConfig: vi.fn(async ({ cwd, workspaceRoot, mode }) => ({ cwd, workspaceRoot, mode })), +})) + describe("SdkTaskHistory", () => { beforeEach(() => { + legacyStateReaderMock.taskHistory = [] + legacyStateReaderMock.apiConversationHistory = [] vi.clearAllMocks() }) @@ -213,6 +231,74 @@ describe("SdkTaskHistory", () => { expect(deleteSession).toHaveBeenCalledWith("task-1") }) + it("emits telemetry when migrating a legacy task to an SDK session", async () => { + vi.spyOn(Date, "now").mockReturnValue(123_456) + legacyStateReaderMock.taskHistory = [ + makeHistoryItem("legacy-task", { + task: "legacy prompt", + isFavorited: true, + tokensIn: 10, + tokensOut: 20, + totalCost: 0.03, + cwdOnTaskInitialization: "/legacy/repo", + }), + ] + legacyStateReaderMock.apiConversationHistory = [ + { role: "user", content: "legacy prompt" }, + { role: "assistant", content: "legacy answer" }, + ] + const telemetry = makeTelemetry() + const { history, startSession } = makeHistory([], telemetry) + + await history.getClineMessages("legacy-task") + + expect(startSession).toHaveBeenCalledWith( + expect.objectContaining({ + config: expect.objectContaining({ sessionId: "legacy-task", cwd: "/legacy/repo" }), + initialMessages: expect.arrayContaining([ + expect.objectContaining({ role: "user" }), + expect.objectContaining({ role: "assistant" }), + ]), + sessionMetadata: expect.objectContaining({ + migratedFromLegacyTask: true, + title: "legacy prompt", + isFavorited: true, + }), + }), + ) + expect(telemetry.captureLegacyTaskMigration).toHaveBeenCalledWith( + expect.objectContaining({ + taskId: "legacy-task", + outcome: "success", + reason: "migrated", + legacyApiHistoryLength: 2, + convertedMessageCount: 2, + hasFavorite: true, + hasCost: true, + hasTokenUsage: true, + hasCwd: true, + }), + ) + }) + + it("emits backlog telemetry when legacy tasks are still pending migration", async () => { + legacyStateReaderMock.taskHistory = [makeHistoryItem("legacy-task", { task: "legacy prompt" })] + const telemetry = makeTelemetry() + const { history } = makeHistory( + [makeSessionRecord("sdk-task"), makeSessionRecord("migrated", { metadata: { migratedFromLegacyTask: true } })], + telemetry, + ) + + await history.listHistory({ hydrate: false }) + + expect(telemetry.captureLegacyTaskMigrationBacklog).toHaveBeenCalledWith({ + pendingLegacyTaskCount: 1, + migratedSdkTaskCount: 1, + visibleSdkTaskCount: 2, + visibleTaskCount: 3, + }) + }) + it("updates usage for an existing SDK task", async () => { vi.spyOn(Date, "now").mockReturnValue(123_456) const { history, updateSession } = makeHistory([ @@ -277,7 +363,15 @@ function makeSessionRecord(id: string, overrides: Partial } } -function makeHistory(records: SessionHistoryRecord[]) { +function makeTelemetry(): TelemetryService { + return { + safeCapture: vi.fn((fn: () => void) => fn()), + captureLegacyTaskMigration: vi.fn(), + captureLegacyTaskMigrationBacklog: vi.fn(), + } as unknown as TelemetryService +} + +function makeHistory(records: SessionHistoryRecord[], telemetry?: TelemetryService) { let currentRecords = records const updateSession = vi.fn( async ( @@ -299,10 +393,15 @@ function makeHistory(records: SessionHistoryRecord[]) { const getSession = vi.fn(async (sessionId: string) => currentRecords.find((record) => record.sessionId === sessionId)) const listHistory = vi.fn(async () => currentRecords) const readMessages = vi.fn(async () => []) + const startSession = vi.fn(async (input: { config: { sessionId?: string } }) => { + currentRecords = [makeSessionRecord(input.config.sessionId ?? "started"), ...currentRecords] + return { sessionId: input.config.sessionId } + }) const host = { get: getSession, listHistory, readMessages, + start: startSession, update: updateSession, delete: deleteSession, } as unknown as VscodeSessionHost @@ -312,7 +411,8 @@ function makeHistory(records: SessionHistoryRecord[]) { const history = new SdkTaskHistory({ mcpHub: {} as McpHub, sessions, + telemetry, }) - return { history, getSession, listHistory, updateSession, deleteSession } + return { history, getSession, listHistory, updateSession, deleteSession, startSession } } diff --git a/apps/vscode/src/sdk/sdk-task-history.ts b/apps/vscode/src/sdk/sdk-task-history.ts index 1e96500585..d55dd967af 100644 --- a/apps/vscode/src/sdk/sdk-task-history.ts +++ b/apps/vscode/src/sdk/sdk-task-history.ts @@ -4,6 +4,7 @@ import { type ContentBlock, formatDisplayUserInput, type MessageWithMetadata } f import type { ClineMessage } from "@shared/ExtensionMessage" import type { HistoryItem } from "@shared/HistoryItem" import type { McpHub } from "@/services/mcp/McpHub" +import type { TelemetryService } from "@/services/telemetry/TelemetryService" import { Logger } from "@/shared/services/Logger" import { buildSessionConfig } from "./cline-session-factory" import { sanitizeInitialMessagesForSessionStart } from "./initial-message-sanitizer" @@ -39,6 +40,7 @@ export interface SdkTaskHistoryOptions { * it so regenerated history ids never overlap live-session ids. Optional for tests. */ getMinter?: () => MessageIdMinter + telemetry?: TelemetryService } type SdkTaskHistoryListOptions = ClineCoreListHistoryOptions & { @@ -68,6 +70,10 @@ function dateStringToTimestamp(value: string | null | undefined): number { return Number.isFinite(timestamp) ? timestamp : 0 } +function historyItemHasTokenUsage(item: HistoryItem): boolean { + return (item.tokensIn ?? 0) > 0 || (item.tokensOut ?? 0) > 0 || (item.cacheReads ?? 0) > 0 || (item.cacheWrites ?? 0) > 0 +} + function historyItemToSessionHistoryRecord(item: HistoryItem): SessionHistoryRecord { const startedAt = new Date(item.ts || Date.now()).toISOString() const displayTask = formatDisplayUserInput(item.task) @@ -369,6 +375,9 @@ export class SdkTaskHistory { const legacyHistory = readTaskHistory() .filter((item) => item.id && item.task && !sdkIds.has(item.id)) .map(historyItemToSessionHistoryRecord) + const migratedSdkTaskCount = visibleSdkHistory.filter( + (item) => metadataBoolean(item.metadata, "migratedFromLegacyTask") === true, + ).length const mergedHistory = [...visibleSdkHistory, ...legacyHistory].sort( (a, b) => @@ -379,6 +388,17 @@ export class SdkTaskHistory { this.metadataHistoryCache = { records: mergedHistory, hostLimit, createdAt: Date.now() } } + this.options.telemetry?.safeCapture( + () => + this.options.telemetry?.captureLegacyTaskMigrationBacklog({ + pendingLegacyTaskCount: legacyHistory.length, + migratedSdkTaskCount, + visibleSdkTaskCount: visibleSdkHistory.length, + visibleTaskCount: mergedHistory.length, + }), + "SdkTaskHistory.listHistory.legacyMigrationBacklog", + ) + const result = mergedHistory.slice(offset, offset + limit) return result } @@ -394,56 +414,102 @@ export class SdkTaskHistory { } private async migrateLegacyTaskIfNeeded(taskId: string): Promise { + const startedAt = Date.now() + let sdkLookupFailed = false + let historyItem: HistoryItem | undefined + let legacyApiHistoryLength: number | undefined + let convertedMessageCount: number | undefined + + const emitMigrationTelemetry = (args: { outcome: "success" | "skipped" | "error"; reason: string }) => { + const payload = { + taskId, + outcome: args.outcome, + reason: args.reason, + durationMs: Date.now() - startedAt, + legacyApiHistoryLength, + convertedMessageCount, + sdkLookupFailed, + hasFavorite: historyItem?.isFavorited === true, + hasCost: (historyItem?.totalCost ?? 0) > 0, + hasTokenUsage: historyItem ? historyItemHasTokenUsage(historyItem) : undefined, + hasCwd: !!historyItem?.cwdOnTaskInitialization, + } + Logger.log("[SdkTaskHistory] Legacy task migration", payload) + this.options.telemetry?.safeCapture( + () => this.options.telemetry?.captureLegacyTaskMigration(payload), + "SdkTaskHistory.migrateLegacyTaskIfNeeded", + ) + } + return this.withHistoryHost(async (host) => { try { const existing = await host.get(taskId) if (existing) { + emitMigrationTelemetry({ outcome: "skipped", reason: "sdk_exists" }) return false } } catch (error) { + sdkLookupFailed = true Logger.warn(`[SdkTaskHistory] Failed to check SDK session before legacy migration: ${taskId}`, error) } - const historyItem = readTaskHistory().find((item) => item.id === taskId) + historyItem = readTaskHistory().find((item) => item.id === taskId) if (!historyItem) { + emitMigrationTelemetry({ outcome: "skipped", reason: "legacy_history_missing" }) return false } const legacyApiHistory = readApiConversationHistory(taskId) + legacyApiHistoryLength = legacyApiHistory.length if (legacyApiHistory.length === 0) { + emitMigrationTelemetry({ outcome: "skipped", reason: "legacy_api_history_empty" }) return false } const initialMessages = legacyApiHistoryToSdkMessages(legacyApiHistory, historyItem) + convertedMessageCount = initialMessages.length if (initialMessages.length === 0) { + emitMigrationTelemetry({ outcome: "skipped", reason: "converted_messages_empty" }) return false } const cwd = historyItem.cwdOnTaskInitialization || process.cwd() - const config = await buildSessionConfig({ cwd, workspaceRoot: cwd, mode: "act" }) - config.sessionId = taskId + let config: Awaited> + try { + config = await buildSessionConfig({ cwd, workspaceRoot: cwd, mode: "act" }) + config.sessionId = taskId + } catch (error) { + emitMigrationTelemetry({ outcome: "error", reason: "config_failed" }) + throw error + } - await host.start({ - config, - prompt: undefined, - interactive: true, - initialMessages, - sessionMetadata: { - title: historyItem.task, - isFavorited: historyItem.isFavorited ?? false, - size: historyItem.size ?? 0, - totalCost: historyItem.totalCost ?? 0, - tokensIn: historyItem.tokensIn ?? 0, - tokensOut: historyItem.tokensOut ?? 0, - cacheWrites: historyItem.cacheWrites ?? 0, - cacheReads: historyItem.cacheReads ?? 0, - modelId: historyItem.modelId ?? "", - migratedFromLegacyTask: true, - }, - }) + try { + await host.start({ + config, + prompt: undefined, + interactive: true, + initialMessages, + sessionMetadata: { + title: historyItem.task, + isFavorited: historyItem.isFavorited ?? false, + size: historyItem.size ?? 0, + totalCost: historyItem.totalCost ?? 0, + tokensIn: historyItem.tokensIn ?? 0, + tokensOut: historyItem.tokensOut ?? 0, + cacheWrites: historyItem.cacheWrites ?? 0, + cacheReads: historyItem.cacheReads ?? 0, + modelId: historyItem.modelId ?? "", + migratedFromLegacyTask: true, + }, + }) + } catch (error) { + emitMigrationTelemetry({ outcome: "error", reason: "write_failed" }) + throw error + } this.invalidateMetadataHistoryCache() Logger.log(`[SdkTaskHistory] Migrated legacy task to SDK session: ${taskId}`) + emitMigrationTelemetry({ outcome: "success", reason: "migrated" }) return true }) } diff --git a/apps/vscode/src/services/telemetry/TelemetryService.ts b/apps/vscode/src/services/telemetry/TelemetryService.ts index c6a520a808..a634bbc491 100644 --- a/apps/vscode/src/services/telemetry/TelemetryService.ts +++ b/apps/vscode/src/services/telemetry/TelemetryService.ts @@ -193,6 +193,26 @@ export class TelemetryService { GRPC: { RESPONSE_SIZE_BYTES: "cline.grpc.response.size_bytes", }, + MIGRATION: { + // Fires whenever Cline checks an old pre-SDK task and decides whether/how to migrate it. + LEGACY_TASK_ATTEMPTS_TOTAL: "cline.migration.legacy_task.attempts.total", + // Fires when the user opens an old task and Cline successfully copies it into SDK session storage. + LEGACY_TASK_SUCCESS_TOTAL: "cline.migration.legacy_task.success.total", + // Fires when Cline tried to migrate an old task but failed while building or writing the SDK session. + LEGACY_TASK_FAILURES_TOTAL: "cline.migration.legacy_task.failures.total", + // Fires when no migration happens because it is unnecessary or impossible, e.g. already migrated or missing old messages. + LEGACY_TASK_SKIPPED_TOTAL: "cline.migration.legacy_task.skipped.total", + // Fires for every migration decision; measures how long the check/migration took. + LEGACY_TASK_DURATION_SECONDS: "cline.migration.legacy_task.duration.seconds", + // Fires when Cline finds old conversation messages; records how many old messages were found. + LEGACY_TASK_LEGACY_MESSAGES_COUNT: "cline.migration.legacy_task.legacy_messages.count", + // Fires after conversion; records how many messages made it into SDK-compatible form. + LEGACY_TASK_CONVERTED_MESSAGES_COUNT: "cline.migration.legacy_task.converted_messages.count", + // Fires when history is listed; counts old pre-SDK tasks still waiting to be migrated. + LEGACY_TASK_PENDING_COUNT: "cline.migration.legacy_task.pending.count", + // Fires when history is listed; counts old tasks that already made it safely into SDK session storage. + LEGACY_TASK_MIGRATED_COUNT: "cline.migration.legacy_task.migrated.count", + }, } // Event constants for tracking user interactions and system events private static readonly EVENTS = { @@ -250,6 +270,8 @@ export class TelemetryService { MCP_TOOL_CALLED: "task.mcp_tool_called", // Tracks when a historical task is loaded from storage HISTORICAL_LOADED: "task.historical_loaded", + // Tracks legacy VS Code task history migration into SDK sessions + LEGACY_TASK_MIGRATION: "task.legacy_task_migration", // Tracks when the retry button is clicked for failed operations RETRY_CLICKED: "task.retry_clicked", // Tracks when a diff edit (replace_in_file) operation fails @@ -2376,6 +2398,129 @@ export class TelemetryService { * @param method The gRPC method name * @param requestId Optional request ID for correlation */ + public captureLegacyTaskMigration(args: { + taskId: string + outcome: "success" | "skipped" | "error" + reason: string + durationMs: number + legacyApiHistoryLength?: number + convertedMessageCount?: number + sdkLookupFailed?: boolean + hasFavorite?: boolean + hasCost?: boolean + hasTokenUsage?: boolean + hasCwd?: boolean + }): void { + const migrationType = "legacy_task_to_sdk_session" + const metricAttributes = { + migration_type: migrationType, + outcome: args.outcome, + reason: args.reason, + } + + this.capture({ + event: TelemetryService.EVENTS.TASK.LEGACY_TASK_MIGRATION, + properties: { + ulid: args.taskId, + migration_type: migrationType, + outcome: args.outcome, + reason: args.reason, + durationMs: args.durationMs, + legacyApiHistoryLength: args.legacyApiHistoryLength, + convertedMessageCount: args.convertedMessageCount, + sdkLookupFailed: args.sdkLookupFailed, + hasFavorite: args.hasFavorite, + hasCost: args.hasCost, + hasTokenUsage: args.hasTokenUsage, + hasCwd: args.hasCwd, + }, + }) + + this.recordCounter( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_ATTEMPTS_TOTAL, + 1, + metricAttributes, + "Legacy VS Code task migration decisions", + ) + if (args.outcome === "success") { + this.recordCounter( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_SUCCESS_TOTAL, + 1, + metricAttributes, + "Legacy VS Code tasks successfully copied into SDK session storage", + ) + } else if (args.outcome === "error") { + this.recordCounter( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_FAILURES_TOTAL, + 1, + metricAttributes, + "Legacy VS Code task migrations that failed while building or writing the SDK session", + ) + } else { + this.recordCounter( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_SKIPPED_TOTAL, + 1, + metricAttributes, + "Legacy VS Code task migration checks that did not need or could not perform a migration", + ) + } + + this.recordHistogram( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_DURATION_SECONDS, + args.durationMs / 1000, + metricAttributes, + "Time spent checking or migrating a legacy VS Code task into SDK session storage", + ) + if (args.legacyApiHistoryLength !== undefined) { + this.recordHistogram( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_LEGACY_MESSAGES_COUNT, + args.legacyApiHistoryLength, + metricAttributes, + "Number of raw legacy API history messages found while migrating a legacy VS Code task", + ) + } + if (args.convertedMessageCount !== undefined) { + this.recordHistogram( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_CONVERTED_MESSAGES_COUNT, + args.convertedMessageCount, + metricAttributes, + "Number of SDK-compatible messages produced from a legacy VS Code task migration", + ) + } + } + + public captureLegacyTaskMigrationBacklog(args: { + pendingLegacyTaskCount: number + migratedSdkTaskCount: number + visibleSdkTaskCount: number + visibleTaskCount: number + }): void { + const attributes = { migration_type: "legacy_task_to_sdk_session" } + this.recordGauge( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_PENDING_COUNT, + args.pendingLegacyTaskCount, + attributes, + "Legacy VS Code tasks visible in history but not yet migrated to SDK sessions", + ) + this.recordGauge( + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_MIGRATED_COUNT, + args.migratedSdkTaskCount, + attributes, + "SDK sessions marked as migrated from legacy VS Code task history", + ) + this.capture({ + event: TelemetryService.EVENTS.TASK.LEGACY_TASK_MIGRATION, + properties: { + migration_type: "legacy_task_to_sdk_session", + outcome: "backlog", + pendingLegacyTaskCount: args.pendingLegacyTaskCount, + migratedSdkTaskCount: args.migratedSdkTaskCount, + visibleSdkTaskCount: args.visibleSdkTaskCount, + visibleTaskCount: args.visibleTaskCount, + }, + }) + } + public captureGrpcResponseSize(sizeUtf8Bytes: number, service: string, method: string, requestId?: string): void { this.recordHistogram( TelemetryService.METRICS.GRPC.RESPONSE_SIZE_BYTES, diff --git a/apps/vscode/src/services/telemetry/__tests__/TelemetryService.metrics.test.ts b/apps/vscode/src/services/telemetry/__tests__/TelemetryService.metrics.test.ts index d9b13dd8a5..d764dfb5db 100644 --- a/apps/vscode/src/services/telemetry/__tests__/TelemetryService.metrics.test.ts +++ b/apps/vscode/src/services/telemetry/__tests__/TelemetryService.metrics.test.ts @@ -383,4 +383,47 @@ describe("TelemetryService metrics", () => { assert.strictEqual(entry.attributes.extension_version, "test") assert.strictEqual(entry.attributes.platform, "test-platform") }) + + it("captureLegacyTaskMigration emits event and migration metrics", () => { + const provider = new FakeProvider() + const service = createTelemetryService(provider) + + service.captureLegacyTaskMigration({ + taskId: "legacy-task", + outcome: "success", + reason: "migrated", + durationMs: 250, + legacyApiHistoryLength: 3, + convertedMessageCount: 2, + hasFavorite: true, + hasCost: true, + hasTokenUsage: true, + hasCwd: true, + }) + + const event = provider.logs.find((entry) => entry.event === "task.legacy_task_migration") + assert.ok(event) + assert.strictEqual(event?.properties?.ulid, "legacy-task") + assert.strictEqual(event?.properties?.outcome, "success") + assert.strictEqual(event?.properties?.legacyApiHistoryLength, 3) + + assert.deepStrictEqual( + provider.counters.map((entry) => entry.name), + [ + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_ATTEMPTS_TOTAL, + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_SUCCESS_TOTAL, + ], + ) + assert.deepStrictEqual( + provider.histograms.map((entry) => entry.name), + [ + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_DURATION_SECONDS, + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_LEGACY_MESSAGES_COUNT, + TelemetryService.METRICS.MIGRATION.LEGACY_TASK_CONVERTED_MESSAGES_COUNT, + ], + ) + assert.strictEqual(provider.histograms[0].value, 0.25) + assert.strictEqual(provider.histograms[0].attributes.migration_type, "legacy_task_to_sdk_session") + assert.strictEqual(provider.histograms[0].attributes.reason, "migrated") + }) })