From a1cb359c0ffd47b0c48f2aa17c080da2f4571b67 Mon Sep 17 00:00:00 2001 From: Philipp Spiess Date: Thu, 10 Aug 2023 19:23:57 +0200 Subject: [PATCH] Autocomplete: Fix suggestion event over counting (#649) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This PR fixes an issue that sometimes caused completion suggestion events to not fire correctly. The issue here was that we decided wether or not a completion is visible in the `getInlineCompletions` code that was now change to _still yield completions_. The yielding is fine, we have relied on these results to be used for the last candidate cache. However, this would also mean that we would store a log id that was _deemed as not visible_ but that never reconsidered this condition. This meant that such a completion could become visible later and we would be able to accept it, even though it was never logged as suggested. To fix this, we move this logic into the VS Code specific part (which conceptually makes more sense anyways since it's full of VS Code specific logic) and also test the visibility after every cache retrieval. ## Test plan I've added three conditions to test invariants that should not be possible. To test locally, I've added debugger break points into either of them and repeatedly triggered a bazillion of completions. After these changes, I don't seem to be able to trigger them anymore. I’m leaving some logs in there, though, so we can see if they happen on production. --- vscode/CHANGELOG.md | 1 + .../completions/getInlineCompletions.test.ts | 67 ++-------- .../src/completions/getInlineCompletions.ts | 100 +-------------- vscode/src/completions/logger.ts | 12 ++ ...vscodeInlineCompletionItemProvider.test.ts | 107 +++++++++++++++- .../vscodeInlineCompletionItemProvider.ts | 121 ++++++++++++++++-- .../run-code-completions-on-dataset.ts | 8 +- 7 files changed, 247 insertions(+), 169 deletions(-) diff --git a/vscode/CHANGELOG.md b/vscode/CHANGELOG.md index 95ff4830cd8b..793a0bdd87c5 100644 --- a/vscode/CHANGELOG.md +++ b/vscode/CHANGELOG.md @@ -17,6 +17,7 @@ Starting from `0.2.0`, Cody is using `major.EVEN_NUMBER.patch` for release versi - Update file link color to match buttons. [pull/600](https://github.com/sourcegraph/cody/pull/600) - Handle `socket hung up` errors that are not caused by the `stop generating` button. [pull/598](https://github.com/sourcegraph/cody/pull/598) - Fix "Reload Window" appearing in all VS Code views. [pull/603](https://github.com/sourcegraph/cody/pull/603) +- Fixes issues where in some instances, suggested autocomplete events were under counted. [pull/649](https://github.com/sourcegraph/cody/pull/649) ### Changed diff --git a/vscode/src/completions/getInlineCompletions.test.ts b/vscode/src/completions/getInlineCompletions.test.ts index 9c012aca3216..62af9f32fd33 100644 --- a/vscode/src/completions/getInlineCompletions.test.ts +++ b/vscode/src/completions/getInlineCompletions.test.ts @@ -1,5 +1,5 @@ import dedent from 'dedent' -import { describe, expect, test, vi } from 'vitest' +import { describe, expect, test } from 'vitest' import { Range } from 'vscode' import { URI } from 'vscode-uri' @@ -12,13 +12,13 @@ import { import { vsCodeMocks } from '../testutils/mocks' import { range } from '../testutils/textDocument' +import { getCurrentDocContext } from './document' import { getInlineCompletions as _getInlineCompletions, InlineCompletionsParams, InlineCompletionsResultSource, LastInlineCompletionCandidate, } from './getInlineCompletions' -import * as CompletionsLogger from './logger' import { createProviderConfig } from './providers/anthropic' import { RequestManager } from './request-manager' import { completion, documentAndPosition } from './testHelpers' @@ -47,7 +47,7 @@ function params( selectedCompletionInfo: undefined, }, ...params - }: Partial> & { + }: Partial> & { languageId?: string onNetworkRequest?: (params: CompletionParameters) => void } = {} @@ -68,13 +68,17 @@ function params( const { document, position } = documentAndPosition(code, languageId, URI_FIXTURE.toString()) + const docContext = getCurrentDocContext(document, position, 1000, 1000) + if (docContext === null) { + throw new Error() + } + return { document, position, context, + docContext, promptChars: 1000, - maxPrefixChars: 1000, - maxSuffixChars: 1000, isEmbeddingsContextEnabled: true, providerConfig, responsePercentage: 0.4, @@ -202,59 +206,6 @@ describe('getInlineCompletions', () => { }) }) - describe('logger', () => { - test('logs a completion as shown', async () => { - const spy = vi.spyOn(CompletionsLogger, 'suggested') - await getInlineCompletions(params('foo = █', [completion`bar`])) - expect(spy).toHaveBeenCalled() - }) - - test('does not log a completion when the abort handler was triggered after a network fetch', async () => { - const spy = vi.spyOn(CompletionsLogger, 'suggested') - const abortController = new AbortController() - await getInlineCompletions({ - ...params('const x = █', [completion`├1337┤`], { onNetworkRequest: () => abortController.abort() }), - abortSignal: abortController.signal, - }) - expect(spy).not.toHaveBeenCalled() - }) - - test('does not log a completion if it does not overlap the completion popup', async () => { - const spy = vi.spyOn(CompletionsLogger, 'suggested') - const abortController = new AbortController() - await getInlineCompletions({ - ...params('console.█', [completion`├log()┤`], { - context: { - triggerKind: vsCodeMocks.InlineCompletionTriggerKind.Automatic, - selectedCompletionInfo: { text: 'dir', range: new vsCodeMocks.Range(0, 6, 0, 8) }, - }, - }), - abortSignal: abortController.signal, - }) - expect(spy).not.toHaveBeenCalled() - }) - - test('log a completion if the suffix is inside the completion', async () => { - const spy = vi.spyOn(CompletionsLogger, 'suggested') - const abortController = new AbortController() - await getInlineCompletions({ - ...params('const a = [1, █];', [completion`├2] ;┤`]), - abortSignal: abortController.signal, - }) - expect(spy).toHaveBeenCalled() - }) - - test('does not log a completion if the suffix does not match', async () => { - const spy = vi.spyOn(CompletionsLogger, 'suggested') - const abortController = new AbortController() - await getInlineCompletions({ - ...params('const a = [1, █)(123);', [completion`├2];┤`]), - abortSignal: abortController.signal, - }) - expect(spy).not.toHaveBeenCalled() - }) - }) - describe('same line suffix behavior', () => { test('does not trigger when there are alphanumeric chars in the line suffix', async () => expect(await getInlineCompletions(params('foo = █ // x', []))).toBeNull()) diff --git a/vscode/src/completions/getInlineCompletions.ts b/vscode/src/completions/getInlineCompletions.ts index 736d16a10adb..01fb6bbb0b7d 100644 --- a/vscode/src/completions/getInlineCompletions.ts +++ b/vscode/src/completions/getInlineCompletions.ts @@ -7,7 +7,7 @@ import { debug } from '../log' import { GetContextOptions, GetContextResult } from './context/context' import { DocumentHistory } from './context/history' -import { DocumentContext, getCurrentDocContext } from './document' +import { DocumentContext } from './document' import * as CompletionLogger from './logger' import { detectMultiline } from './multiline' import { CompletionProviderTracer, Provider, ProviderConfig, ProviderOptions } from './providers/provider' @@ -22,11 +22,10 @@ export interface InlineCompletionsParams { document: vscode.TextDocument position: vscode.Position context: vscode.InlineCompletionContext + docContext: DocumentContext // Prompt parameters promptChars: number - maxPrefixChars: number - maxSuffixChars: number providerConfig: ProviderConfig responsePercentage: number prefixPercentage: number @@ -132,9 +131,8 @@ async function doGetInlineCompletions({ document, position, context, + docContext, promptChars, - maxPrefixChars, - maxSuffixChars, providerConfig, responsePercentage, prefixPercentage, @@ -153,11 +151,6 @@ async function doGetInlineCompletions({ }: InlineCompletionsParams): Promise { tracer?.({ params: { document, position, context } }) - const docContext = getCurrentDocContext(document, position, maxPrefixChars, maxSuffixChars) - if (!docContext) { - return null - } - // If we have a suffix in the same line as the cursor and the suffix contains any word // characters, do not attempt to make a completion. This means we only make completions if // we have a suffix in the same line for special characters like `)]}` etc. @@ -255,7 +248,7 @@ async function doGetInlineCompletions({ ? InlineCompletionsResultSource.CacheAfterRequestStart : InlineCompletionsResultSource.Network - logCompletions(logId, completions, document, docContext, context, providerConfig, source, abortSignal) + CompletionLogger.loaded(logId) return { logId, @@ -375,88 +368,3 @@ function createCompletionProviderTracer( } ) } - -function logCompletions( - logId: string, - completions: InlineCompletionItem[], - document: vscode.TextDocument, - docContext: DocumentContext, - context: vscode.InlineCompletionContext, - providerConfig: ProviderConfig, - source: InlineCompletionsResultSource, - abortSignal: AbortSignal | undefined -): void { - CompletionLogger.loaded(logId) - - // There are these cases when a completion is being returned here but won't - // be displayed by VS Code. - // - // - When the abort signal was already triggered and a new completion - // request was stared. - // - When the VS Code completion popup is open and we suggest a completion - // that does not match the currently selected completion. For now we make - // sure to not log these completions as displayed. - // TODO: Take this into account when creating the completion prefix. - // - When no completions contains characters in the current line that are - // not in the current line suffix. Since VS Code will try to merge - // completion with the suffix, we have to do a per-character diff to test - // this. - const isAborted = abortSignal ? abortSignal.aborted : false - const isMatchingPopupItem = completionMatchesPopupItem(completions, document, context) - const isMatchingSuffix = completionMatchesSuffix(completions, docContext, providerConfig) - const isVisible = !isAborted && isMatchingPopupItem && isMatchingSuffix - - if (isVisible) { - if (completions.length > 0) { - CompletionLogger.suggested(logId, InlineCompletionsResultSource[source]) - } else { - CompletionLogger.noResponse(logId) - } - } -} - -function completionMatchesPopupItem( - completions: InlineCompletionItem[], - document: vscode.TextDocument, - context: vscode.InlineCompletionContext -): boolean { - if (context.selectedCompletionInfo) { - const currentText = document.getText(context.selectedCompletionInfo.range) - const selectedText = context.selectedCompletionInfo.text - if (completions.length > 0 && !(currentText + completions[0].insertText).startsWith(selectedText)) { - return false - } - } - return true -} - -function completionMatchesSuffix( - completions: InlineCompletionItem[], - docContext: DocumentContext, - providerConfig: ProviderConfig -): boolean { - // Models that support infilling do not replace an existing suffix but - // instead insert the completion only at the current cursor position. Thus, - // we do not need to compare the suffix - if (providerConfig.supportsInfilling) { - return true - } - - const suffix = docContext.currentLineSuffix - - for (const completion of completions) { - const insertion = completion.insertText - let j = 0 - // eslint-disable-next-line @typescript-eslint/prefer-for-of - for (let i = 0; i < insertion.length; i++) { - if (insertion[i] === suffix[j]) { - j++ - } - } - if (j === suffix.length) { - return true - } - } - - return false -} diff --git a/vscode/src/completions/logger.ts b/vscode/src/completions/logger.ts index 01ee0ef82fff..e7d848834ae4 100644 --- a/vscode/src/completions/logger.ts +++ b/vscode/src/completions/logger.ts @@ -122,6 +122,18 @@ export function accept(id: string, lines: number): void { return } + // Some additional logging to ensure the invariant is correct. I expect these branches to never + // hit but if they do, they might help debug analytics issues + if (!completionEvent.loadedAt) { + logCompletionEvent('unexpectedNotLoaded') + } + if (!completionEvent.startLoggedAt) { + logCompletionEvent('unexpectedNotStarted') + } + if (!completionEvent.suggestedAt) { + logCompletionEvent('unexpectedNotSuggested') + } + completionEvent.acceptedAt = performance.now() logSuggestionEvents() diff --git a/vscode/src/completions/vscodeInlineCompletionItemProvider.test.ts b/vscode/src/completions/vscodeInlineCompletionItemProvider.test.ts index 6ac8ffbc7f54..e2f3d51c9f02 100644 --- a/vscode/src/completions/vscodeInlineCompletionItemProvider.test.ts +++ b/vscode/src/completions/vscodeInlineCompletionItemProvider.test.ts @@ -5,6 +5,7 @@ import type * as vscode from 'vscode' import { vsCodeMocks } from '../testutils/mocks' import { getInlineCompletions, InlineCompletionsResultSource } from './getInlineCompletions' +import * as CompletionLogger from './logger' import { createProviderConfig } from './providers/anthropic' import { documentAndPosition } from './testHelpers' import { InlineCompletionItem } from './types' @@ -72,8 +73,9 @@ describe('InlineCompletionItemProvider', () => { source: InlineCompletionsResultSource.Network, }) const provider = new MockableInlineCompletionItemProvider(fn) - const { items } = await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) - expect(items).toMatchInlineSnapshot(` + const result = await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) + expect(result).not.toBeNull() + expect(result!.items).toMatchInlineSnapshot(` [ InlineCompletionItem { "insertText": "const foo = test", @@ -157,4 +159,105 @@ describe('InlineCompletionItemProvider', () => { await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) expect(fn.mock.calls.map(call => call[0].lastCandidate?.result.items)).toEqual([[item]]) }) + + describe('logger', () => { + test('logs a completion as shown', async () => { + const spy = vi.spyOn(CompletionLogger, 'suggested') + + const { document, position } = documentAndPosition('const foo = █', 'typescript') + const fn = vi.fn(getInlineCompletions).mockResolvedValue({ + logId: '1', + items: [{ insertText: 'bar', range: new vsCodeMocks.Range(position, position) }], + source: InlineCompletionsResultSource.Network, + }) + + const provider = new MockableInlineCompletionItemProvider(fn) + await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) + + expect(spy).toHaveBeenCalled() + }) + + test('does not log a completion when the abort handler was triggered after a network fetch', async () => { + const spy = vi.spyOn(CompletionLogger, 'suggested') + + let onCancel = () => {} + const token: vscode.CancellationToken = { + isCancellationRequested: false, + onCancellationRequested(fn: any): vscode.Disposable { + onCancel = fn + return { dispose: () => {} } + }, + } + function cancel() { + token.isCancellationRequested = true + onCancel() + } + + const { document, position } = documentAndPosition('const foo = █', 'typescript') + const fn = vi.fn(getInlineCompletions).mockImplementation(() => { + cancel() + return Promise.resolve({ + logId: '1', + items: [{ insertText: 'bar', range: new vsCodeMocks.Range(position, position) }], + source: InlineCompletionsResultSource.Network, + }) + }) + + const provider = new MockableInlineCompletionItemProvider(fn) + await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT, token) + + expect(spy).not.toHaveBeenCalled() + }) + + test('does not log a completion if it does not overlap the completion popup', async () => { + const spy = vi.spyOn(CompletionLogger, 'suggested') + + const { document, position } = documentAndPosition('console.█', 'typescript') + const fn = vi.fn(getInlineCompletions).mockResolvedValue({ + logId: '1', + items: [{ insertText: 'log()', range: new vsCodeMocks.Range(position, position) }], + source: InlineCompletionsResultSource.Network, + }) + + const provider = new MockableInlineCompletionItemProvider(fn) + await provider.provideInlineCompletionItems(document, position, { + triggerKind: vsCodeMocks.InlineCompletionTriggerKind.Automatic, + selectedCompletionInfo: { text: 'dir', range: new vsCodeMocks.Range(0, 6, 0, 8) }, + }) + + expect(spy).not.toHaveBeenCalled() + }) + + test('log a completion if the suffix is inside the completion', async () => { + const spy = vi.spyOn(CompletionLogger, 'suggested') + + const { document, position } = documentAndPosition('const a = [1, █];', 'typescript') + const fn = vi.fn(getInlineCompletions).mockResolvedValue({ + logId: '1', + items: [{ insertText: '2] ;', range: new vsCodeMocks.Range(position, position) }], + source: InlineCompletionsResultSource.Network, + }) + + const provider = new MockableInlineCompletionItemProvider(fn) + await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) + + expect(spy).toHaveBeenCalled() + }) + + test('does not log a completion if the suffix does not match', async () => { + const spy = vi.spyOn(CompletionLogger, 'suggested') + + const { document, position } = documentAndPosition('const a = [1, █)(123);', 'typescript') + const fn = vi.fn(getInlineCompletions).mockResolvedValue({ + logId: '1', + items: [{ insertText: '2];', range: new vsCodeMocks.Range(position, position) }], + source: InlineCompletionsResultSource.Network, + }) + + const provider = new MockableInlineCompletionItemProvider(fn) + await provider.provideInlineCompletionItems(document, position, DUMMY_CONTEXT) + + expect(spy).not.toHaveBeenCalled() + }) + }) }) diff --git a/vscode/src/completions/vscodeInlineCompletionItemProvider.ts b/vscode/src/completions/vscodeInlineCompletionItemProvider.ts index 4c5ffea146e8..c784521b9e38 100644 --- a/vscode/src/completions/vscodeInlineCompletionItemProvider.ts +++ b/vscode/src/completions/vscodeInlineCompletionItemProvider.ts @@ -7,13 +7,14 @@ import { CodyStatusBar } from '../services/StatusBar' import { getContext, GetContextOptions, GetContextResult } from './context/context' import { DocumentHistory } from './context/history' +import { DocumentContext, getCurrentDocContext } from './document' import { getInlineCompletions, InlineCompletionsParams, InlineCompletionsResultSource, LastInlineCompletionCandidate, } from './getInlineCompletions' -import * as CompletionsLogger from './logger' +import * as CompletionLogger from './logger' import { ProviderConfig } from './providers/provider' import { RequestManager } from './request-manager' import { ProvideInlineCompletionItemsTracer, ProvideInlineCompletionsItemTraceData } from './tracer' @@ -38,7 +39,6 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem private promptChars: number private maxPrefixChars: number private maxSuffixChars: number - private abortOpenCompletions: () => void = () => {} private readonly config: Required @@ -107,7 +107,7 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem context: vscode.InlineCompletionContext, // Making it optional here to execute multiple suggestion in parallel from the CLI script. token?: vscode.CancellationToken - ): Promise { + ): Promise { const tracer = this.config.tracer ? createTracerForInvocation(this.config.tracer) : undefined let stopLoading: () => void | undefined @@ -120,22 +120,24 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem } const abortController = new AbortController() - this.abortOpenCompletions() if (token) { if (token.isCancellationRequested) { abortController.abort() } token.onCancellationRequested(() => abortController.abort()) - this.abortOpenCompletions = () => abortController.abort() + } + + const docContext = getCurrentDocContext(document, position, this.maxPrefixChars, this.maxSuffixChars) + if (!docContext) { + return null } const result = await this.getInlineCompletions({ document, position, context, + docContext, promptChars: this.promptChars, - maxPrefixChars: this.maxPrefixChars, - maxSuffixChars: this.maxSuffixChars, providerConfig: this.config.providerConfig, responsePercentage: this.config.responsePercentage, prefixPercentage: this.config.prefixPercentage, @@ -153,12 +155,16 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem tracer, }) + if (!result) { + return null + } + // Track the last candidate completion (that is shown as ghost text in the editor) so that // we can reuse it if the user types in such a way that it is still valid (such as by typing // `ab` if the ghost text suggests `abcd`). - if (result && result.source !== InlineCompletionsResultSource.LastCandidate) { + if (result.source !== InlineCompletionsResultSource.LastCandidate) { this.lastCandidate = - result?.items.length > 0 + result.items.length > 0 ? { uri: document.uri, lastTriggerPosition: position, @@ -176,6 +182,26 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem : undefined } + // A completion that won't be visible in VS Code will not be returned and not be logged. + if ( + !isCompletionVisible( + result?.items, + document, + docContext, + context, + this.config.providerConfig, + abortController.signal + ) + ) { + return null + } + + if (result.items.length > 0) { + CompletionLogger.suggested(result.logId, InlineCompletionsResultSource[result.source]) + } else { + CompletionLogger.noResponse(result.logId) + } + return { items: result ? this.processInlineCompletionsForVSCode(result.logId, document, position, result.items) : [], } @@ -186,7 +212,7 @@ export class InlineCompletionItemProvider implements vscode.InlineCompletionItem // log id is never reused if the completion is accepted. this.lastCandidate = undefined - CompletionsLogger.accept(logId, lines) + CompletionLogger.accept(logId, lines) } /** @@ -242,3 +268,78 @@ function createTracerForInvocation(tracer: ProvideInlineCompletionItemsTracer): tracer(data) } } + +function isCompletionVisible( + completions: InlineCompletionItem[], + document: vscode.TextDocument, + docContext: DocumentContext, + context: vscode.InlineCompletionContext, + providerConfig: ProviderConfig, + abortSignal: AbortSignal | undefined +): boolean { + // There are these cases when a completion is being returned here but won't + // be displayed by VS Code. + // + // - When the abort signal was already triggered and a new completion + // request was stared. + // - When the VS Code completion popup is open and we suggest a completion + // that does not match the currently selected completion. For now we make + // sure to not log these completions as displayed. + // TODO: Take this into account when creating the completion prefix. + // - When no completions contains characters in the current line that are + // not in the current line suffix. Since VS Code will try to merge + // completion with the suffix, we have to do a per-character diff to test + // this. + const isAborted = abortSignal ? abortSignal.aborted : false + const isMatchingPopupItem = completionMatchesPopupItem(completions, document, context) + const isMatchingSuffix = completionMatchesSuffix(completions, docContext, providerConfig) + const isVisible = !isAborted && isMatchingPopupItem && isMatchingSuffix + + return isVisible +} + +function completionMatchesPopupItem( + completions: InlineCompletionItem[], + document: vscode.TextDocument, + context: vscode.InlineCompletionContext +): boolean { + if (context.selectedCompletionInfo) { + const currentText = document.getText(context.selectedCompletionInfo.range) + const selectedText = context.selectedCompletionInfo.text + if (completions.length > 0 && !(currentText + completions[0].insertText).startsWith(selectedText)) { + return false + } + } + return true +} + +function completionMatchesSuffix( + completions: InlineCompletionItem[], + docContext: DocumentContext, + providerConfig: ProviderConfig +): boolean { + // Models that support infilling do not replace an existing suffix but + // instead insert the completion only at the current cursor position. Thus, + // we do not need to compare the suffix + if (providerConfig.supportsInfilling) { + return true + } + + const suffix = docContext.currentLineSuffix + + for (const completion of completions) { + const insertion = completion.insertText + let j = 0 + // eslint-disable-next-line @typescript-eslint/prefer-for-of + for (let i = 0; i < insertion.length; i++) { + if (insertion[i] === suffix[j]) { + j++ + } + } + if (j === suffix.length) { + return true + } + } + + return false +} diff --git a/vscode/test/completions/run-code-completions-on-dataset.ts b/vscode/test/completions/run-code-completions-on-dataset.ts index ee4c3b15e0a2..9fb092bdcd2e 100644 --- a/vscode/test/completions/run-code-completions-on-dataset.ts +++ b/vscode/test/completions/run-code-completions-on-dataset.ts @@ -135,9 +135,11 @@ async function generateCompletionsForDataset(codeSamples: Sample[]): Promise - typeof item.insertText === 'string' ? item.insertText : '' - ) + const completions = completionItems + ? ('items' in completionItems ? completionItems.items : completionItems).map(item => + typeof item.insertText === 'string' ? item.insertText : '' + ) + : [] console.error(`#${index}@i=${i}`, completions) codeSampleResults.push({ completions,