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..0d9020ef36 100644 --- a/src/__tests__/history-resume-delegation.spec.ts +++ b/src/__tests__/history-resume-delegation.spec.ts @@ -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/core/task/Task.ts b/src/core/task/Task.ts index 8f69a3a0d4..2e5d97582b 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,72 @@ 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 + } + + this.emitFinalTokenUsageUpdate() + TelemetryService.instance.captureTaskCompleted(this.taskId, toolUsageDelta, messageCountDelta, reason) + + this.telemetryToolUsageBaseline = JSON.parse(JSON.stringify(this.toolUsage)) + this.telemetryMessageCountsBaseline = { ...this.messageCounts } + this.lastTelemetryFlushAt = Date.now() + } + + 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..854bd10f1d 100644 --- a/src/core/task/__tests__/Task.spec.ts +++ b/src/core/task/__tests__/Task.spec.ts @@ -3059,6 +3059,242 @@ 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() + }) + }) + + 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 mockApiConfig: ProviderSettings diff --git a/src/core/task/__tests__/messageCounting.retrySymmetry.spec.ts b/src/core/task/__tests__/messageCounting.retrySymmetry.spec.ts new file mode 100644 index 0000000000..c37d46c464 --- /dev/null +++ b/src/core/task/__tests__/messageCounting.retrySymmetry.spec.ts @@ -0,0 +1,131 @@ +// npx vitest run core/task/__tests__/messageCounting.retrySymmetry.spec.ts + +import { shouldAddUserMessageToHistory } from "../messageCounting" + +/** + * Regression coverage for the empty-assistant-response retry cycle in + * Task#recursivelyMakeClineRequests: the user message is added once (incrementing + * messageCounts.user), popped when the assistant fails to respond (decrementing + * messageCounts.user to match), then re-added on retry via userMessageWasRemoved + * (incrementing messageCounts.user again). This exercises that increment/decrement/ + * increment sequence end-to-end using the same primitives Task.ts calls, without + * needing to drive the full streaming loop. + */ +describe("empty-assistant-response retry keeps messageCounts.user symmetric", () => { + function simulateAttempt( + messageCounts: { user: number; assistant: number }, + params: { + retryAttempt: number | undefined + isEmptyUserContent: boolean + userMessageWasRemoved: boolean | undefined + }, + ) { + if (shouldAddUserMessageToHistory(params)) { + messageCounts.user++ + } + } + + function simulatePopOnEmptyResponse( + messageCounts: { user: number; assistant: number }, + shouldAddUserMessage = true, + ) { + // Mirrors Task.ts: pop the last user message from apiConversationHistory and + // decrement messageCounts.user only if this iteration actually incremented it. + // Messages added by flushPendingToolResultsToHistory or loaded from resumed + // history are not counted, so popping them must not decrement. + if (shouldAddUserMessage) { + messageCounts.user-- + } + } + + function simulateDeclineRetry(messageCounts: { user: number; assistant: number }) { + // Mirrors Task.ts's "User declined to retry" branch: the popped user message is + // re-added directly (not via shouldAddUserMessageToHistory) and a synthetic failure + // assistant message is appended, so both increments are paired explicitly here + // rather than going through simulateAttempt. + messageCounts.user++ + messageCounts.assistant++ + } + + it("ends at 1 after one empty-response retry that then succeeds (not 2)", () => { + const messageCounts = { user: 0, assistant: 0 } + + // First attempt: message added, count incremented. + simulateAttempt(messageCounts, { retryAttempt: 0, isEmptyUserContent: false, userMessageWasRemoved: false }) + expect(messageCounts.user).toBe(1) + + // Assistant returns nothing -- Task.ts pops the message it just added. + simulatePopOnEmptyResponse(messageCounts) + expect(messageCounts.user).toBe(0) + + // Retry (either auto or manual-approved branch) re-adds it via userMessageWasRemoved. + simulateAttempt(messageCounts, { retryAttempt: 1, isEmptyUserContent: false, userMessageWasRemoved: true }) + + // Exactly one logical user turn occurred -- the count must reflect that, not 2. + expect(messageCounts.user).toBe(1) + }) + + it("stays symmetric across multiple consecutive empty-response retries", () => { + const messageCounts = { user: 0, assistant: 0 } + + simulateAttempt(messageCounts, { retryAttempt: 0, isEmptyUserContent: false, userMessageWasRemoved: false }) + simulatePopOnEmptyResponse(messageCounts) + + simulateAttempt(messageCounts, { retryAttempt: 1, isEmptyUserContent: false, userMessageWasRemoved: true }) + simulatePopOnEmptyResponse(messageCounts) + + simulateAttempt(messageCounts, { retryAttempt: 2, isEmptyUserContent: false, userMessageWasRemoved: true }) + simulatePopOnEmptyResponse(messageCounts) + + // Final successful attempt. + simulateAttempt(messageCounts, { retryAttempt: 3, isEmptyUserContent: false, userMessageWasRemoved: true }) + + expect(messageCounts.user).toBe(1) + }) + + it("never goes negative when a message is popped and correctly re-added", () => { + const messageCounts = { user: 0, assistant: 0 } + + simulateAttempt(messageCounts, { retryAttempt: 0, isEmptyUserContent: false, userMessageWasRemoved: false }) + simulatePopOnEmptyResponse(messageCounts) + simulateAttempt(messageCounts, { retryAttempt: 1, isEmptyUserContent: false, userMessageWasRemoved: true }) + + expect(messageCounts.user).toBeGreaterThanOrEqual(0) + }) + + it("stays symmetric when the user declines to retry after an empty response", () => { + const messageCounts = { user: 0, assistant: 0 } + + // First attempt: user message added, count incremented. + simulateAttempt(messageCounts, { retryAttempt: 0, isEmptyUserContent: false, userMessageWasRemoved: false }) + expect(messageCounts).toEqual({ user: 1, assistant: 0 }) + + // Assistant returns nothing -- popped, decremented. + simulatePopOnEmptyResponse(messageCounts) + expect(messageCounts).toEqual({ user: 0, assistant: 0 }) + + // User declines to retry: message is re-added directly, plus a synthetic failure + // assistant message -- exactly one logical user turn and one assistant turn + // occurred overall, so both counters must end at 1, not 0. + simulateDeclineRetry(messageCounts) + expect(messageCounts).toEqual({ user: 1, assistant: 1 }) + }) + + it("does not go negative when the popped message was not counted by this iteration (e.g. flushPendingToolResultsToHistory)", () => { + // Scenario: a user message was appended to apiConversationHistory by + // flushPendingToolResultsToHistory (or loaded from resumed history) without + // incrementing messageCounts.user. shouldAddUserMessage is false for this + // turn (empty content). The assistant returns nothing and the pop fires. + // The count must stay at 0, not go to -1. + const messageCounts = { user: 0, assistant: 0 } + + // This turn: empty content, so shouldAddUserMessageToHistory returns false. + const shouldAddUserMessage = false + simulateAttempt(messageCounts, { retryAttempt: 0, isEmptyUserContent: true, userMessageWasRemoved: false }) + expect(messageCounts.user).toBe(0) + + // Assistant returns nothing -- pop fires but guard skips the decrement. + simulatePopOnEmptyResponse(messageCounts, shouldAddUserMessage) + expect(messageCounts.user).toBe(0) + }) +}) 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..3239439ba1 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,15 @@ 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.emitFinalTokenUsageUpdate() + task.flushTelemetryInstallment("attempt_completion") + hasFlushedTelemetry = true + const delegation = await this.delegateToParent( task, result, @@ -113,7 +135,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 +169,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 +259,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..6b101c661b 100644 --- a/src/core/tools/__tests__/attemptCompletionTool.spec.ts +++ b/src/core/tools/__tests__/attemptCompletionTool.spec.ts @@ -81,9 +81,13 @@ 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((reason: "attempt_completion" | "idle" | "shutdown") => { + mockCaptureTaskCompleted(mockTask.taskId, mockTask.toolUsage, mockTask.messageCounts, reason) + }), } }) @@ -585,7 +589,9 @@ describe("attemptCompletionTool", () => { }) expect(mockTask.ask).toHaveBeenCalledWith("completion_result", "", false) expect(mockPushToolResult).not.toHaveBeenCalledWith("") - expect(mockCaptureTaskCompleted).not.toHaveBeenCalled() + // Emission now happens once per validated attempt_completion call, before + // delegation is attempted -- independent of whether delegation succeeds. + expect(mockCaptureTaskCompleted).toHaveBeenCalledTimes(1) }) it("does not resume the parent when the parent is no longer awaiting this child", async () => { @@ -633,7 +639,12 @@ 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(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "child-1", + {}, + { user: 0, assistant: 0 }, + "attempt_completion", + ) }) it("delegates an interrupted subtask completion when the parent is still delegated and awaiting that child", async () => { @@ -732,7 +743,12 @@ 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(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "child-1", + {}, + { user: 0, assistant: 0 }, + "attempt_completion", + ) }) it("emits TaskCompleted only when completion is accepted", async () => { @@ -757,7 +773,12 @@ describe("attemptCompletionTool", () => { await attemptCompletionTool.handle(mockTask as Task, block, callbacks) expect(mockHandleError).not.toHaveBeenCalled() - expect(mockCaptureTaskCompleted).toHaveBeenCalledWith("task_1") + expect(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "task_1", + {}, + { user: 0, assistant: 0 }, + "attempt_completion", + ) expect(mockTask.emit).toHaveBeenCalledWith( RooCodeEventName.TaskCompleted, "task_1", @@ -766,7 +787,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 +813,16 @@ 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(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "task_1", + {}, + { user: 0, assistant: 0 }, + "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 +834,177 @@ describe("attemptCompletionTool", () => { }) }) }) + +// Uses the same top-level mocks (vi.mock("@roo-code/telemetry") etc.) and +// mockCaptureTaskCompleted already established for the "attemptCompletionTool" suite above. +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((reason: "attempt_completion" | "idle" | "shutdown") => { + mockCaptureTaskCompleted("task_1", {}, { user: 0, assistant: 0 }, reason) + }), + ...overrides, + } + } + + beforeEach(() => { + mockCaptureTaskCompleted.mockReset() + }) + + 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(mockCaptureTaskCompleted).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(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "task_1", + {}, + { user: 0, assistant: 0 }, + "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(mockCaptureTaskCompleted).toHaveBeenCalledWith( + "task_1", + {}, + { user: 0, assistant: 0 }, + "attempt_completion", + ) + expect(task.emit).not.toHaveBeenCalledWith( + RooCodeEventName.TaskCompleted, + expect.anything(), + expect.anything(), + expect.anything(), + ) + }) +})