From 254a5f92b7b1d7211292d295d0ea7acdf218e58c Mon Sep 17 00:00:00 2001 From: Valery Bugakov Date: Mon, 6 Jan 2025 20:03:31 +0800 Subject: [PATCH] feat(audoedit): add `isRead` field --- .../analytics-logger/analytics-logger.test.ts | 115 ++++++---- .../analytics-logger/analytics-logger.ts | 211 ++++++++++++------ .../suggestion-id-registry.ts | 15 +- 3 files changed, 231 insertions(+), 110 deletions(-) diff --git a/vscode/src/autoedits/analytics-logger/analytics-logger.test.ts b/vscode/src/autoedits/analytics-logger/analytics-logger.test.ts index 0a12c97aca12..0f0b11ca11f5 100644 --- a/vscode/src/autoedits/analytics-logger/analytics-logger.test.ts +++ b/vscode/src/autoedits/analytics-logger/analytics-logger.test.ts @@ -1,13 +1,21 @@ import omit from 'lodash/omit' import * as uuid from 'uuid' -import { type MockInstance, afterEach, beforeEach, describe, expect, it, vi } from 'vitest' -import * as vscode from 'vscode' - -import { mockAuthStatus, ps, telemetryRecorder } from '@sourcegraph/cody-shared' +import { type MockInstance, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from 'vitest' +import { + isWindows, + mockAuthStatus, + ps, + setDisplayPathEnvInfo, + telemetryRecorder, +} from '@sourcegraph/cody-shared' + +import { getCurrentDocContext } from '../../completions/get-current-doc-context' import { documentAndPosition } from '../../completions/test-helpers' import * as sentryModule from '../../services/sentry/sentry' import type { AutoeditModelOptions } from '../adapters/base' +import { getCurrentFilePromptComponents } from '../prompt/prompt-utils' +import { getDecorationInfo } from '../renderer/diff-utils' import { AutoeditAnalyticsLogger, @@ -21,7 +29,30 @@ describe('AutoeditAnalyticsLogger', () => { let recordSpy: MockInstance let stableIdCounter = 0 + setDisplayPathEnvInfo({ + isWindows: isWindows(), + workspaceFolders: [], + }) + const { document, position } = documentAndPosition('█', 'typescript', 'file:///fake-file.ts') + const docContext = getCurrentDocContext({ + document, + position, + maxPrefixLength: 1000, + maxSuffixLength: 1000, + }) + + const { codeToReplaceData } = getCurrentFilePromptComponents({ + docContext, + position, + document, + tokenBudget: { + maxPrefixLinesInArea: 2, + maxSuffixLinesInArea: 2, + codeToRewritePrefixLines: 1, + codeToRewriteSuffixLines: 1, + }, + }) const modelOptions: AutoeditModelOptions = { url: 'https://test-url.com/', @@ -35,19 +66,27 @@ describe('AutoeditAnalyticsLogger', () => { isChatModel: false, } - const requestStartMetadata: Parameters[0] = { - languageId: 'typescript', - model: 'autoedit-model', - traceId: 'trace-id', - triggerKind: autoeditTriggerKind.automatic, - codeToRewrite: 'Code to rewrite', + function getRequestStartMetadata(): Parameters[0] { + return { + startedAt: performance.now(), + docContext, + document, + position, + codeToReplaceData, + payload: { + languageId: 'typescript', + model: 'autoedit-model', + triggerKind: autoeditTriggerKind.automatic, + codeToRewrite: 'Code to rewrite', + }, + } } function createAndAdvanceRequest({ finalPhase, prediction, }: { finalPhase: 'suggested' | 'accepted' | 'rejected'; prediction: string }): AutoeditRequestID { - const requestId = autoeditLogger.createRequest(requestStartMetadata) + const requestId = autoeditLogger.createRequest(getRequestStartMetadata()) autoeditLogger.markAsContextLoaded({ requestId, @@ -68,7 +107,7 @@ describe('AutoeditAnalyticsLogger', () => { autoeditLogger.markAsLoaded({ requestId, - modelOptions: modelOptions, + prompt: modelOptions.prompt, payload: { prediction, source: autoeditSource.network, @@ -77,16 +116,16 @@ describe('AutoeditAnalyticsLogger', () => { }, }) + autoeditLogger.markAsPostProcessed({ + requestId, + prediction, + inlineCompletionItems: [], + decorationInfo: getDecorationInfo(prediction, prediction), + }) autoeditLogger.markAsSuggested(requestId) if (finalPhase === 'accepted') { - autoeditLogger.markAsAccepted({ - requestId, - trackedRange: new vscode.Range(position, position), - position, - document, - prediction, - }) + autoeditLogger.markAsAccepted(requestId) } if (finalPhase === 'rejected') { @@ -96,15 +135,17 @@ describe('AutoeditAnalyticsLogger', () => { return requestId } + beforeAll(() => { + vi.useFakeTimers() + mockAuthStatus() + }) + beforeEach(() => { autoeditLogger = new AutoeditAnalyticsLogger() recordSpy = vi.spyOn(telemetryRecorder, 'recordEvent') - mockAuthStatus() stableIdCounter = 0 vi.spyOn(uuid, 'v4').mockImplementation(() => `stable-id-for-tests-${++stableIdCounter}`) - - vi.useFakeTimers() }) afterEach(() => { @@ -113,20 +154,14 @@ describe('AutoeditAnalyticsLogger', () => { }) it('logs a suggestion lifecycle (started -> contextLoaded -> loaded -> suggested -> accepted)', () => { - const prediction = 'console.log("Hello from autoedit!")' + const prediction = 'say("Hello from autoedit!")' const requestId = createAndAdvanceRequest({ finalPhase: 'accepted', prediction, }) // Invalid transition attempt - autoeditLogger.markAsAccepted({ - requestId, - trackedRange: new vscode.Range(position, position), - position, - document, - prediction, - }) + autoeditLogger.markAsAccepted(requestId) expect(recordSpy).toHaveBeenCalledTimes(3) expect(recordSpy).toHaveBeenNthCalledWith(1, 'cody.autoedit', 'suggested', expect.any(Object)) @@ -147,17 +182,17 @@ describe('AutoeditAnalyticsLogger', () => { }, "interactionID": "stable-id-for-tests-2", "metadata": { - "charCount": 35, + "charCount": 27, "contextSummary.duration": 1.234, "contextSummary.prefixChars": 5, "contextSummary.suffixChars": 5, "contextSummary.totalChars": 10, - "displayDuration": 0, "isAccepted": 1, "isDisjoint": 0, "isFullyOutsideOfVisibleRanges": 1, "isFuzzyMatch": 0, "isPartiallyOutsideOfVisibleRanges": 1, + "isRead": 1, "isSelectionStale": 1, "latency": 300, "lineCount": 1, @@ -166,7 +201,8 @@ describe('AutoeditAnalyticsLogger', () => { "outsideOfActiveEditor": 1, "recordsPrivateMetadataTranscript": 1, "source": 1, - "suggestionsStartedSinceLastSuggestion": 0, + "suggestionsStartedSinceLastSuggestion": 1, + "timeFromSuggestedAt": 0, "triggerKind": 1, "windowNotFocused": 1, }, @@ -185,9 +221,8 @@ describe('AutoeditAnalyticsLogger', () => { "languageId": "typescript", "model": "autoedit-model", "otherCompletionProviders": [], - "prediction": "console.log("Hello from autoedit!")", + "prediction": "say("Hello from autoedit!")", "responseHeaders": {}, - "traceId": "trace-id", "upstreamLatency": undefined, }, "version": 0, @@ -241,15 +276,15 @@ describe('AutoeditAnalyticsLogger', () => { const suggestedEvent3 = recordSpy.mock.calls[3].at(2) // First two suggested calls should reuse the same stable ID - expect(suggestedEvent1.privateMetadata.id).toEqual('stable-id-for-tests-2') - expect(suggestedEvent2.privateMetadata.id).toEqual('stable-id-for-tests-2') + expect(suggestedEvent1.privateMetadata.id).toEqual(suggestedEvent2.privateMetadata.id) // The third one should be different because we just accepted a completion // which removes the stable ID from the cache. - expect(suggestedEvent3.privateMetadata.id).toEqual('stable-id-for-tests-5') + expect(suggestedEvent3.privateMetadata.id).not.toBe(suggestedEvent1.privateMetadata.id) + expect(suggestedEvent3.privateMetadata.id).not.toBe(suggestedEvent2.privateMetadata.id) }) it('logs `discarded` if the suggestion was not suggested for any reason', () => { - const requestId = autoeditLogger.createRequest(requestStartMetadata) + const requestId = autoeditLogger.createRequest(getRequestStartMetadata()) autoeditLogger.markAsContextLoaded({ requestId, payload: { contextSummary: undefined } }) autoeditLogger.markAsDiscarded(requestId) @@ -258,7 +293,7 @@ describe('AutoeditAnalyticsLogger', () => { }) it('handles invalid transitions by logging debug events (invalidTransitionToXYZ)', () => { - const requestId = autoeditLogger.createRequest(requestStartMetadata) + const requestId = autoeditLogger.createRequest(getRequestStartMetadata()) // Both calls below are invalid transitions, so the logger logs debug events autoeditLogger.markAsSuggested(requestId) diff --git a/vscode/src/autoedits/analytics-logger/analytics-logger.ts b/vscode/src/autoedits/analytics-logger/analytics-logger.ts index 133d7dd1e691..d0bb087ebc74 100644 --- a/vscode/src/autoedits/analytics-logger/analytics-logger.ts +++ b/vscode/src/autoedits/analytics-logger/analytics-logger.ts @@ -1,11 +1,12 @@ import capitalize from 'lodash/capitalize' import { LRUCache } from 'lru-cache' import * as uuid from 'uuid' -import * as vscode from 'vscode' +import type * as vscode from 'vscode' import { type BillingCategory, type BillingProduct, + type DocumentContext, isDotComAuthed, isNetworkError, telemetryRecorder, @@ -19,9 +20,11 @@ import { type CodeGenEventMetadata, charactersLogger } from '../../services/Char import { upstreamHealthProvider } from '../../services/UpstreamHealthProvider' import { captureException, shouldErrorBeReported } from '../../services/sentry/sentry' import { splitSafeMetadata } from '../../services/telemetry-v2' +import type { AutoeditsPrompt } from '../adapters/base' +import type { CodeToReplaceData } from '../prompt/prompt-utils' +import type { DecorationInfo } from '../renderer/decorators/base' -import type { AutoeditModelOptions } from '../adapters/base' -import { AutoeditSuggestionIdRegistry } from './suggestion-id-registry' +import { autoeditIdRegistry } from './suggestion-id-registry' /** * This file implements a state machine to manage the lifecycle of an autoedit request. @@ -56,8 +59,17 @@ type Phase = | 'contextLoaded' /** The autoedit suggestion has been loaded — we have a prediction string. */ | 'loaded' + /** + * The suggestion is not discard during post processing and we have all the data to render the suggestion. + * This intermediate step is required for the agent API. We cannot graduate the request to the suggested + * state right away. We first need to save requests metadata to the analytics logger cache, so that + * agent can access it using the request ID only in `unstable_handleDidShowCompletionItem` calls. + */ + | 'postProcessed' /** The autoedit suggestion has been suggested to the user. */ | 'suggested' + /** The autoedit suggestion is marked as read is it's still visible to the user after a hardcoded timeout. */ + | 'read' /** The user has accepted the suggestion. */ | 'accepted' /** The user has rejected the suggestion. */ @@ -71,8 +83,10 @@ type Phase = const validRequestTransitions = { started: ['contextLoaded', 'discarded'], contextLoaded: ['loaded', 'discarded'], - loaded: ['suggested', 'discarded'], - suggested: ['accepted', 'rejected'], + loaded: ['postProcessed', 'discarded'], + postProcessed: ['suggested'], + suggested: ['read', 'accepted', 'rejected'], + read: ['accepted', 'rejected'], accepted: [], rejected: [], discarded: [], @@ -103,7 +117,7 @@ interface AutoeditStartedMetadata { model: string /** Optional trace ID for cross-service correlation, if your environment provides it. */ - traceId: string + traceId?: string /** Describes how the autoedit request was triggered by the user. */ triggerKind: AutoeditTriggerKindMetadata @@ -185,9 +199,21 @@ interface AutoeditLoadedMetadata extends AutoeditContextLoadedMetadata { interface AutoEditFinalMetadata extends AutoeditLoadedMetadata { /** Displayed to the user for this many milliseconds. */ - displayDuration: number + timeFromSuggestedAt: number /** True if the suggestion was explicitly/intentionally accepted. */ isAccepted: boolean + /** + * True if the suggestion was visible for a certain time + * Required to correctly calculate CAR and other metrics where we + * want to account only for suggestions visible for a certain time. + * + * `timeFromSuggestedAt` is not a reliable source of truth for + * this case because a user could have rejected a suggestion without + * triggering `accepted` or `discarded` immediately. This is related to + * limited VS Code APIs which do not provide a reliable way to know + * if a suggestion is really visible. + */ + isRead: boolean /** The number of the auto-edits started since the last suggestion was shown. */ suggestionsStartedSinceLastSuggestion: number } @@ -214,49 +240,77 @@ interface AutoeditBaseState { phase: Phase } -interface StartedState extends AutoeditBaseState { +export interface StartedState extends AutoeditBaseState { phase: 'started' /** Time (ms) when we started computing or requesting the suggestion. */ startedAt: number + + /** Metadata required to show a suggestion based on `requestId` only. */ + codeToReplaceData: CodeToReplaceData + document: vscode.TextDocument + position: vscode.Position + docContext: DocumentContext + /** Partial payload for this phase. Will be augmented with more info as we progress. */ payload: AutoeditStartedMetadata } -interface ContextLoadedState extends Omit { +export interface ContextLoadedState extends Omit { phase: 'contextLoaded' payload: AutoeditContextLoadedMetadata } -interface LoadedState extends Omit { +export interface LoadedState extends Omit { phase: 'loaded' /** Timestamp when the suggestion completed generation/loading. */ loadedAt: number payload: AutoeditLoadedMetadata } -interface SuggestedState extends Omit { +export interface PostProcessedState extends Omit { + phase: 'postProcessed' + + /** Metadata required to show a suggestion based on `requestId` only. */ + prediction: string + decorationInfo: DecorationInfo | null + inlineCompletionItems: vscode.InlineCompletionItem[] | null + + payload: AutoeditLoadedMetadata +} + +export interface SuggestedState extends Omit { phase: 'suggested' /** Timestamp when the suggestion was first shown to the user. */ suggestedAt: number } -interface AcceptedState extends Omit { +export interface ReadState extends Omit { + phase: 'read' + /** Timestamp when the suggestion was marked as visible to the user. */ + readAt: number +} + +export interface AcceptedState extends Omit { phase: 'accepted' /** Timestamp when the user accepted the suggestion. */ acceptedAt: number /** Timestamp when the suggestion was logged to our analytics backend. This is to avoid double-logging. */ suggestionLoggedAt?: number + /** Optional because it might be accepted before the read timeout */ + readAt?: number payload: AutoeditAcceptedEventPayload } -interface RejectedState extends Omit { +export interface RejectedState extends Omit { phase: 'rejected' /** Timestamp when the suggestion was logged to our analytics backend. This is to avoid double-logging. */ suggestionLoggedAt?: number + /** Optional because it might be accepted before the read timeout */ + readAt?: number payload: AutoeditRejectedEventPayload } -interface DiscardedState extends Omit { +export interface DiscardedState extends Omit { phase: 'discarded' /** Timestamp when the suggestion was logged to our analytics backend. This is to avoid double-logging. */ suggestionLoggedAt?: number @@ -267,7 +321,9 @@ interface PhaseStates { started: StartedState contextLoaded: ContextLoadedState loaded: LoadedState + postProcessed: PostProcessedState suggested: SuggestedState + read: ReadState accepted: AcceptedState rejected: RejectedState discarded: DiscardedState @@ -281,7 +337,7 @@ type PreviousPossiblePhaseFrom = { [F in Phase]: T extends (typeof validRequestTransitions)[F][number] ? PhaseStates[F] : never }[Phase] -type AutoeditRequestState = PhaseStates[Phase] +export type AutoeditRequestState = PhaseStates[Phase] type AutoeditEventAction = | 'suggested' @@ -301,11 +357,6 @@ export class AutoeditAnalyticsLogger { */ private activeRequests = new LRUCache({ max: 20 }) - /** - * Encapsulates the logic for reusing stable suggestion IDs for repeated text/context. - */ - private suggestionIdRegistry = new AutoeditSuggestionIdRegistry() - /** * Tracks repeated errors via their message key to avoid spamming logs. */ @@ -316,14 +367,23 @@ export class AutoeditAnalyticsLogger { /** * Creates a new ephemeral request with initial metadata. At this stage, we do not have the prediction yet. */ - public createRequest( + public createRequest({ + startedAt, + payload, + codeToReplaceData, + document, + position, + docContext, + }: { + startedAt: number + codeToReplaceData: CodeToReplaceData + document: vscode.TextDocument + position: vscode.Position + docContext: DocumentContext payload: Required< - Pick< - AutoeditStartedMetadata, - 'languageId' | 'model' | 'traceId' | 'triggerKind' | 'codeToRewrite' - > + Pick > - ): AutoeditRequestID { + }): AutoeditRequestID { const { codeToRewrite, ...restPayload } = payload const requestId = uuid.v4() as AutoeditRequestID const otherCompletionProviders = getOtherCompletionProvider() @@ -331,7 +391,11 @@ export class AutoeditAnalyticsLogger { const request: StartedState = { requestId, phase: 'started', - startedAt: getTimeNowInMillis(), + startedAt, + codeToReplaceData, + document, + position, + docContext, payload: { otherCompletionProviderEnabled: otherCompletionProviders.length > 0, otherCompletionProviders, @@ -371,34 +435,51 @@ export class AutoeditAnalyticsLogger { */ public markAsLoaded({ requestId, - modelOptions, + prompt, payload, }: { requestId: AutoeditRequestID - modelOptions: AutoeditModelOptions + prompt: AutoeditsPrompt payload: Required< Pick > }): void { const { prediction, source, isFuzzyMatch, responseHeaders } = payload - const stableId = this.suggestionIdRegistry.getOrCreate(modelOptions, prediction) + const stableId = autoeditIdRegistry.getOrCreate(prompt, prediction) const loadedAt = getTimeNowInMillis() - this.tryTransitionTo(requestId, 'loaded', request => ({ - ...request, - loadedAt, - payload: { - ...request.payload, - id: stableId, - lineCount: lines(prediction).length, - charCount: prediction.length, - // 🚨 SECURITY: included only for DotCom users. - prediction: isDotComAuthed() && prediction.length < 300 ? prediction : undefined, - source, - isFuzzyMatch, - responseHeaders, - latency: loadedAt - request.startedAt, - }, + this.tryTransitionTo(requestId, 'loaded', request => { + return { + ...request, + loadedAt, + payload: { + ...request.payload, + id: stableId, + lineCount: lines(prediction).length, + charCount: prediction.length, + // 🚨 SECURITY: included only for DotCom users. + prediction: isDotComAuthed() && prediction.length < 300 ? prediction : undefined, + source, + isFuzzyMatch, + responseHeaders, + latency: loadedAt - request.startedAt, + }, + } + }) + } + + public markAsPostProcessed({ + requestId, + ...state + }: { + requestId: AutoeditRequestID + prediction: string + decorationInfo: DecorationInfo | null + inlineCompletionItems: vscode.InlineCompletionItem[] | null + }) { + this.tryTransitionTo(requestId, 'postProcessed', currentRequest => ({ + ...currentRequest, + ...state, })) } @@ -412,33 +493,27 @@ export class AutoeditAnalyticsLogger { return null } - // Reset the number of the auto-edits started since the last suggestion. - this.autoeditsStartedSinceLastSuggestion = 0 - return result.updatedRequest } - public markAsAccepted({ - requestId, - trackedRange, - position, - document, - prediction, - }: { - requestId: AutoeditRequestID - trackedRange?: vscode.Range - position: vscode.Position - document: vscode.TextDocument - prediction: string - }): void { + public markAsRead(requestId: AutoeditRequestID): void { + this.tryTransitionTo(requestId, 'read', currentRequest => ({ + ...currentRequest, + readAt: getTimeNowInMillis(), + })) + } + + public markAsAccepted(requestId: AutoeditRequestID): void { const acceptedAt = getTimeNowInMillis() const result = this.tryTransitionTo(requestId, 'accepted', request => { + const { codeToReplaceData, document, prediction, payload } = request + // Ensure the AutoeditSuggestionID is never reused by removing it from the suggestion id registry - this.suggestionIdRegistry.deleteEntryIfValueExists(request.payload.id) + autoeditIdRegistry.deleteEntryIfValueExists(payload.id) // Calculate metadata required for PCW. - const rangeForCharacterMetadata = trackedRange || new vscode.Range(position, position) + const rangeForCharacterMetadata = codeToReplaceData.range const { charsDeleted, charsInserted, ...charactersLoggerMetadata } = charactersLogger.getChangeEventMetadataForCodyCodeGenEvents({ document, @@ -460,7 +535,8 @@ export class AutoeditAnalyticsLogger { ...request.payload, ...charactersLoggerMetadata, isAccepted: true, - displayDuration: acceptedAt - request.suggestedAt, + isRead: true, + timeFromSuggestedAt: acceptedAt - request.suggestedAt, suggestionsStartedSinceLastSuggestion: this.autoeditsStartedSinceLastSuggestion, }, } @@ -480,7 +556,8 @@ export class AutoeditAnalyticsLogger { payload: { ...request.payload, isAccepted: false, - displayDuration: getTimeNowInMillis() - request.suggestedAt, + isRead: 'readAt' in request, + timeFromSuggestedAt: getTimeNowInMillis() - request.suggestedAt, suggestionsStartedSinceLastSuggestion: this.autoeditsStartedSinceLastSuggestion, }, })) @@ -503,6 +580,10 @@ export class AutoeditAnalyticsLogger { } } + public getRequest(requestId: AutoeditRequestID): AutoeditRequestState | undefined { + return this.activeRequests.get(requestId) + } + private tryTransitionTo

( requestId: AutoeditRequestID, nextPhase: P, diff --git a/vscode/src/autoedits/analytics-logger/suggestion-id-registry.ts b/vscode/src/autoedits/analytics-logger/suggestion-id-registry.ts index 503cac896800..29a7a4117d7e 100644 --- a/vscode/src/autoedits/analytics-logger/suggestion-id-registry.ts +++ b/vscode/src/autoedits/analytics-logger/suggestion-id-registry.ts @@ -1,7 +1,7 @@ import { LRUCache } from 'lru-cache' import * as uuid from 'uuid' -import type { AutoeditModelOptions } from '../adapters/base' +import type { AutoeditsPrompt } from '../adapters/base' import type { AutoeditSuggestionID } from './analytics-logger' /** @@ -20,8 +20,8 @@ export class AutoeditSuggestionIdRegistry { * Produce a stable suggestion ID for the given context + text, reusing * previously generated IDs for duplicates. */ - public getOrCreate(options: AutoeditModelOptions, prediction: string): AutoeditSuggestionID { - const key = this.getAutoeditSuggestionKey(options, prediction) + public getOrCreate(prompt: AutoeditsPrompt, prediction: string): AutoeditSuggestionID { + const key = this.getAutoeditSuggestionKey(prompt, prediction) let stableId = this.suggestionIdCache.get(key) if (!stableId) { stableId = uuid.v4() as AutoeditSuggestionID @@ -34,10 +34,10 @@ export class AutoeditSuggestionIdRegistry { * Creates a stable string key that identifies the same suggestion across repeated displays. */ private getAutoeditSuggestionKey( - params: AutoeditModelOptions, + prompt: AutoeditsPrompt, prediction: string ): AutoeditSuggestionKey { - const key = `${params.prompt.systemMessage}█${params.prompt.userMessage}█${prediction}` + const key = `${prompt.systemMessage}█${prompt.userMessage}█${prediction}` return key as AutoeditSuggestionKey } @@ -55,3 +55,8 @@ export class AutoeditSuggestionIdRegistry { } } } + +/** + * Encapsulates the logic for reusing stable suggestion IDs for repeated text/context. + */ +export const autoeditIdRegistry = new AutoeditSuggestionIdRegistry()