diff --git a/packages/telemetry/src/TelemetryService.ts b/packages/telemetry/src/TelemetryService.ts index 8eb1ed0ab6..564701e0a9 100644 --- a/packages/telemetry/src/TelemetryService.ts +++ b/packages/telemetry/src/TelemetryService.ts @@ -5,6 +5,7 @@ import { type TelemetryPropertiesProvider, TelemetryEventName, type TelemetrySetting, + type ToolUsage, } from "@roo-code/types" /** @@ -86,8 +87,31 @@ export class TelemetryService { this.captureEvent(TelemetryEventName.TASK_RESTARTED, { taskId }) } - public captureTaskCompleted(taskId: string): void { - this.captureEvent(TelemetryEventName.TASK_COMPLETED, { taskId }) + /** + * Captures task completion, summarizing per-task tool and message counts that + * were previously reported as separate per-turn events to reduce event volume. + * + * A single task may emit this more than once (e.g. an "idle" or "shutdown" + * installment followed by a final "attempt_completion" one). toolsUsed and + * messageCount are always deltas since the previous emission for that task, + * not running totals -- summing installments for a taskId reconstructs the + * full-task counts without double-counting. + * + * Note: "attempt_completion" means the model called that tool, not that the + * user accepted the result. + */ + public captureTaskCompleted( + taskId: string, + toolsUsed?: ToolUsage, + messageCount?: { user: number; assistant: number }, + completionReason: "attempt_completion" | "idle" | "shutdown" = "attempt_completion", + ): void { + this.captureEvent(TelemetryEventName.TASK_COMPLETED, { + taskId, + completionReason, + ...(toolsUsed !== undefined && { toolsUsed }), + ...(messageCount !== undefined && { messageCount }), + }) } public captureConversationMessage(taskId: string, source: "user" | "assistant"): void { diff --git a/packages/telemetry/src/__tests__/TelemetryService.task-completed.test.ts b/packages/telemetry/src/__tests__/TelemetryService.task-completed.test.ts new file mode 100644 index 0000000000..270fc8f83a --- /dev/null +++ b/packages/telemetry/src/__tests__/TelemetryService.task-completed.test.ts @@ -0,0 +1,66 @@ +// pnpm --filter @roo-code/telemetry test src/__tests__/TelemetryService.task-completed.test.ts + +import { TelemetryEventName, type TelemetryClient } from "@roo-code/types" + +import { TelemetryService } from "../TelemetryService" + +describe("TelemetryService.captureTaskCompleted", () => { + let mockClient: TelemetryClient + + beforeEach(() => { + mockClient = { + setProvider: vi.fn(), + capture: vi.fn().mockResolvedValue(undefined), + captureException: vi.fn().mockResolvedValue(undefined), + updateTelemetryState: vi.fn(), + isTelemetryEnabled: vi.fn().mockReturnValue(true), + shutdown: vi.fn().mockResolvedValue(undefined), + } + }) + + it("captures Task Completed with the taskId and a default 'attempt_completion' completionReason when no summary is provided", () => { + const service = new TelemetryService([mockClient]) + + service.captureTaskCompleted("task_1") + + expect(mockClient.capture).toHaveBeenCalledWith({ + event: TelemetryEventName.TASK_COMPLETED, + properties: { taskId: "task_1", completionReason: "attempt_completion" }, + }) + }) + + it("includes toolsUsed and messageCount summaries when provided", () => { + const service = new TelemetryService([mockClient]) + + service.captureTaskCompleted( + "task_1", + { read_file: { attempts: 3, failures: 0 }, apply_diff: { attempts: 1, failures: 1 } }, + { user: 4, assistant: 5 }, + ) + + expect(mockClient.capture).toHaveBeenCalledWith({ + event: TelemetryEventName.TASK_COMPLETED, + properties: { + taskId: "task_1", + completionReason: "attempt_completion", + toolsUsed: { read_file: { attempts: 3, failures: 0 }, apply_diff: { attempts: 1, failures: 1 } }, + messageCount: { user: 4, assistant: 5 }, + }, + }) + }) + + it("includes the given completionReason for idle/shutdown installments", () => { + const service = new TelemetryService([mockClient]) + + service.captureTaskCompleted("task_1", { read_file: { attempts: 1, failures: 0 } }, undefined, "idle") + + expect(mockClient.capture).toHaveBeenCalledWith({ + event: TelemetryEventName.TASK_COMPLETED, + properties: { + taskId: "task_1", + completionReason: "idle", + toolsUsed: { read_file: { attempts: 1, failures: 0 } }, + }, + }) + }) +}) diff --git a/src/__tests__/history-resume-delegation.spec.ts b/src/__tests__/history-resume-delegation.spec.ts index fc496d0c84..24ea04dd8e 100644 --- a/src/__tests__/history-resume-delegation.spec.ts +++ b/src/__tests__/history-resume-delegation.spec.ts @@ -26,7 +26,7 @@ vi.mock("vscode", () => { return { window, workspace, env, Uri, commands, ExtensionMode, version } }) -// Mock TelemetryService (needed by attemptCompletionTool's emitTaskCompleted) +// Mock TelemetryService (needed by attemptCompletionTool's emitPublicTaskCompleted) vi.mock("@roo-code/telemetry", () => ({ TelemetryService: { instance: { @@ -1255,6 +1255,7 @@ describe("History resume delegation - parent metadata transitions", () => { userMessageContent: [], consecutiveMistakeCount: 0, emitFinalTokenUsageUpdate: vi.fn(), + flushTelemetryInstallment: vi.fn(), } as unknown as import("../core/task/Task").Task const block = { diff --git a/src/__tests__/nested-delegation-resume.spec.ts b/src/__tests__/nested-delegation-resume.spec.ts index 35341f935c..8464f81b12 100644 --- a/src/__tests__/nested-delegation-resume.spec.ts +++ b/src/__tests__/nested-delegation-resume.spec.ts @@ -203,6 +203,7 @@ describe("Nested delegation resume (A → B → C)", () => { userMessageContent: [], consecutiveMistakeCount: 0, emitFinalTokenUsageUpdate: vi.fn(), + flushTelemetryInstallment: vi.fn(), } as unknown as Task const blockC = { @@ -250,6 +251,7 @@ describe("Nested delegation resume (A → B → C)", () => { userMessageContent: [], consecutiveMistakeCount: 0, emitFinalTokenUsageUpdate: vi.fn(), + flushTelemetryInstallment: vi.fn(), } as unknown as Task const blockB = { diff --git a/src/__tests__/task-run-dispatch.spec.ts b/src/__tests__/task-run-dispatch.spec.ts index 283cec3338..90af5a519d 100644 --- a/src/__tests__/task-run-dispatch.spec.ts +++ b/src/__tests__/task-run-dispatch.spec.ts @@ -17,6 +17,7 @@ type Runnable = { metadata: { task?: string | null; images?: string[] | null } resumeTaskFromHistory: () => Promise startTask: (task?: string, images?: string[]) => Promise + startIdleTelemetryCheck: () => void } function makeRunnable(overrides: Partial = {}): Runnable & { run(): Promise } { @@ -27,6 +28,7 @@ function makeRunnable(overrides: Partial = {}): Runnable & { run(): Pr metadata: { task: undefined, images: undefined }, resumeTaskFromHistory: vi.fn().mockResolvedValue(undefined), startTask: vi.fn().mockResolvedValue(undefined), + startIdleTelemetryCheck: vi.fn(), ...overrides, } // Bind the real run() implementation from Task.prototype to our stand-in. diff --git a/src/core/assistant-message/__tests__/presentAssistantMessage-custom-tool.spec.ts b/src/core/assistant-message/__tests__/presentAssistantMessage-custom-tool.spec.ts index 6675f18ce8..7838553835 100644 --- a/src/core/assistant-message/__tests__/presentAssistantMessage-custom-tool.spec.ts +++ b/src/core/assistant-message/__tests__/presentAssistantMessage-custom-tool.spec.ts @@ -23,16 +23,6 @@ vi.mock("@roo-code/core", () => ({ }, })) -vi.mock("@roo-code/telemetry", () => ({ - TelemetryService: { - instance: { - captureToolUsage: vi.fn(), - captureConsecutiveMistakeError: vi.fn(), - }, - }, -})) - -import { TelemetryService } from "@roo-code/telemetry" import { customToolRegistry } from "@roo-code/core" describe("presentAssistantMessage - Custom Tool Recording", () => { @@ -118,7 +108,6 @@ describe("presentAssistantMessage - Custom Tool Recording", () => { // Should record as "custom_tool", not "my_custom_tool" expect(mockTask.recordToolUsage).toHaveBeenCalledWith("custom_tool") - expect(TelemetryService.instance.captureToolUsage).toHaveBeenCalledWith(mockTask.taskId, "custom_tool") }) }) @@ -171,7 +160,6 @@ describe("presentAssistantMessage - Custom Tool Recording", () => { // Should record as "read_file", not "custom_tool" expect(mockTask.recordToolUsage).toHaveBeenCalledWith("read_file") - expect(TelemetryService.instance.captureToolUsage).toHaveBeenCalledWith(mockTask.taskId, "read_file") }) it("should record MCP tool usage as 'use_mcp_tool' (not custom_tool)", async () => { @@ -213,7 +201,6 @@ describe("presentAssistantMessage - Custom Tool Recording", () => { // Should record as "use_mcp_tool", not "custom_tool" expect(mockTask.recordToolUsage).toHaveBeenCalledWith("use_mcp_tool") - expect(TelemetryService.instance.captureToolUsage).toHaveBeenCalledWith(mockTask.taskId, "use_mcp_tool") }) }) @@ -355,7 +342,6 @@ describe("presentAssistantMessage - Custom Tool Recording", () => { // Should not record usage for partial blocks expect(mockTask.recordToolUsage).not.toHaveBeenCalled() - expect(TelemetryService.instance.captureToolUsage).not.toHaveBeenCalled() }) }) }) diff --git a/src/core/assistant-message/presentAssistantMessage.ts b/src/core/assistant-message/presentAssistantMessage.ts index f71b5cc1bd..12a5bfb4a2 100644 --- a/src/core/assistant-message/presentAssistantMessage.ts +++ b/src/core/assistant-message/presentAssistantMessage.ts @@ -235,7 +235,6 @@ export async function presentAssistantMessage(cline: Task) { if (!mcpBlock.partial) { cline.recordToolUsage("use_mcp_tool") // Record as use_mcp_tool for analytics - TelemetryService.instance.captureToolUsage(cline.taskId, "use_mcp_tool") } // Resolve sanitized server name back to original server name @@ -558,7 +557,6 @@ export async function presentAssistantMessage(cline: Task) { const isCustomTool = stateExperiments?.customTools && customToolRegistry.has(block.name) const recordName = isCustomTool ? "custom_tool" : block.name cline.recordToolUsage(recordName) - TelemetryService.instance.captureToolUsage(cline.taskId, recordName) // Track legacy format usage for read_file tool (for migration monitoring) if (block.name === "read_file" && block.usedLegacyFormat) { diff --git a/src/core/task/Task.ts b/src/core/task/Task.ts index 8f69a3a0d4..c31b295669 100644 --- a/src/core/task/Task.ts +++ b/src/core/task/Task.ts @@ -135,6 +135,7 @@ import { MessageManager } from "../message-manager" import { validateAndFixToolResultIds } from "./validateToolResultIds" import { mergeConsecutiveApiMessages } from "./mergeConsecutiveApiMessages" import { prepareApiConversationMessage } from "./apiConversationHistory" +import { shouldAddUserMessageToHistory } from "./messageCounting" const MAX_EXPONENTIAL_BACKOFF_SECONDS = 600 // 10 minutes const DEFAULT_USAGE_COLLECTION_TIMEOUT_MS = 5000 // 5 seconds @@ -322,6 +323,25 @@ export class Task extends EventEmitter implements TaskLike { consecutiveNoAssistantMessagesCount: number = 0 toolUsage: ToolUsage = {} + // Conversation message counts, summarized once per Task Completed + // installment instead of emitting a separate telemetry event per turn. + messageCounts: { user: number; assistant: number } = { user: 0, assistant: 0 } + + // Idle/shutdown telemetry flush: reports toolUsage/messageCounts for tasks that + // go quiet or get torn down without the model ever calling attempt_completion + // (or without the user accepting it), so long-running/abandoned tasks aren't + // invisible to telemetry. Each flush reports only what changed since the previous + // one, tracked via telemetryToolUsageBaseline/telemetryMessageCountsBaseline -- + // task.toolUsage/messageCounts themselves are never mutated by this, since they're + // also read as running totals by the public TaskCompleted API event and the UI. + // Checked on an interval rather than hooked into every say()/ask() call site. + private static readonly IDLE_TELEMETRY_CHECK_INTERVAL_MS = 5 * 60 * 1000 + private static readonly IDLE_TELEMETRY_THRESHOLD_MS = 30 * 60 * 1000 + private idleTelemetryCheckInterval?: NodeJS.Timeout + private lastTelemetryFlushAt: number = Date.now() + private telemetryToolUsageBaseline: ToolUsage = {} + private telemetryMessageCountsBaseline: { user: number; assistant: number } = { user: 0, assistant: 0 } + // Checkpoints enableCheckpoints: boolean checkpointTimeout: number @@ -601,6 +621,7 @@ export class Task extends EventEmitter implements TaskLike { if (startTask) { this._started = true + this.startIdleTelemetryCheck() if (task || images) { void this.startTask(task, images).catch((error) => { console.error("[Task#constructor] startTask failed:", error) @@ -881,6 +902,8 @@ export class Task extends EventEmitter implements TaskLike { const { images, task, historyItem } = options let promise + instance.startIdleTelemetryCheck() + if (images || task) { promise = instance.startTask(task, images) } else if (historyItem) { @@ -1878,6 +1901,7 @@ export class Task extends EventEmitter implements TaskLike { return } this._started = true + this.startIdleTelemetryCheck() const { task, images } = this.metadata @@ -1902,6 +1926,7 @@ export class Task extends EventEmitter implements TaskLike { return Promise.resolve() } this._started = true + this.startIdleTelemetryCheck() const { task, images } = this.metadata @@ -2270,6 +2295,17 @@ export class Task extends EventEmitter implements TaskLike { public dispose(): void { console.log(`[Task#dispose] disposing task ${this.taskId}.${this.instanceId}`) + // Stop the idle telemetry check and report any unflushed activity as a + // shutdown installment, so a task torn down mid-work (panel closed, task + // switched, extension deactivated) isn't invisible to telemetry. + try { + clearInterval(this.idleTelemetryCheckInterval) + this.idleTelemetryCheckInterval = undefined + this.flushTelemetryInstallment("shutdown") + } catch (error) { + console.error("Error flushing shutdown telemetry:", error) + } + // Cancel any in-progress HTTP request try { this.cancelCurrentRequest() @@ -2629,18 +2665,16 @@ export class Task extends EventEmitter implements TaskLike { // Add environment details as its own text block, separate from tool // results. const finalUserContent = [...contentWithoutEnvDetails, { type: "text" as const, text: environmentDetails }] - // Only add user message to conversation history if: - // 1. This is the first attempt (retryAttempt === 0), AND - // 2. The original userContent was not empty (empty signals delegation resume where - // the user message with tool_result and env details is already in history), OR - // 3. The message was removed in a previous iteration (userMessageWasRemoved === true) - // This prevents consecutive user messages while allowing re-add when needed + // See shouldAddUserMessageToHistory for the full add/skip rules (retry/empty/removed). const isEmptyUserContent = currentUserContent.length === 0 - const shouldAddUserMessage = - ((currentItem.retryAttempt ?? 0) === 0 && !isEmptyUserContent) || currentItem.userMessageWasRemoved + const shouldAddUserMessage = shouldAddUserMessageToHistory({ + retryAttempt: currentItem.retryAttempt, + isEmptyUserContent, + userMessageWasRemoved: currentItem.userMessageWasRemoved, + }) if (shouldAddUserMessage) { await this.addToApiConversationHistory({ role: "user", content: finalUserContent }) - TelemetryService.instance.captureConversationMessage(this.taskId, "user") + this.messageCounts.user++ } // Since we sent off a placeholder api_req_started message to update the @@ -3557,7 +3591,7 @@ export class Task extends EventEmitter implements TaskLike { ) this.assistantMessageSavedToHistory = true - TelemetryService.instance.captureConversationMessage(this.taskId, "assistant") + this.messageCounts.assistant++ } // Present any partial blocks that were just completed. @@ -3658,11 +3692,17 @@ export class Task extends EventEmitter implements TaskLike { // we need to remove that message before retrying to avoid having two consecutive // user messages (which would cause tool_result validation errors). const state = await this.providerRef.deref()?.getState() - if (this.apiConversationHistory.length > 0) { + // Only pop the user message that this iteration added. When + // shouldAddUserMessage is false (empty continuation, resumed history, + // or flushPendingToolResultsToHistory message) there is nothing to + // remove, and popping would corrupt history. + let removedCurrentUserMessage = false + if (shouldAddUserMessage && this.apiConversationHistory.length > 0) { const lastMessage = this.apiConversationHistory[this.apiConversationHistory.length - 1] if (lastMessage.role === "user") { - // Remove the last user message that we added earlier this.apiConversationHistory.pop() + this.messageCounts.user-- + removedCurrentUserMessage = true } } @@ -3685,13 +3725,14 @@ export class Task extends EventEmitter implements TaskLike { break } - // Push the same content back onto the stack to retry, incrementing the retry attempt counter - // Mark that user message was removed so it gets re-added on retry + // Push the same content back onto the stack to retry, incrementing the retry attempt counter. + // Only mark userMessageWasRemoved when we actually removed one -- the + // restore branch in shouldAddUserMessageToHistory must only fire once. stack.push({ userContent: currentUserContent, includeFileDetails: false, retryAttempt: (currentItem.retryAttempt ?? 0) + 1, - userMessageWasRemoved: true, + userMessageWasRemoved: removedCurrentUserMessage, }) // Continue to retry the request @@ -3706,32 +3747,41 @@ export class Task extends EventEmitter implements TaskLike { if (response === "yesButtonClicked") { await this.say("api_req_retried") - // Push the same content back to retry + // Push the same content back to retry. Only mark userMessageWasRemoved + // when we actually removed one so the restore fires exactly once. stack.push({ userContent: currentUserContent, includeFileDetails: false, retryAttempt: (currentItem.retryAttempt ?? 0) + 1, + userMessageWasRemoved: removedCurrentUserMessage, }) // Continue to retry the request continue } else { - // User declined to retry - // Re-add the user message we removed. - await this.addToApiConversationHistory({ - role: "user", - content: currentUserContent, - }) + // User declined to retry. Re-add the user message only if this + // iteration removed one, so the history and counter stay consistent. + if (removedCurrentUserMessage) { + await this.addToApiConversationHistory({ + role: "user", + content: currentUserContent, + }) + this.messageCounts.user++ + } await this.say( "error", "Unexpected API Response: The language model did not provide any assistant messages. This may indicate an issue with the API or the model's output.", ) + // Synthetic assistant message recording the failure -- increment + // messageCounts.assistant to match, same as the normal + // assistant-message-saved path. await this.addToApiConversationHistory({ role: "assistant", content: [{ type: "text", text: "Failure: I did not provide a response." }], }) + this.messageCounts.assistant++ } } } @@ -4679,6 +4729,76 @@ export class Task extends EventEmitter implements TaskLike { } } + /** + * Emits a Task Completed installment for whatever toolUsage/messageCounts have + * changed since the previous installment (from any reason), then advances the + * telemetry baseline so a later installment reports only its own delta. Does + * NOT touch task.toolUsage/messageCounts themselves -- those stay running totals + * for the public TaskCompleted API event and the UI. No-ops if nothing changed + * since the last installment, so idle/shutdown checks don't emit empty events + * for tasks that were already fully reported (e.g. right after attempt_completion). + */ + public flushTelemetryInstallment(reason: "attempt_completion" | "idle" | "shutdown"): void { + const toolUsageDelta: ToolUsage = {} + + for (const [toolName, usage] of Object.entries(this.toolUsage) as [ToolName, ToolUsage[ToolName]][]) { + if (!usage) { + continue + } + + const baseline = this.telemetryToolUsageBaseline[toolName] + const attempts = usage.attempts - (baseline?.attempts ?? 0) + const failures = usage.failures - (baseline?.failures ?? 0) + + if (attempts > 0 || failures > 0) { + toolUsageDelta[toolName] = { attempts, failures } + } + } + + const messageCountDelta = { + user: Math.max(0, this.messageCounts.user - this.telemetryMessageCountsBaseline.user), + assistant: Math.max(0, this.messageCounts.assistant - this.telemetryMessageCountsBaseline.assistant), + } + + const hasToolUsageDelta = Object.keys(toolUsageDelta).length > 0 + const hasMessageDelta = messageCountDelta.user > 0 || messageCountDelta.assistant > 0 + + if (!hasToolUsageDelta && !hasMessageDelta) { + return + } + + // Advance the baseline before emitting so a synchronous throw from an + // EventEmitter listener or TelemetryService client cannot leave the baseline + // behind the running totals, which would cause the same delta to re-appear + // on the next flush. The delta values are already captured in locals above. + this.telemetryToolUsageBaseline = JSON.parse(JSON.stringify(this.toolUsage)) + this.telemetryMessageCountsBaseline = { ...this.messageCounts } + this.lastTelemetryFlushAt = Date.now() + + this.emitFinalTokenUsageUpdate() + TelemetryService.instance.captureTaskCompleted(this.taskId, toolUsageDelta, messageCountDelta, reason) + } + + startIdleTelemetryCheck(): void { + if (this.idleTelemetryCheckInterval !== undefined) { + return + } + this.idleTelemetryCheckInterval = setInterval(() => { + // Measure idleness from the later of the last activity and the last flush. + // Using lastMessageTs alone would keep the condition true forever after the + // first idle flush, re-running the empty-delta check on every interval tick. + const lastEventAt = Math.max(this.lastMessageTs ?? 0, this.lastTelemetryFlushAt) + const idleForMs = Date.now() - lastEventAt + + if (idleForMs >= Task.IDLE_TELEMETRY_THRESHOLD_MS) { + this.flushTelemetryInstallment("idle") + } + }, Task.IDLE_TELEMETRY_CHECK_INTERVAL_MS) + + // Don't hold the process open just for this timer. + this.idleTelemetryCheckInterval?.unref?.() + } + // Getters public get taskStatus(): TaskStatus { diff --git a/src/core/task/__tests__/Task.spec.ts b/src/core/task/__tests__/Task.spec.ts index d9f7240c5c..08361a5a2c 100644 --- a/src/core/task/__tests__/Task.spec.ts +++ b/src/core/task/__tests__/Task.spec.ts @@ -5,6 +5,7 @@ import * as path from "path" import * as vscode from "vscode" import { Anthropic } from "@anthropic-ai/sdk" +import type { Mock } from "vitest" import { providerIdentifiers, @@ -34,6 +35,17 @@ type TaskTestAccess = { saveClineMessages: () => Promise } +type TaskAskResult = Awaited> +type ProviderState = Awaited> +type MockedClineProvider = ClineProvider & { + getState: Mock & { + mockResolvedValue: (value: Partial) => void + } +} +type RateLimitedProviderSettings = ProviderSettings & { + rateLimitSeconds: number +} + function getTaskTestAccess(task: Task): TaskTestAccess { return task as unknown as TaskTestAccess } @@ -66,7 +78,7 @@ vi.mock("execa", () => ({ })) vi.mock("fs/promises", async (importOriginal) => { - const actual = (await importOriginal()) as Record + const actual = await importOriginal() const mockFunctions = { mkdir: vi.fn().mockResolvedValue(undefined), writeFile: vi.fn().mockResolvedValue(undefined), @@ -153,7 +165,7 @@ vi.mock("vscode", () => { stat: vi.fn().mockResolvedValue({ type: 1 }), // FileType.File = 1 }, onDidSaveTextDocument: vi.fn(() => mockDisposable), - getConfiguration: vi.fn(() => ({ get: (key: string, defaultValue: any) => defaultValue })), + getConfiguration: vi.fn(() => ({ get: (_key: string, defaultValue: unknown) => defaultValue })), }, env: { uriScheme: "vscode", @@ -239,9 +251,9 @@ const mockMessages = [ ] describe("Cline", () => { - let mockProvider: any + let mockProvider: ClineProvider let mockApiConfig: ProviderSettings - let mockOutputChannel: any + let mockOutputChannel: vscode.OutputChannel let mockExtensionContext: vscode.ExtensionContext beforeEach(() => { @@ -301,8 +313,10 @@ describe("Cline", () => { // Setup mock output channel mockOutputChannel = { + name: "test-output", appendLine: vi.fn(), append: vi.fn(), + replace: vi.fn(), clear: vi.fn(), show: vi.fn(), hide: vi.fn(), @@ -357,6 +371,74 @@ describe("Cline", () => { })) }) + describe("empty-response retries", () => { + function stream(chunks: ApiStreamChunk[]): AsyncGenerator { + return (async function* () { + yield* chunks + })() + } + + async function createTaskWithManualRetries() { + const task = new Task({ + provider: mockProvider, + apiConfiguration: mockApiConfig, + task: "test task", + startTask: false, + }) + const state = await mockProvider.getState() + vi.spyOn(mockProvider, "getState").mockResolvedValue({ + ...state, + apiConfiguration: mockApiConfig, + autoApprovalEnabled: false, + }) + vi.spyOn(task.diffViewProvider, "reset").mockResolvedValue(undefined) + return task + } + + it("restores the user message before a confirmed empty-response retry", async () => { + const task = await createTaskWithManualRetries() + let retryHistory: ApiMessage[] | undefined + let retryUserMessageCount: number | undefined + + vi.spyOn(task, "ask").mockResolvedValue({ response: "yesButtonClicked" } satisfies TaskAskResult) + vi.spyOn(task, "attemptApiRequest") + .mockImplementationOnce(() => stream([])) + .mockImplementationOnce(() => { + retryHistory = structuredClone(task.apiConversationHistory) + retryUserMessageCount = task.messageCounts.user + return stream([{ type: "text", text: "retry succeeded" }]) + }) + .mockImplementation(() => { + throw new Error("stop after retry response") + }) + + await task.recursivelyMakeClineRequests([{ type: "text", text: "original user request" }]) + + expect(retryHistory).toHaveLength(1) + expect(retryHistory?.[0]).toMatchObject({ + role: "user", + content: expect.arrayContaining([expect.objectContaining({ text: "original user request" })]), + }) + expect(retryUserMessageCount).toBe(1) + }) + + it("restores the user message and records the failure when retry is declined", async () => { + const task = await createTaskWithManualRetries() + + vi.spyOn(task, "ask").mockResolvedValue({ response: "noButtonClicked" } satisfies TaskAskResult) + vi.spyOn(task, "attemptApiRequest").mockImplementation(() => stream([])) + + const result = await task.recursivelyMakeClineRequests([{ type: "text", text: "original user request" }]) + + expect(result).toBe(false) + expect(task.apiConversationHistory).toMatchObject([ + { role: "user", content: [{ type: "text", text: "original user request" }] }, + { role: "assistant", content: [{ type: "text", text: "Failure: I did not provide a response." }] }, + ]) + expect(task.messageCounts).toEqual({ user: 1, assistant: 1 }) + }) + }) + describe("constructor", () => { it("should always have diff strategy defined", async () => { const cline = new Task({ @@ -498,7 +580,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(error: any) { + async throw(error: unknown) { throw error }, async [Symbol.asyncDispose]() { @@ -604,7 +686,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(error: any) { + async throw(error: unknown) { throw error }, async [Symbol.asyncDispose]() { @@ -681,7 +763,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() { @@ -700,7 +782,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() { @@ -772,7 +854,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() {}, @@ -788,7 +870,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() {}, @@ -849,7 +931,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() { @@ -868,7 +950,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, async [Symbol.asyncDispose]() { @@ -989,8 +1071,8 @@ describe("Cline", () => { }) describe("Subtask Rate Limiting", () => { - let mockProvider: any - let mockApiConfig: any + let mockProvider: MockedClineProvider + let mockApiConfig: RateLimitedProviderSettings let mockDelay: ReturnType beforeEach(() => { @@ -1021,7 +1103,8 @@ describe("Cline", () => { postStateToWebviewWithoutTaskHistory: vi.fn().mockResolvedValue(undefined), postMessageToWebview: vi.fn().mockResolvedValue(undefined), updateTaskHistory: vi.fn().mockResolvedValue(undefined), - } + // Task receives a full ClineProvider at runtime; this focused unit test only exercises these methods. + } as unknown as MockedClineProvider // Get the mocked delay function mockDelay = delay as ReturnType @@ -1056,7 +1139,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1097,7 +1180,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1149,7 +1232,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1215,7 +1298,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1305,7 +1388,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1363,7 +1446,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -1382,8 +1465,8 @@ describe("Cline", () => { }) describe("Dynamic Strategy Selection", () => { - let mockProvider: any - let mockApiConfig: any + let mockProvider: MockedClineProvider + let mockApiConfig: ProviderSettings beforeEach(() => { vi.clearAllMocks() @@ -1398,7 +1481,7 @@ describe("Cline", () => { globalStorageUri: { fsPath: "/test/storage" }, }, getState: vi.fn(), - } + } as MockedClineProvider }) it("should use MultiSearchReplaceDiffStrategy by default", async () => { @@ -1950,7 +2033,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2101,7 +2184,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2171,7 +2254,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2237,7 +2320,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2302,7 +2385,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2462,7 +2545,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2478,7 +2561,7 @@ describe("Cline", () => { async return() { return { done: true, value: undefined } }, - async throw(e: any) { + async throw(e: unknown) { throw e }, [Symbol.asyncDispose]: async () => {}, @@ -2933,7 +3016,7 @@ describe("Cline", () => { }) describe("Queued message processing after condense", () => { - function createProvider(): any { + function createProvider(): ClineProvider { const storageUri = { fsPath: path.join(os.tmpdir(), "test-storage") } const ctx = { globalState: { @@ -3059,8 +3142,261 @@ describe("Queued message processing after condense", () => { }) }) +describe("Telemetry installments (idle/shutdown flush)", () => { + let mockProvider: ClineProvider + let mockApiConfig: ProviderSettings + let mockExtensionContext: vscode.ExtensionContext + let captureTaskCompletedSpy: ReturnType + + beforeEach(() => { + if (!TelemetryService.hasInstance()) { + TelemetryService.createInstance([]) + } + + captureTaskCompletedSpy = vi.spyOn(TelemetryService.instance, "captureTaskCompleted") + + const storageUri = { fsPath: path.join(os.tmpdir(), "test-storage") } + + mockExtensionContext = { + globalState: { + get: vi.fn().mockReturnValue(undefined), + update: vi.fn().mockResolvedValue(undefined), + keys: vi.fn().mockReturnValue([]), + }, + globalStorageUri: storageUri, + workspaceState: { + get: vi.fn().mockReturnValue(undefined), + update: vi.fn().mockResolvedValue(undefined), + keys: vi.fn().mockReturnValue([]), + }, + secrets: { + get: vi.fn().mockResolvedValue(undefined), + store: vi.fn().mockResolvedValue(undefined), + delete: vi.fn().mockResolvedValue(undefined), + }, + extensionUri: { fsPath: "/mock/extension/path" }, + extension: { packageJSON: { version: "1.0.0" } }, + } as unknown as vscode.ExtensionContext + + mockProvider = new ClineProvider( + mockExtensionContext, + { + appendLine: vi.fn(), + append: vi.fn(), + clear: vi.fn(), + show: vi.fn(), + hide: vi.fn(), + dispose: vi.fn(), + } as unknown as vscode.OutputChannel, + "sidebar", + new ContextProxy(mockExtensionContext), + ) + mockProvider.postMessageToWebview = vi.fn().mockResolvedValue(undefined) + mockProvider.postStateToWebview = vi.fn().mockResolvedValue(undefined) + + mockApiConfig = { + apiProvider: "anthropic", + apiModelId: "claude-3-5-sonnet-20241022", + apiKey: "test-api-key", + } + }) + + const createdTasks: Task[] = [] + + afterEach(() => { + for (const task of createdTasks) { + task.dispose() + } + createdTasks.length = 0 + vi.useRealTimers() + captureTaskCompletedSpy.mockRestore() + }) + + function createTask() { + const task = new Task({ + provider: mockProvider, + apiConfiguration: mockApiConfig, + task: "test task", + startTask: false, + }) + task.startIdleTelemetryCheck() + createdTasks.push(task) + return task + } + + describe("flushTelemetryInstallment", () => { + it("reports nothing and does not call captureTaskCompleted when there is no new activity", () => { + const task = createTask() + + task.flushTelemetryInstallment("idle") + + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + + it("reports the current toolUsage/messageCounts as the delta on the first flush", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.recordToolUsage("read_file") + task.messageCounts = { user: 2, assistant: 3 } + + task.flushTelemetryInstallment("idle") + + expect(captureTaskCompletedSpy).toHaveBeenCalledWith( + task.taskId, + { read_file: { attempts: 2, failures: 0 } }, + { user: 2, assistant: 3 }, + "idle", + ) + }) + + it("does not mutate task.toolUsage/messageCounts (they stay running totals for the public API/UI)", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.messageCounts = { user: 1, assistant: 1 } + + task.flushTelemetryInstallment("idle") + + expect(task.toolUsage).toEqual({ read_file: { attempts: 1, failures: 0 } }) + expect(task.messageCounts).toEqual({ user: 1, assistant: 1 }) + }) + + it("reports only the delta since the previous installment on a second flush", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.messageCounts = { user: 1, assistant: 1 } + task.flushTelemetryInstallment("idle") + captureTaskCompletedSpy.mockClear() + + task.recordToolUsage("read_file") + task.recordToolUsage("write_to_file") + task.messageCounts = { user: 3, assistant: 2 } + task.flushTelemetryInstallment("shutdown") + + expect(captureTaskCompletedSpy).toHaveBeenCalledWith( + task.taskId, + { read_file: { attempts: 1, failures: 0 }, write_to_file: { attempts: 1, failures: 0 } }, + { user: 2, assistant: 1 }, + "shutdown", + ) + }) + + it("does not emit an empty second installment when nothing changed since the first flush", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.flushTelemetryInstallment("idle") + captureTaskCompletedSpy.mockClear() + + task.flushTelemetryInstallment("shutdown") + + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + + it("includes failure deltas alongside attempt deltas", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.flushTelemetryInstallment("idle") + captureTaskCompletedSpy.mockClear() + + task.recordToolError("read_file") + + task.flushTelemetryInstallment("shutdown") + + expect(captureTaskCompletedSpy).toHaveBeenCalledWith( + task.taskId, + { read_file: { attempts: 0, failures: 1 } }, + { user: 0, assistant: 0 }, + "shutdown", + ) + }) + }) + + describe("idle flush timer", () => { + it("flushes once activity has been quiet for the idle threshold", () => { + vi.useFakeTimers() + const task = createTask() + task.recordToolUsage("read_file") + + vi.advanceTimersByTime(31 * 60 * 1000) + + expect(captureTaskCompletedSpy).toHaveBeenCalledWith( + task.taskId, + { read_file: { attempts: 1, failures: 0 } }, + { user: 0, assistant: 0 }, + "idle", + ) + }) + + it("does not flush before the idle threshold has elapsed", () => { + vi.useFakeTimers() + const task = createTask() + task.recordToolUsage("read_file") + + vi.advanceTimersByTime(10 * 60 * 1000) + + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + + it("does not call the idle flush after a prior idle installment without new activity", () => { + vi.useFakeTimers() + const task = createTask() + const flushTelemetryInstallmentSpy = vi.spyOn(task, "flushTelemetryInstallment") + task.recordToolUsage("read_file") + + vi.advanceTimersByTime(31 * 60 * 1000) + expect(captureTaskCompletedSpy).toHaveBeenCalledTimes(1) + flushTelemetryInstallmentSpy.mockClear() + captureTaskCompletedSpy.mockClear() + + vi.advanceTimersByTime(5 * 60 * 1000) + + expect(flushTelemetryInstallmentSpy).not.toHaveBeenCalled() + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + }) + + describe("dispose", () => { + it("flushes unreported activity as a shutdown installment", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.messageCounts = { user: 1, assistant: 1 } + + task.dispose() + + expect(captureTaskCompletedSpy).toHaveBeenCalledWith( + task.taskId, + { read_file: { attempts: 1, failures: 0 } }, + { user: 1, assistant: 1 }, + "shutdown", + ) + }) + + it("does not flush again if everything was already reported before dispose", () => { + const task = createTask() + task.recordToolUsage("read_file") + task.flushTelemetryInstallment("attempt_completion") + captureTaskCompletedSpy.mockClear() + + task.dispose() + + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + + it("stops the idle timer so a disposed task never flushes again", () => { + vi.useFakeTimers() + const task = createTask() + task.recordToolUsage("read_file") + task.dispose() + captureTaskCompletedSpy.mockClear() + + vi.advanceTimersByTime(60 * 60 * 1000) + + expect(captureTaskCompletedSpy).not.toHaveBeenCalled() + }) + }) +}) + describe("pushToolResultToUserContent", () => { - let mockProvider: any + let mockProvider: ClineProvider let mockApiConfig: ProviderSettings beforeEach(() => { diff --git a/src/core/task/__tests__/messageCounting.spec.ts b/src/core/task/__tests__/messageCounting.spec.ts new file mode 100644 index 0000000000..6e49473201 --- /dev/null +++ b/src/core/task/__tests__/messageCounting.spec.ts @@ -0,0 +1,75 @@ +// npx vitest run core/task/__tests__/messageCounting.spec.ts + +import { shouldAddUserMessageToHistory } from "../messageCounting" + +describe("shouldAddUserMessageToHistory", () => { + it("adds the message on a first attempt with non-empty content", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 0, + isEmptyUserContent: false, + userMessageWasRemoved: false, + }), + ).toBe(true) + }) + + it("adds the message when retryAttempt is undefined (treated as first attempt) with non-empty content", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: undefined, + isEmptyUserContent: false, + userMessageWasRemoved: undefined, + }), + ).toBe(true) + }) + + it("skips an empty-content first attempt (delegation resume - already in history)", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 0, + isEmptyUserContent: true, + userMessageWasRemoved: false, + }), + ).toBe(false) + }) + + it("skips a retry attempt (retryAttempt > 0) with non-empty content", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 1, + isEmptyUserContent: false, + userMessageWasRemoved: false, + }), + ).toBe(false) + }) + + it("re-adds the message on a retry attempt if it was previously removed", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 2, + isEmptyUserContent: false, + userMessageWasRemoved: true, + }), + ).toBe(true) + }) + + it("re-adds an empty-content message if it was previously removed", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 0, + isEmptyUserContent: true, + userMessageWasRemoved: true, + }), + ).toBe(true) + }) + + it("skips a retry attempt with empty content that was not removed", () => { + expect( + shouldAddUserMessageToHistory({ + retryAttempt: 3, + isEmptyUserContent: true, + userMessageWasRemoved: false, + }), + ).toBe(false) + }) +}) diff --git a/src/core/task/messageCounting.ts b/src/core/task/messageCounting.ts new file mode 100644 index 0000000000..11a886d619 --- /dev/null +++ b/src/core/task/messageCounting.ts @@ -0,0 +1,20 @@ +/** + * Whether the current turn's user message should be added to API conversation + * history (and counted towards the per-task message-count telemetry summary). + * + * Only added when: + * 1. This is the first attempt (retryAttempt === 0) AND the content is non-empty, OR + * 2. The message was removed in a previous iteration (userMessageWasRemoved === true) + * + * Empty content on a first attempt signals a delegation resume, where the user message + * with tool_result and env details is already in history -- adding it again would create + * a duplicate (and inflate the message count). + */ +export function shouldAddUserMessageToHistory(params: { + retryAttempt: number | undefined + isEmptyUserContent: boolean + userMessageWasRemoved: boolean | undefined +}): boolean { + const { retryAttempt, isEmptyUserContent, userMessageWasRemoved } = params + return ((retryAttempt ?? 0) === 0 && !isEmptyUserContent) || Boolean(userMessageWasRemoved) +} diff --git a/src/core/tools/AttemptCompletionTool.ts b/src/core/tools/AttemptCompletionTool.ts index 39feae0d9b..b5f19decb0 100644 --- a/src/core/tools/AttemptCompletionTool.ts +++ b/src/core/tools/AttemptCompletionTool.ts @@ -1,7 +1,6 @@ import * as vscode from "vscode" import { RooCodeEventName, type HistoryItem } from "@roo-code/types" -import { TelemetryService } from "@roo-code/telemetry" import { Task } from "../task/Task" import { formatResponse } from "../prompts/responses" @@ -81,6 +80,19 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { await task.say("completion_result", result, undefined, false) + // Whether this attempt_completion call is a stale replay of an already-completed + // subtask (user revisiting it from history) rather than a live model-initiated + // completion. Determined below, before telemetry is flushed, so a replay -- which + // runs this handler again on a fresh Task instance with a zero telemetry baseline + // -- doesn't produce a duplicate "attempt_completion" installment for work that + // was already reported when the subtask first completed. + let isStaleHistoryReplay = false + // Whether the delegation branch below already flushed telemetry (it needs to + // flush before delegateToParent, which may return early) -- prevents the shared + // fallthrough flush from double-reporting when delegation falls through to + // "continue" instead of returning. + let hasFlushedTelemetry = false + // Check for subtask using parentTaskId (metadata-driven delegation) if (task.parentTaskId) { // Check if this subtask has already completed and returned to parent @@ -97,6 +109,7 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { // Fall through to normal completion ask flow below (outside this if block) // This shows the user the completion result and waits for acceptance // without injecting another tool_result to the parent + isStaleHistoryReplay = true } else if (status === "active" || status === "interrupted") { historyLookupTaskId = task.parentTaskId const { historyItem: parentHistory } = await provider.getTaskWithId(task.parentTaskId) @@ -105,6 +118,14 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { (parentHistory?.status === "delegated" || parentHistory?.status === "active") && parentHistory?.awaitingChildId === task.taskId ) { + // Known not to be a stale history replay (status was "active", not + // "completed"), so flush telemetry before the delegation call, which + // may return early below. hasFlushedTelemetry prevents the shared + // fallthrough flush further down from double-reporting if delegation + // falls through to "continue" instead of returning. + task.flushTelemetryInstallment("attempt_completion") + hasFlushedTelemetry = true + const delegation = await this.delegateToParent( task, result, @@ -113,7 +134,7 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { pushToolResult, ) if (delegation === "delegated") { - this.emitTaskCompleted(task) + this.emitPublicTaskCompleted(task) } if (delegation !== "continue") return } else { @@ -147,10 +168,30 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { } } + // PostHog telemetry: report here, once per model-initiated attempt_completion + // call, regardless of whether the user goes on to accept, decline, or give + // feedback. Gating this on user acceptance previously meant a task that never + // got an explicit "yes" (declined, abandoned mid-review, etc.) reported nothing + // at all. This is independent of the public TaskCompleted API event, which still + // only fires once the task is genuinely finished. Skipped for a stale history + // replay (revisiting an already-completed subtask) since that reruns this handler + // on a fresh Task instance and would otherwise double-report work already flushed + // when the subtask first completed, and skipped if the delegation branch above + // already flushed. + if (!isStaleHistoryReplay && !hasFlushedTelemetry) { + task.emitFinalTokenUsageUpdate() + task.flushTelemetryInstallment("attempt_completion") + } + const { response, text, images } = await task.ask("completion_result", "", false) if (response === "yesButtonClicked") { - this.emitTaskCompleted(task) + // A stale history replay reruns this handler on a fresh Task instance for a + // subtask that already completed (and already emitted TaskCompleted) the first + // time through -- re-acknowledging it from history must not emit it again. + if (!isStaleHistoryReplay) { + this.emitPublicTaskCompleted(task) + } return } @@ -217,12 +258,17 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { } } - private emitTaskCompleted(task: Task): void { + /** + * Emits the public RooCodeEventName.TaskCompleted API event. Only called once the + * task is genuinely finished (user accepted, or a subtask was successfully delegated + * back to its parent) -- unlike the PostHog telemetry flush, which reports on every + * model-initiated attempt_completion call regardless of outcome. + */ + private emitPublicTaskCompleted(task: Task): void { // Force final token usage update before emitting TaskCompleted. // This ensures the latest stats are captured regardless of throttle timer. task.emitFinalTokenUsageUpdate() - TelemetryService.instance.captureTaskCompleted(task.taskId) task.emit(RooCodeEventName.TaskCompleted, task.taskId, task.getTokenUsage(), task.toolUsage) } } diff --git a/src/core/tools/__tests__/attemptCompletionTool.spec.ts b/src/core/tools/__tests__/attemptCompletionTool.spec.ts index 86ff112585..015be6f6bb 100644 --- a/src/core/tools/__tests__/attemptCompletionTool.spec.ts +++ b/src/core/tools/__tests__/attemptCompletionTool.spec.ts @@ -11,17 +11,6 @@ vi.mock("../../prompts/responses", () => ({ }, })) -const { mockCaptureTaskCompleted } = vi.hoisted(() => ({ - mockCaptureTaskCompleted: vi.fn(), -})) -vi.mock("@roo-code/telemetry", () => ({ - TelemetryService: { - instance: { - captureTaskCompleted: mockCaptureTaskCompleted, - }, - }, -})) - // Mock vscode module vi.mock("vscode", () => ({ workspace: { @@ -53,7 +42,6 @@ describe("attemptCompletionTool", () => { let mockGetConfiguration: ReturnType any>> beforeEach(() => { - mockCaptureTaskCompleted.mockReset() mockPushToolResult = vi.fn() mockAskApproval = vi.fn() mockHandleError = vi.fn() @@ -81,9 +69,11 @@ describe("attemptCompletionTool", () => { emit: vi.fn(), getTokenUsage: vi.fn().mockReturnValue({}), toolUsage: {}, + messageCounts: { user: 0, assistant: 0 }, taskId: "task_1", apiConfiguration: { apiProvider: "test" } as any, api: { getModel: vi.fn().mockReturnValue({ id: "test-model", info: {} }) } as any, + flushTelemetryInstallment: vi.fn(), } }) @@ -585,7 +575,10 @@ describe("attemptCompletionTool", () => { }) expect(mockTask.ask).toHaveBeenCalledWith("completion_result", "", false) expect(mockPushToolResult).not.toHaveBeenCalledWith("") - expect(mockCaptureTaskCompleted).not.toHaveBeenCalled() + // Flush once per validated attempt_completion call, before delegation is + // attempted, independent of whether delegation succeeds. + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") }) it("does not resume the parent when the parent is no longer awaiting this child", async () => { @@ -633,7 +626,8 @@ describe("attemptCompletionTool", () => { expect(mockProvider.reopenParentFromDelegation).not.toHaveBeenCalled() expect(mockProvider.log).toHaveBeenCalledWith(expect.stringContaining("Skipping delegation")) expect(mockTask.ask).toHaveBeenCalledWith("completion_result", "", false) - expect(mockCaptureTaskCompleted).toHaveBeenCalledWith("child-1") + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") }) it("delegates an interrupted subtask completion when the parent is still delegated and awaiting that child", async () => { @@ -732,7 +726,8 @@ describe("attemptCompletionTool", () => { expect(mockProvider.reopenParentFromDelegation).not.toHaveBeenCalled() expect(mockProvider.log).toHaveBeenCalledWith(expect.stringContaining("Skipping delegation")) expect(mockTask.ask).toHaveBeenCalledWith("completion_result", "", false) - expect(mockCaptureTaskCompleted).toHaveBeenCalledWith("child-1") + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") }) it("emits TaskCompleted only when completion is accepted", async () => { @@ -757,7 +752,8 @@ describe("attemptCompletionTool", () => { await attemptCompletionTool.handle(mockTask as Task, block, callbacks) expect(mockHandleError).not.toHaveBeenCalled() - expect(mockCaptureTaskCompleted).toHaveBeenCalledWith("task_1") + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") expect(mockTask.emit).toHaveBeenCalledWith( RooCodeEventName.TaskCompleted, "task_1", @@ -766,7 +762,7 @@ describe("attemptCompletionTool", () => { ) }) - it("does not emit TaskCompleted when user provides follow-up feedback", async () => { + it("reports telemetry but does not emit the public TaskCompleted event when user provides follow-up feedback", async () => { const block: AttemptCompletionToolUse = { type: "tool_use", name: "attempt_completion", @@ -792,7 +788,12 @@ describe("attemptCompletionTool", () => { await attemptCompletionTool.handle(mockTask as Task, block, callbacks) expect(mockHandleError).not.toHaveBeenCalled() - expect(mockCaptureTaskCompleted).not.toHaveBeenCalled() + // Telemetry is reported on every model-initiated attempt_completion call, + // regardless of whether the user accepts, declines, or gives feedback. + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(mockTask.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") + // The public RooCodeEventName.TaskCompleted API event still only fires once + // the user actually accepts the result. expect(mockTask.emit).not.toHaveBeenCalledWith( RooCodeEventName.TaskCompleted, expect.anything(), @@ -804,3 +805,161 @@ describe("attemptCompletionTool", () => { }) }) }) + +describe("attemptCompletionTool telemetry invariants", () => { + function makeTask(overrides: Partial = {}): Partial { + return { + consecutiveMistakeCount: 0, + recordToolError: vi.fn(), + todoList: undefined, + say: vi.fn().mockResolvedValue(undefined), + ask: vi.fn().mockResolvedValue({ response: "yesButtonClicked", text: "", images: [] }), + emitFinalTokenUsageUpdate: vi.fn(), + emit: vi.fn(), + getTokenUsage: vi.fn().mockReturnValue({}), + toolUsage: {}, + messageCounts: { user: 0, assistant: 0 }, + taskId: "task_1", + flushTelemetryInstallment: vi.fn(), + ...overrides, + } + } + + it("does not emit a duplicate telemetry installment when replaying an already-completed subtask from history", async () => { + const block: AttemptCompletionToolUse = { + type: "tool_use", + name: "attempt_completion", + params: { result: "done" }, + nativeArgs: { result: "done" }, + partial: false, + } + const mockProvider = { + log: vi.fn(), + getTaskWithId: vi.fn().mockImplementation((id: string) => { + if (id === "child-1") return Promise.resolve({ historyItem: { id, status: "completed" } }) + throw new Error(`unexpected task id ${id}`) + }), + reopenParentFromDelegation: vi.fn(), + } + + const task = makeTask({ + taskId: "child-1", + parentTaskId: "parent-1", + toolUsage: { read_file: { attempts: 5, failures: 0 } }, + messageCounts: { user: 3, assistant: 4 }, + }) + Object.assign(task, { providerRef: { deref: () => mockProvider } }) + + await attemptCompletionTool.handle(task as Task, block, { + askApproval: vi.fn(), + handleError: vi.fn(), + pushToolResult: vi.fn(), + askFinishSubTaskApproval: vi.fn(), + toolDescription: vi.fn(), + } as AttemptCompletionCallbacks) + + expect(task.flushTelemetryInstallment).not.toHaveBeenCalled() + }) + + it("does not emit the public TaskCompleted event when replaying an already-completed subtask from history", async () => { + const block: AttemptCompletionToolUse = { + type: "tool_use", + name: "attempt_completion", + params: { result: "done" }, + nativeArgs: { result: "done" }, + partial: false, + } + const mockProvider = { + log: vi.fn(), + getTaskWithId: vi.fn().mockImplementation((id: string) => { + if (id === "child-1") return Promise.resolve({ historyItem: { id, status: "completed" } }) + throw new Error(`unexpected task id ${id}`) + }), + reopenParentFromDelegation: vi.fn(), + } + + const task = makeTask({ + taskId: "child-1", + parentTaskId: "parent-1", + ask: vi.fn().mockResolvedValue({ response: "yesButtonClicked", text: "", images: [] }), + }) + Object.assign(task, { providerRef: { deref: () => mockProvider } }) + + await attemptCompletionTool.handle(task as Task, block, { + askApproval: vi.fn(), + handleError: vi.fn(), + pushToolResult: vi.fn(), + askFinishSubTaskApproval: vi.fn(), + toolDescription: vi.fn(), + } as AttemptCompletionCallbacks) + + expect(task.emit).not.toHaveBeenCalledWith( + RooCodeEventName.TaskCompleted, + expect.anything(), + expect.anything(), + expect.anything(), + ) + }) + + it("emits the public TaskCompleted API event only when completion is accepted, but reports telemetry either way", async () => { + const block: AttemptCompletionToolUse = { + type: "tool_use", + name: "attempt_completion", + params: { result: "done" }, + nativeArgs: { result: "done" }, + partial: false, + } + + const task = makeTask({ + ask: vi.fn().mockResolvedValue({ response: "yesButtonClicked", text: "", images: [] }), + }) + + await attemptCompletionTool.handle(task as Task, block, { + askApproval: vi.fn(), + handleError: vi.fn(), + pushToolResult: vi.fn(), + askFinishSubTaskApproval: vi.fn(), + toolDescription: vi.fn(), + } as AttemptCompletionCallbacks) + + expect(task.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(task.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") + expect(task.emit).toHaveBeenCalledWith( + RooCodeEventName.TaskCompleted, + "task_1", + expect.anything(), + expect.anything(), + ) + }) + + it("still reports telemetry for a model-initiated completion even when the user provides follow-up feedback instead of accepting", async () => { + const block: AttemptCompletionToolUse = { + type: "tool_use", + name: "attempt_completion", + params: { result: "done" }, + nativeArgs: { result: "done" }, + partial: false, + } + + const task = makeTask({ + ask: vi.fn().mockResolvedValue({ response: "messageResponse", text: "one more thing", images: [] }), + }) + + await attemptCompletionTool.handle(task as Task, block, { + askApproval: vi.fn(), + handleError: vi.fn(), + pushToolResult: vi.fn(), + askFinishSubTaskApproval: vi.fn(), + toolDescription: vi.fn(), + } as AttemptCompletionCallbacks) + + expect(task.flushTelemetryInstallment).toHaveBeenCalledTimes(1) + expect(task.flushTelemetryInstallment).toHaveBeenCalledWith("attempt_completion") + expect(task.emit).not.toHaveBeenCalledWith( + RooCodeEventName.TaskCompleted, + expect.anything(), + expect.anything(), + expect.anything(), + ) + }) +}) diff --git a/src/eslint-suppressions.json b/src/eslint-suppressions.json index 608e190d04..f9bc219167 100644 --- a/src/eslint-suppressions.json +++ b/src/eslint-suppressions.json @@ -854,11 +854,6 @@ "count": 8 } }, - "core/task/__tests__/Task.spec.ts": { - "@typescript-eslint/no-explicit-any": { - "count": 31 - } - }, "core/task/__tests__/Task.sticky-profile-race.spec.ts": { "@typescript-eslint/no-explicit-any": { "count": 3