Microsoft/vscode
1
0
Fork 0
mirror of https://github.com/microsoft/vscode.git synced 2026-06-01 05:04:59 +01:00
Code Issues Packages Projects Releases Wiki Activity

logService: feat: migrate ITracer to ILogger interface (#3127)

Browse Source 
* logService: feat: migrate ITracer to ILogger interface

Replace deprecated ITracer interface with ILogger across inline edits
and xtab providers. Add LogTarget.fromCallback() and withExtraTarget()
to ILogger for callback-based logging support previously provided by
ITracer's sub() method.

* tracing: migrate off of ITracer in favor of ILogService

* Update src/extension/xtab/node/xtabProvider.ts

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

* address copilot review

---------

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
This commit is contained in:
Ulugbek Abdullaev
2026-01-26 10:52:49 +01:00
committed by GitHub
parent e8e9b03ba7
commit 0ae760bbed
28 changed files with 614 additions and 449 deletions
Download Patch File Download Diff File Expand all files Collapse all files
extensions/copilot/src/extension/inlineEdits/common/editRebase.ts
+10 -10
View File
@@ -5,7 +5,7 @@
import { SingleEdits } from '../../../platform/inlineEdits/common/dataTypes/edit';
import * as errors from '../../../util/common/errors';
import { ITracer } from '../../../util/common/tracing';
import { ILogger } from '../../../platform/log/common/logService';
import { AnnotatedStringEdit, AnnotatedStringReplacement, IEditData, StringEdit, StringReplacement, VoidEditData } from '../../../util/vs/editor/common/core/edits/stringEdit';
import { OffsetRange } from '../../../util/vs/editor/common/core/ranges/offsetRange';
import { StringText } from '../../../util/vs/editor/common/core/text/abstractText';
@@ -30,20 +30,20 @@ export class EditDataWithIndex implements IEditData<EditDataWithIndex> {
}
}
export function tryRebase(originalDocument: string, editWindow: OffsetRange | undefined, originalEdits: readonly StringReplacement[], detailedEdits: AnnotatedStringReplacement<EditDataWithIndex>[][], userEditSince: StringEdit, currentDocumentContent: string, currentSelection: readonly OffsetRange[], resolution: 'strict' | 'lenient', tracer: ITracer, nesConfigs: NesRebaseConfigs = {}): { rebasedEdit: StringReplacement; rebasedEditIndex: number }[] | 'outsideEditWindow' | 'rebaseFailed' | 'error' | 'inconsistentEdits' {
export function tryRebase(originalDocument: string, editWindow: OffsetRange | undefined, originalEdits: readonly StringReplacement[], detailedEdits: AnnotatedStringReplacement<EditDataWithIndex>[][], userEditSince: StringEdit, currentDocumentContent: string, currentSelection: readonly OffsetRange[], resolution: 'strict' | 'lenient', logger: ILogger, nesConfigs: NesRebaseConfigs = {}): { rebasedEdit: StringReplacement; rebasedEditIndex: number }[] | 'outsideEditWindow' | 'rebaseFailed' | 'error' | 'inconsistentEdits' {
const start = Date.now();
try {
return _tryRebase(originalDocument, editWindow, originalEdits, detailedEdits, userEditSince, currentDocumentContent, currentSelection, resolution, tracer, nesConfigs);
return _tryRebase(originalDocument, editWindow, originalEdits, detailedEdits, userEditSince, currentDocumentContent, currentSelection, resolution, logger, nesConfigs);
} catch (err) {
tracer.trace(`Rebase error: ${errors.toString(err)}`);
logger.trace(`Rebase error: ${errors.toString(err)}`);
return 'error';
} finally {
tracer.trace(`Rebase duration: ${Date.now() - start}ms`);
logger.trace(`Rebase duration: ${Date.now() - start}ms`);
}
}
function _tryRebase(originalDocument: string, editWindow: OffsetRange | undefined, originalEdits: readonly StringReplacement[], detailedEdits: AnnotatedStringReplacement<EditDataWithIndex>[][], userEditSinceOrig: StringEdit, currentDocumentContent: string, currentSelection: readonly OffsetRange[], resolution: 'strict' | 'lenient', tracer: ITracer, nesConfigs: NesRebaseConfigs) {
if (!checkEditConsistency(originalDocument, userEditSinceOrig, currentDocumentContent, tracer, true)) {
function _tryRebase(originalDocument: string, editWindow: OffsetRange | undefined, originalEdits: readonly StringReplacement[], detailedEdits: AnnotatedStringReplacement<EditDataWithIndex>[][], userEditSinceOrig: StringEdit, currentDocumentContent: string, currentSelection: readonly OffsetRange[], resolution: 'strict' | 'lenient', logger: ILogger, nesConfigs: NesRebaseConfigs) {
if (!checkEditConsistency(originalDocument, userEditSinceOrig, currentDocumentContent, logger, true)) {
return 'inconsistentEdits';
}
const userEditSince = userEditSinceOrig.removeCommonSuffixAndPrefix(originalDocument);
@@ -101,19 +101,19 @@ function _tryRebase(originalDocument: string, editWindow: OffsetRange | undefine
}
}
if (resolution === 'strict' && resultEdits.length > 0 && new SingleEdits(originalEdits).apply(originalDocument) !== StringEdit.create(resultEdits.map(r => r.rebasedEdit)).apply(currentDocumentContent)) {
tracer.trace('Result consistency check failed.');
logger.trace('Result consistency check failed');
return 'inconsistentEdits';
}
return resultEdits;
}
export function checkEditConsistency(original: string, edit: StringEdit, current: string, tracer: ITracer, enabled = TROUBLESHOOT_EDIT_CONSISTENCY) {
export function checkEditConsistency(original: string, edit: StringEdit, current: string, logger: ILogger, enabled = TROUBLESHOOT_EDIT_CONSISTENCY) {
if (!enabled) {
return true;
}
const consistent = edit.apply(original) === current;
if (!consistent) {
tracer.trace('Edit consistency check failed.');
logger.trace('Edit consistency check failed');
}
return consistent;
}
extensions/copilot/src/extension/inlineEdits/common/rejectionCollector.ts
+11 -11
View File
@@ -6,7 +6,7 @@
import { DocumentId } from '../../../platform/inlineEdits/common/dataTypes/documentId';
import { IObservableDocument, ObservableWorkspace } from '../../../platform/inlineEdits/common/observableWorkspace';
import { autorunWithChanges } from '../../../platform/inlineEdits/common/utils/observable';
import { createTracer, ITracer } from '../../../util/common/tracing';
import { ILogger, ILogService } from '../../../platform/log/common/logService';
import { Disposable, IDisposable, toDisposable } from '../../../util/vs/base/common/lifecycle';
import { mapObservableArrayCached } from '../../../util/vs/base/common/observable';
import { StringEdit, StringReplacement } from '../../../util/vs/editor/common/core/edits/stringEdit';
@@ -15,18 +15,18 @@ import { StringText } from '../../../util/vs/editor/common/core/text/abstractTex
export class RejectionCollector extends Disposable {
private readonly _garbageCollector = this._register(new LRUGarbageCollector(20));
private readonly _documentCaches = new Map<DocumentId, DocumentRejectionTracker>();
private readonly _tracer: ITracer;
private readonly _logger: ILogger;
constructor(
public readonly workspace: ObservableWorkspace,
trace: (s: string) => void,
logService: ILogService,
) {
super();
this._tracer = createTracer(['NES', 'RejectionCollector'], trace);
this._logger = logService.createSubLogger(['NES', 'RejectionCollector']);
mapObservableArrayCached(this, workspace.openDocuments, (doc, store) => {
const state = new DocumentRejectionTracker(doc, this._garbageCollector, this._tracer);
const state = new DocumentRejectionTracker(doc, this._garbageCollector, this._logger);
this._documentCaches.set(state.doc.id, state);
store.add(autorunWithChanges(this, {
@@ -48,23 +48,23 @@ export class RejectionCollector extends Disposable {
public reject(docId: DocumentId, edit: StringReplacement): void {
const docCache = this._documentCaches.get(docId);
if (!docCache) {
this._tracer.trace(`Rejecting, no document cache: ${edit}`);
this._logger.trace(`Rejecting, no document cache: ${edit}`);
return;
}
const e = edit.removeCommonSuffixAndPrefix(docCache.doc.value.get().value);
this._tracer.trace(`Rejecting: ${e}`);
this._logger.trace(`Rejecting: ${e}`);
docCache.reject(e);
}
public isRejected(docId: DocumentId, edit: StringReplacement): boolean {
const docCache = this._documentCaches.get(docId);
if (!docCache) {
this._tracer.trace(`Checking rejection, no document cache: ${edit}`);
this._logger.trace(`Checking rejection, no document cache: ${edit}`);
return false;
}
const e = edit.removeCommonSuffixAndPrefix(docCache.doc.value.get().value);
const isRejected = docCache.isRejected(e);
this._tracer.trace(`Checking rejection, ${isRejected ? 'rejected' : 'not rejected'}: ${e}`);
this._logger.trace(`Checking rejection, ${isRejected ? 'rejected' : 'not rejected'}: ${e}`);
return isRejected;
}
@@ -79,7 +79,7 @@ class DocumentRejectionTracker {
constructor(
public readonly doc: IObservableDocument,
private readonly _garbageCollector: LRUGarbageCollector,
private readonly _tracer: ITracer,
private readonly _logger: ILogger,
) {
}
@@ -95,7 +95,7 @@ class DocumentRejectionTracker {
return;
}
const r = new RejectedEdit(edit.toEdit(), () => {
this._tracer.trace(`Evicting: ${edit}`);
this._logger.trace(`Evicting: ${edit}`);
this._rejectedEdits.delete(r);
});
this._rejectedEdits.add(r);
extensions/copilot/src/extension/inlineEdits/node/nextEditCache.ts
+12 -13
View File
@@ -7,10 +7,9 @@ import { ConfigKey, IConfigurationService } from '../../../platform/configuratio
import { DocumentId } from '../../../platform/inlineEdits/common/dataTypes/documentId';
import { IObservableDocument, ObservableWorkspace } from '../../../platform/inlineEdits/common/observableWorkspace';
import { autorunWithChanges } from '../../../platform/inlineEdits/common/utils/observable';
import { ILogService } from '../../../platform/log/common/logService';
import { ILogger, ILogService } from '../../../platform/log/common/logService';
import { IExperimentationService } from '../../../platform/telemetry/common/nullExperimentationService';
import { LRUCache } from '../../../util/common/cache';
import { createTracer, ITracer } from '../../../util/common/tracing';
import { Disposable, toDisposable } from '../../../util/vs/base/common/lifecycle';
import { mapObservableArrayCached } from '../../../util/vs/base/common/observableInternal';
import { AnnotatedStringReplacement, StringEdit, StringReplacement } from '../../../util/vs/editor/common/core/edits/stringEdit';
@@ -149,25 +148,25 @@ export class NextEditCache extends Disposable {
class DocumentEditCache {
private readonly _trackedCachedEdits: CachedEdit[] = [];
private _tracer: ITracer;
private _logger: ILogger;
constructor(
private readonly _nextEditCache: NextEditCache,
public readonly docId: DocumentId,
private readonly _doc: IObservableDocument,
private readonly _sharedCache: LRUCache<CachedEdit>,
private readonly _logService: ILogService,
_logService: ILogService,
) {
this._tracer = createTracer(['NES', 'DocumentEditCache'], (s) => this._logService.trace(s));
this._logger = _logService.createSubLogger(['NES', 'DocumentEditCache']);
}
public handleEdit(edit: StringEdit): void {
const tracer = this._tracer.sub('handleEdit');
const logger = this._logger.createSubLogger('handleEdit');
for (const cachedEdit of this._trackedCachedEdits) {
if (cachedEdit.userEditSince) {
cachedEdit.userEditSince = cachedEdit.userEditSince.compose(edit);
cachedEdit.rebaseFailed = false;
if (!checkEditConsistency(cachedEdit.documentBeforeEdit.value, cachedEdit.userEditSince, this._doc.value.get().value, tracer)) {
if (!checkEditConsistency(cachedEdit.documentBeforeEdit.value, cachedEdit.userEditSince, this._doc.value.get().value, logger)) {
cachedEdit.userEditSince = undefined;
}
}
@@ -189,7 +188,7 @@ class DocumentEditCache {
const key = this._getKey(documentContents.value);
const cachedEdit: CachedEdit = { docId: this.docId, edit: nextEdit, edits: nextEdits, detailedEdits: [], userEditSince, subsequentN, source, documentBeforeEdit: documentContents, editWindow, cacheTime: Date.now(), isFromCursorJump: opts.isFromCursorJump };
if (userEditSince) {
if (!checkEditConsistency(cachedEdit.documentBeforeEdit.value, userEditSince, this._doc.value.get().value, this._tracer.sub('setKthNextEdit'))) {
if (!checkEditConsistency(cachedEdit.documentBeforeEdit.value, userEditSince, this._doc.value.get().value, this._logger.createSubLogger('setKthNextEdit'))) {
cachedEdit.userEditSince = undefined;
} else {
this._trackedCachedEdits.unshift(cachedEdit);
@@ -241,10 +240,10 @@ class DocumentEditCache {
}
public tryRebaseCacheEntry(cachedEdit: CachedEdit, currentDocumentContents: StringText, currentSelection: readonly OffsetRange[], nesConfigs: INesConfigs): CachedEdit | undefined {
const tracer = this._tracer.sub('tryRebaseCacheEntry');
const logger = this._logger.createSubLogger('tryRebaseCacheEntry');
if (cachedEdit.userEditSince && !cachedEdit.rebaseFailed) {
const originalEdits = cachedEdit.edits || (cachedEdit.edit ? [cachedEdit.edit] : []);
const res = tryRebase(cachedEdit.documentBeforeEdit.value, cachedEdit.editWindow, originalEdits, cachedEdit.detailedEdits, cachedEdit.userEditSince, currentDocumentContents.value, currentSelection, 'strict', tracer, nesConfigs);
const res = tryRebase(cachedEdit.documentBeforeEdit.value, cachedEdit.editWindow, originalEdits, cachedEdit.detailedEdits, cachedEdit.userEditSince, currentDocumentContents.value, currentSelection, 'strict', logger, nesConfigs);
if (res === 'rebaseFailed') {
cachedEdit.rebaseFailed = true;
} else if (res === 'inconsistentEdits' || res === 'error') {
@@ -264,7 +263,7 @@ class DocumentEditCache {
}
public isRejectedNextEdit(currentDocumentContents: StringText, edit: StringReplacement, nesConfigs: INesConfigs) {
const tracer = this._tracer.sub('isRejectedNextEdit');
const logger = this._logger.createSubLogger('isRejectedNextEdit');
const resultEdit = edit.removeCommonSuffixAndPrefix(currentDocumentContents.value);
for (const rejectedEdit of this._trackedCachedEdits.filter(edit => edit.rejected)) {
if (!rejectedEdit.userEditSince) {
@@ -274,13 +273,13 @@ class DocumentEditCache {
if (!edits.length) {
continue; // cached 'no edits'
}
const rejectedEdits = tryRebase(rejectedEdit.documentBeforeEdit.value, undefined, edits, rejectedEdit.detailedEdits, rejectedEdit.userEditSince, currentDocumentContents.value, [], 'lenient', tracer, nesConfigs);
const rejectedEdits = tryRebase(rejectedEdit.documentBeforeEdit.value, undefined, edits, rejectedEdit.detailedEdits, rejectedEdit.userEditSince, currentDocumentContents.value, [], 'lenient', logger, nesConfigs);
if (typeof rejectedEdits === 'string') {
continue;
}
const rejected = rejectedEdits.some(rejected => rejected.rebasedEdit.removeCommonSuffixAndPrefix(currentDocumentContents.value).equals(resultEdit));
if (rejected) {
tracer.trace('Found rejected edit that matches current edit');
logger.trace('Found rejected edit that matches current edit');
return true;
}
}
extensions/copilot/src/extension/inlineEdits/node/nextEditProvider.ts
+57 -59
View File
@@ -14,12 +14,11 @@ import { IStatelessNextEditProvider, NoNextEditReason, PushEdit, ShowNextEditPre
import { autorunWithChanges } from '../../../platform/inlineEdits/common/utils/observable';
import { DocumentHistory, HistoryContext, IHistoryContextProvider } from '../../../platform/inlineEdits/common/workspaceEditTracker/historyContextProvider';
import { NesXtabHistoryTracker } from '../../../platform/inlineEdits/common/workspaceEditTracker/nesXtabHistoryTracker';
import { ILogService } from '../../../platform/log/common/logService';
import { ILogger, ILogService, LogTarget } from '../../../platform/log/common/logService';
import { ISnippyService } from '../../../platform/snippy/common/snippyService';
import { IExperimentationService } from '../../../platform/telemetry/common/nullExperimentationService';
import * as errors from '../../../util/common/errors';
import { Result } from '../../../util/common/result';
import { createTracer, ITracer } from '../../../util/common/tracing';
import { assert } from '../../../util/vs/base/common/assert';
import { DeferredPromise, timeout, TimeoutTimer } from '../../../util/vs/base/common/async';
import { CachedFunction } from '../../../util/vs/base/common/cache';
@@ -69,7 +68,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
public readonly ID = this._statelessNextEditProvider.ID;
private readonly _rejectionCollector = this._register(new RejectionCollector(this._workspace, s => this._logService.trace(s)));
private readonly _rejectionCollector = this._register(new RejectionCollector(this._workspace, this._logService));
private readonly _nextEditCache: NextEditCache;
private _pendingStatelessNextEditRequest: StatelessNextEditRequest<CachedOrRebasedEdit> | null = null;
@@ -89,7 +88,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
private _lastNextEditResult: NextEditResult | undefined;
private _shouldExpandEditWindow = false;
private _tracer: ITracer;
private _logger: ILogger;
constructor(
private readonly _workspace: ObservableWorkspace,
@@ -104,7 +103,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
) {
super();
this._tracer = createTracer(['NES', 'NextEditProvider'], (s) => this._logService.trace(s));
this._logger = this._logService.createSubLogger(['NES', 'NextEditProvider']);
this._nextEditCache = new NextEditCache(this._workspace, this._logService, this._configService, this._expService);
mapObservableArrayCached(this, this._workspace.openDocuments, (doc, store) => {
@@ -138,11 +137,10 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const sw = new StopWatch();
const tracer = this._tracer.sub(context.requestUuid.substring(4, 8), {
extraLog: (msg: string) => {
const logger = this._logger.createSubLogger(context.requestUuid.substring(4, 8))
.withExtraTarget(LogTarget.fromCallback((_level, msg) => {
logContext.trace(`[${Math.floor(sw.elapsed()).toString().padStart(4, ' ')}ms] ${msg}`);
}
});
}));
const shouldExpandEditWindow = this._shouldExpandEditWindow;
@@ -150,7 +148,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
let result: NextEditResult;
try {
result = await this._getNextEditCanThrow(docId, context, now, shouldExpandEditWindow, tracer, logContext, cancellationToken, telemetryBuilder);
result = await this._getNextEditCanThrow(docId, context, now, shouldExpandEditWindow, logger, logContext, cancellationToken, telemetryBuilder);
} catch (error) {
logContext.setError(error);
telemetryBuilder.setNextEditProviderError(errors.toString(error));
@@ -169,18 +167,18 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
context: NESInlineCompletionContext,
triggerTime: number,
shouldExpandEditWindow: boolean,
parentTracer: ITracer,
parentLogger: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
telemetryBuilder: LlmNESTelemetryBuilder
): Promise<NextEditResult> {
const tracer = parentTracer.sub('_getNextEdit');
tracer.trace(`invoked with trigger id = ${context.changeHint?.data}`);
const logger = parentLogger.createSubLogger('_getNextEdit');
logger.trace(`invoked with trigger id = ${context.changeHint?.data}`);
const doc = this._workspace.getDocument(docId);
if (!doc) {
tracer.throws(`Document "${docId.baseName}" not found`);
logger.trace(`Document "${docId.baseName}" not found`);
throw new BugIndicatingError(`Document "${docId.baseName}" not found`);
}
@@ -191,7 +189,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const cachedEdit = this._nextEditCache.lookupNextEdit(docId, documentAtInvocationTime, selections, nesConfigs);
if (cachedEdit?.rejected) {
tracer.trace('cached edit was previously rejected');
logger.trace('cached edit was previously rejected');
telemetryBuilder.setStatus('previouslyRejectedCache');
telemetryBuilder.setWasPreviouslyRejected();
const nextEditResult = new NextEditResult(logContext.requestId, cachedEdit.source, undefined);
@@ -208,7 +206,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
let isSubsequentCachedEdit = false;
if (cachedEdit) {
tracer.trace('using cached edit');
logger.trace('using cached edit');
const actualEdit = cachedEdit.rebasedEdit || cachedEdit.edit;
if (actualEdit) {
edit = { actualEdit, isFromCursorJump: cachedEdit.isFromCursorJump };
@@ -225,7 +223,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
logContext.recordingBookmark = req.log.recordingBookmark;
} else {
tracer.trace(`fetching next edit with shouldExpandEditWindow=${shouldExpandEditWindow}`);
logger.trace(`fetching next edit with shouldExpandEditWindow=${shouldExpandEditWindow}`);
const providerRequestStartDateTime = (this._configService.getExperimentBasedConfig(ConfigKey.TeamInternal.InlineEditsDebounceUseCoreRequestTime, this._expService)
? (context.requestIssuedDateTime ?? undefined)
: undefined);
@@ -233,15 +231,15 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
telemetryBuilder.setHeaderRequestId(req.headerRequestId);
const startVersion = doc.value.get();
tracer.trace('awaiting firstEdit promise');
const result = await this.fetchNextEdit(req, doc, nesConfigs, shouldExpandEditWindow, tracer, telemetryBuilder, cancellationToken);
tracer.trace('resolved firstEdit promise');
logger.trace('awaiting firstEdit promise');
const result = await this.fetchNextEdit(req, doc, nesConfigs, shouldExpandEditWindow, logger, telemetryBuilder, cancellationToken);
logger.trace('resolved firstEdit promise');
const latency = `First edit latency: ${Date.now() - this._lastTriggerTime} ms`;
logContext.addLog(latency);
tracer.trace(latency);
logger.trace(latency);
if (result.isError()) {
tracer.trace(`failed to fetch next edit ${result.err.toString()}`);
logger.trace(`failed to fetch next edit ${result.err.toString()}`);
telemetryBuilder.setStatus(`noEdit:${result.err.kind}`);
error = result.err;
} else {
@@ -251,16 +249,16 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const docDidChange = targetDocumentId === doc.id && startVersion.value !== currentDocument.value;
if (docDidChange) {
tracer.trace('document changed while fetching next edit');
logger.trace('document changed while fetching next edit');
telemetryBuilder.setStatus('docChanged');
logContext.setIsSkipped();
} else {
const suggestedNextEdit = result.val.rebasedEdit || result.val.edit;
if (!suggestedNextEdit) {
tracer.trace('empty edits');
logger.trace('empty edits');
telemetryBuilder.setStatus('emptyEdits');
} else {
tracer.trace('fetch succeeded');
logger.trace('fetch succeeded');
logContext.setResponseResults([suggestedNextEdit]); // TODO: other streamed edits?
edit = { actualEdit: suggestedNextEdit, isFromCursorJump: result.val.isFromCursorJump };
}
@@ -269,7 +267,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
}
if (error instanceof NoNextEditReason.FetchFailure || error instanceof NoNextEditReason.Unexpected) {
tracer.throws('has throwing error', error.error);
logger.trace(`has throwing error: ${error.error}`);
throw error.error;
} else if (error instanceof NoNextEditReason.NoSuggestions) {
if (error.nextCursorPosition === undefined) {
@@ -283,19 +281,19 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const emptyResult = new NextEditResult(logContext.requestId, req, undefined);
if (!edit) {
tracer.returns('had no edit');
logger.trace('had no edit');
// telemetry builder status must've been set earlier
return emptyResult;
}
if (cancellationToken.isCancellationRequested) {
tracer.returns('cancelled');
logger.trace('cancelled');
telemetryBuilder.setStatus(`noEdit:gotCancelled`);
return emptyResult;
}
if (this._rejectionCollector.isRejected(targetDocumentId, edit.actualEdit) || currentDocument && this._nextEditCache.isRejectedNextEdit(targetDocumentId, currentDocument, edit.actualEdit, nesConfigs)) {
tracer.returns('edit was previously rejected');
logger.trace('edit was previously rejected');
telemetryBuilder.setStatus('previouslyRejected');
telemetryBuilder.setWasPreviouslyRejected();
return emptyResult;
@@ -313,17 +311,17 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
telemetryBuilder.setHasNextEdit(true);
const delay = this.computeMinimumResponseDelay({ triggerTime, isRebasedCachedEdit, isSubsequentCachedEdit, enforceCacheDelay: context.enforceCacheDelay }, tracer);
const delay = this.computeMinimumResponseDelay({ triggerTime, isRebasedCachedEdit, isSubsequentCachedEdit, enforceCacheDelay: context.enforceCacheDelay }, logger);
if (delay > 0) {
await timeout(delay);
if (cancellationToken.isCancellationRequested) {
tracer.returns('cancelled');
logger.trace('cancelled');
telemetryBuilder.setStatus(`noEdit:gotCancelled`);
return emptyResult;
}
}
tracer.returns('returning next edit result');
logger.trace('returning next edit result');
return nextEditResult;
}
@@ -369,9 +367,9 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
};
}
private async fetchNextEdit(req: NextEditFetchRequest, doc: IObservableDocument, nesConfigs: INesConfigs, shouldExpandEditWindow: boolean, parentTracer: ITracer, telemetryBuilder: LlmNESTelemetryBuilder, cancellationToken: CancellationToken): Promise<Result<CachedOrRebasedEdit, NoNextEditReason>> {
private async fetchNextEdit(req: NextEditFetchRequest, doc: IObservableDocument, nesConfigs: INesConfigs, shouldExpandEditWindow: boolean, parentLogger: ILogger, telemetryBuilder: LlmNESTelemetryBuilder, cancellationToken: CancellationToken): Promise<Result<CachedOrRebasedEdit, NoNextEditReason>> {
const curDocId = doc.id;
const tracer = parentTracer.sub('fetchNextEdit');
const logger = parentLogger.createSubLogger('fetchNextEdit');
const historyContext = this._historyContextProvider.getHistoryContext(curDocId);
if (!historyContext) {
@@ -408,7 +406,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
}
if (cancellationToken.isCancellationRequested) {
tracer.trace('document changed after rebase failed');
logger.trace('document changed after rebase failed');
telemetryBuilder.setStatelessNextEditTelemetry(nextEditResult.telemetry);
return Result.error(new NoNextEditReason.GotCancelled('afterFailedRebase'));
}
@@ -418,17 +416,17 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const existingNextEditRequest2 = pendingRequestStillCurrent && !this._pendingStatelessNextEditRequest?.cancellationTokenSource.token.isCancellationRequested
&& this._pendingStatelessNextEditRequest || undefined;
if (existingNextEditRequest2) {
tracer.trace('reusing 2nd existing next edit request after rebase failed');
logger.trace('reusing 2nd existing next edit request after rebase failed');
const nextEditResult = await this._joinNextEditRequest(existingNextEditRequest2, telemetryBuilder, logContext, cancellationToken);
telemetryBuilder.setStatelessNextEditTelemetry(nextEditResult.telemetry);
return nextEditResult.nextEdit.isError() ? nextEditResult.nextEdit : existingNextEditRequest2.firstEdit.p;
}
tracer.trace('creating new next edit request after rebase failed');
logger.trace('creating new next edit request after rebase failed');
}
}
const res = await this._executeNewNextEditRequest(req, doc, historyContext, nesConfigs, shouldExpandEditWindow, tracer, telemetryBuilder, cancellationToken);
const res = await this._executeNewNextEditRequest(req, doc, historyContext, nesConfigs, shouldExpandEditWindow, logger, telemetryBuilder, cancellationToken);
const nextEditRequest = res.nextEditRequest;
const nextEditResult = res.nextEditResult;
telemetryBuilder.setStatelessNextEditTelemetry(nextEditResult.telemetry);
@@ -458,7 +456,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
historyContext: HistoryContext,
nesConfigs: INesConfigs,
shouldExpandEditWindow: boolean,
parentTracer: ITracer,
parentLogger: ILogger,
telemetryBuilder: LlmNESTelemetryBuilder,
cancellationToken: CancellationToken
): Promise<{
@@ -466,7 +464,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
nextEditResult: StatelessNextEditResult;
}> {
const curDocId = doc.id;
const tracer = parentTracer.sub('_executeNewNextEditRequest');
const logger = parentLogger.createSubLogger('_executeNewNextEditRequest');
const recording = this._debugRecorder?.getRecentLog();
@@ -538,7 +536,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
data.value.changes.forEach(edit => {
if (nextEditRequest.intermediateUserEdit && !edit.isEmpty()) {
nextEditRequest.intermediateUserEdit = nextEditRequest.intermediateUserEdit.compose(edit);
if (!checkEditConsistency(nextEditRequest.documentBeforeEdits.value, nextEditRequest.intermediateUserEdit, data.value.value.value, tracer)) {
if (!checkEditConsistency(nextEditRequest.documentBeforeEdits.value, nextEditRequest.intermediateUserEdit, data.value.value.value, logger)) {
nextEditRequest.intermediateUserEdit = undefined;
}
}
@@ -560,21 +558,21 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
};
});
const pushEdit: PushEdit = (result) => {
const myTracer = tracer.sub('pushEdit');
const myLogger = logger.createSubLogger('pushEdit');
++ithEdit;
myTracer.trace(`processing edit #${ithEdit} (starts at 0)`);
myLogger.trace(`processing edit #${ithEdit} (starts at 0)`);
if (result.isError()) { // either error or stream of edits ended
// if there was a request made, and it ended without any edits, reset shouldExpandEditWindow
if (ithEdit === 0 && result.err instanceof NoNextEditReason.NoSuggestions) {
myTracer.trace('resetting shouldExpandEditWindow to false due to NoSuggestions');
myLogger.trace('resetting shouldExpandEditWindow to false due to NoSuggestions');
this._shouldExpandEditWindow = false;
}
if (statePerDoc.get(curDocId).nextEdits.length) {
myTracer.returns(`${statePerDoc.get(curDocId).nextEdits.length} edits returned`);
myLogger.trace(`${statePerDoc.get(curDocId).nextEdits.length} edits returned`);
} else {
myTracer.returns(`no edit, reason: ${result.err.kind}`);
myLogger.trace(`no edit, reason: ${result.err.kind}`);
if (result.err instanceof NoNextEditReason.NoSuggestions) {
const { documentBeforeEdits, window } = result.err;
let reducedWindow = window;
@@ -606,7 +604,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
}
// reset shouldExpandEditWindow to false when we get any edit
myTracer.trace('resetting shouldExpandEditWindow to false due to receiving an edit');
myLogger.trace('resetting shouldExpandEditWindow to false due to receiving an edit');
this._shouldExpandEditWindow = false;
const targetDocState = statePerDoc.get(result.val.targetDocument ?? curDocId);
@@ -617,7 +615,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
const rebasedEdit = edit.tryRebase(targetDocState.editsSoFar);
if (rebasedEdit === undefined) {
myTracer.trace(`edit ${ithEdit} is undefined after rebasing`);
myLogger.trace(`edit ${ithEdit} is undefined after rebasing`);
if (!firstEdit.isSettled) {
firstEdit.complete(Result.error(new NoNextEditReason.Uncategorized(new Error('Rebased edit is undefined'))));
}
@@ -628,9 +626,9 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
let cachedEdit: CachedOrRebasedEdit | undefined;
if (rebasedEdit.replacements.length === 0) {
myTracer.trace(`WARNING: ${ithEdit} has no edits`);
myLogger.trace(`WARNING: ${ithEdit} has no edits`);
} else if (rebasedEdit.replacements.length > 1) {
myTracer.trace(`WARNING: ${ithEdit} has ${rebasedEdit.replacements.length} edits, but expected only 1`);
myLogger.trace(`WARNING: ${ithEdit} has ${rebasedEdit.replacements.length} edits, but expected only 1`);
} else {
// populate the cache
const nextEdit = rebasedEdit.replacements[0];
@@ -646,11 +644,11 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
req,
{ isFromCursorJump: result.val.isFromCursorJump }
);
myTracer.trace(`populated cache for ${ithEdit}`);
myLogger.trace(`populated cache for ${ithEdit}`);
}
if (!firstEdit.isSettled) {
myTracer.trace('resolving firstEdit promise');
myLogger.trace('resolving firstEdit promise');
logContext.setResult(new RootedLineEdit(targetDocState.docContents, lineEdit)); // this's correct without rebasing because this's the first edit
firstEdit.complete(cachedEdit ? Result.ok(cachedEdit) : Result.error(new NoNextEditReason.Unexpected(new Error('No cached edit'))));
}
@@ -662,7 +660,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
};
const pushEdit = createPushEdit();
try {
nextEditResult = await this._statelessNextEditProvider.provideNextEdit(nextEditRequest, pushEdit, tracer, logContext, nextEditRequest.cancellationTokenSource.token);
nextEditResult = await this._statelessNextEditProvider.provideNextEdit(nextEditRequest, pushEdit, logger, logContext, nextEditRequest.cancellationTokenSource.token);
nextEditRequest.setResult(nextEditResult);
} catch (err) {
nextEditRequest.setResultError(err);
@@ -725,10 +723,10 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
return disposables;
}
private computeMinimumResponseDelay({ triggerTime, isRebasedCachedEdit, isSubsequentCachedEdit, enforceCacheDelay }: { triggerTime: number; isRebasedCachedEdit: boolean; isSubsequentCachedEdit: boolean; enforceCacheDelay: boolean }, tracer: ITracer): number {
private computeMinimumResponseDelay({ triggerTime, isRebasedCachedEdit, isSubsequentCachedEdit, enforceCacheDelay }: { triggerTime: number; isRebasedCachedEdit: boolean; isSubsequentCachedEdit: boolean; enforceCacheDelay: boolean }, logger: ILogger): number {
if (!enforceCacheDelay) {
tracer.trace('[minimumDelay] no minimum delay enforced due to enforceCacheDelay being false');
logger.trace('[minimumDelay] no minimum delay enforced due to enforceCacheDelay being false');
return 0;
}
@@ -748,7 +746,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
// if the provider call took longer than the minimum delay, we don't need to delay further
const delay = Math.max(0, minimumResponseDelay - nextEditProviderCallLatency);
tracer.trace(`[minimumDelay] expected delay: ${minimumResponseDelay}ms, effective delay: ${delay}. isRebasedCachedEdit: ${isRebasedCachedEdit} (rebasedCacheDelay: ${rebasedCacheDelay}), isSubsequentCachedEdit: ${isSubsequentCachedEdit} (subsequentCacheDelay: ${subsequentCacheDelay})`);
logger.trace(`[minimumDelay] expected delay: ${minimumResponseDelay}ms, effective delay: ${delay}. isRebasedCachedEdit: ${isRebasedCachedEdit} (rebasedCacheDelay: ${rebasedCacheDelay}), isSubsequentCachedEdit: ${isSubsequentCachedEdit} (subsequentCacheDelay: ${subsequentCacheDelay})`);
return delay;
}
@@ -761,12 +759,12 @@ export class NextEditProvider extends Disposable implements INextEditProvider<Ne
this.runSnippy(docId, suggestion);
this._statelessNextEditProvider.handleAcceptance?.();
const tracer = this._tracer.subNoEntry(suggestion.source.opportunityId.substring(4, 8)).subNoEntry('handleAcceptance');
const logger = this._logger.createSubLogger(suggestion.source.opportunityId.substring(4, 8)).createSubLogger('handleAcceptance');
if (suggestion === this._lastNextEditResult) {
tracer.trace('setting shouldExpandEditWindow to true due to acceptance of last suggestion');
logger.trace('setting shouldExpandEditWindow to true due to acceptance of last suggestion');
this._shouldExpandEditWindow = true;
} else {
tracer.trace('NOT setting shouldExpandEditWindow to true because suggestion is not the last suggestion');
logger.trace('NOT setting shouldExpandEditWindow to true because suggestion is not the last suggestion');
}
}
extensions/copilot/src/extension/inlineEdits/node/serverPoweredInlineEditProvider.ts
+2 -2
View File
@@ -9,7 +9,7 @@ import { InlineEditRequestLogContext } from '../../../platform/inlineEdits/commo
import { ISerializedNextEditRequest, IStatelessNextEditProvider, NoNextEditReason, PushEdit, StatelessNextEditRequest, StatelessNextEditResult, StatelessNextEditTelemetryBuilder } from '../../../platform/inlineEdits/common/statelessNextEditProvider';
import { fromUnknown } from '../../../util/common/errors';
import { Result } from '../../../util/common/result';
import { ITracer } from '../../../util/common/tracing';
import { ILogger } from '../../../platform/log/common/logService';
import { assert } from '../../../util/vs/base/common/assert';
import { CancellationToken } from '../../../util/vs/base/common/cancellation';
import { LineEdit, LineReplacement, SerializedLineReplacement } from '../../../util/vs/editor/common/core/edits/lineEdit';
@@ -48,7 +48,7 @@ export class ServerPoweredInlineEditProvider implements IStatelessNextEditProvid
) {
}
async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, _tracer: ITracer, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult> {
async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, _logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult> {
const telemetryBuilder = new StatelessNextEditTelemetryBuilder(request);
extensions/copilot/src/extension/inlineEdits/test/common/editRebase.spec.ts
+10 -10
View File
@@ -4,7 +4,7 @@
*--------------------------------------------------------------------------------------------*/
import { expect, suite, test } from 'vitest';
import { decomposeStringEdit } from '../../../../platform/inlineEdits/common/dataTypes/editUtils';
import { createTracer } from '../../../../util/common/tracing';
import { TestLogService } from '../../../../platform/testing/common/testLogService';
import { StringEdit, StringReplacement } from '../../../../util/vs/editor/common/core/edits/stringEdit';
import { OffsetRange } from '../../../../util/vs/editor/common/core/ranges/offsetRange';
import { maxAgreementOffset, maxImperfectAgreementLength, tryRebase, tryRebaseStringEdits } from '../../common/editRebase';
@@ -49,16 +49,16 @@ class Point3D {
}
`);
const tracer = createTracer('nextEditCache.spec', console.log);
const logger = new TestLogService();
{
const res = tryRebase(originalDocument, undefined, decomposeStringEdit(suggestedEdit).edits, [], userEdit, currentDocument, [], 'strict', tracer);
const res = tryRebase(originalDocument, undefined, decomposeStringEdit(suggestedEdit).edits, [], userEdit, currentDocument, [], 'strict', logger);
expect(res).toBeTypeOf('object');
const result = res as Exclude<typeof res, string | undefined>;
expect(result[0].rebasedEditIndex).toBe(1);
expect(result[0].rebasedEdit.toString()).toMatchInlineSnapshot(`"[68, 76) -> "\\n\\t\\tthis.z = z;""`);
}
{
const res = tryRebase(originalDocument, undefined, decomposeStringEdit(suggestedEdit).edits, [], userEdit, currentDocument, [], 'lenient', tracer);
const res = tryRebase(originalDocument, undefined, decomposeStringEdit(suggestedEdit).edits, [], userEdit, currentDocument, [], 'lenient', logger);
expect(res).toBeTypeOf('object');
const result = res as Exclude<typeof res, string | undefined>;
expect(result[0].rebasedEditIndex).toBe(1);
@@ -135,9 +135,9 @@ function main() {
}
`);
const tracer = createTracer('nextEditCache.spec', console.log);
expect(tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'strict', tracer)).toStrictEqual('rebaseFailed');
expect(tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'lenient', tracer)).toStrictEqual('rebaseFailed');
const logger = new TestLogService();
expect(tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'strict', logger)).toStrictEqual('rebaseFailed');
expect(tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'lenient', logger)).toStrictEqual('rebaseFailed');
});
test('tryRebase correct offsets', async () => {
@@ -214,9 +214,9 @@ int main()
}
`);
const tracer = createTracer('nextEditCache.spec', console.log);
const logger = new TestLogService();
{
const res = tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'strict', tracer);
const res = tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'strict', logger);
expect(res).toBeTypeOf('object');
const result = res as Exclude<typeof res, string | undefined>;
expect(result[0].rebasedEditIndex).toBe(0);
@@ -224,7 +224,7 @@ int main()
expect(result[0].rebasedEdit.removeCommonSuffixAndPrefix(currentDocument).toString()).toMatchInlineSnapshot(`"[87, 164) -> "esult42.empty())\\n return result42.size();\\n result42.clear();\\n return result42""`);
}
{
const res = tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'lenient', tracer);
const res = tryRebase(originalDocument, undefined, suggestedEdit.replacements, [], userEdit, currentDocument, [], 'lenient', logger);
expect(res).toBeTypeOf('object');
const result = res as Exclude<typeof res, string | undefined>;
expect(result[0].rebasedEditIndex).toBe(0);
extensions/copilot/src/extension/inlineEdits/test/node/nextEditProviderCaching.spec.ts
+2 -3
View File
@@ -15,14 +15,13 @@ import { MutableObservableWorkspace } from '../../../../platform/inlineEdits/com
import { IStatelessNextEditProvider, NoNextEditReason, PushEdit, StatelessNextEditRequest, StatelessNextEditResult, StatelessNextEditTelemetryBuilder } from '../../../../platform/inlineEdits/common/statelessNextEditProvider';
import { NesHistoryContextProvider } from '../../../../platform/inlineEdits/common/workspaceEditTracker/nesHistoryContextProvider';
import { NesXtabHistoryTracker } from '../../../../platform/inlineEdits/common/workspaceEditTracker/nesXtabHistoryTracker';
import { ILogService, LogServiceImpl } from '../../../../platform/log/common/logService';
import { ILogger, ILogService, LogServiceImpl } from '../../../../platform/log/common/logService';
import { ISnippyService, NullSnippyService } from '../../../../platform/snippy/common/snippyService';
import { IExperimentationService, NullExperimentationService } from '../../../../platform/telemetry/common/nullExperimentationService';
import { mockNotebookService } from '../../../../platform/test/common/testNotebookService';
import { TestWorkspaceService } from '../../../../platform/test/node/testWorkspaceService';
import { IWorkspaceService } from '../../../../platform/workspace/common/workspaceService';
import { Result } from '../../../../util/common/result';
import { ITracer } from '../../../../util/common/tracing';
import { CancellationToken } from '../../../../util/vs/base/common/cancellation';
import { DisposableStore } from '../../../../util/vs/base/common/lifecycle';
import { URI } from '../../../../util/vs/base/common/uri';
@@ -60,7 +59,7 @@ describe('NextEditProvider Caching', () => {
const obsGit = new ObservableGit(gitExtensionService);
const statelessNextEditProvider: IStatelessNextEditProvider = {
ID: 'TestNextEditProvider',
provideNextEdit: async (request: StatelessNextEditRequest, pushEdit: PushEdit, tracer: ITracer, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken) => {
provideNextEdit: async (request: StatelessNextEditRequest, pushEdit: PushEdit, logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken) => {
const telemetryBuilder = new StatelessNextEditTelemetryBuilder(request);
const lineEdit = LineEdit.createFromUnsorted(
[
extensions/copilot/src/extension/inlineEdits/test/node/rejectionCollector.spec.ts
+3 -2
View File
@@ -7,6 +7,7 @@ import { outdent } from 'outdent';
import { describe, expect, test } from 'vitest';
import { DocumentId } from '../../../../platform/inlineEdits/common/dataTypes/documentId';
import { IObservableDocument, MutableObservableWorkspace } from '../../../../platform/inlineEdits/common/observableWorkspace';
import { TestLogService } from '../../../../platform/testing/common/testLogService';
import { runOnChange } from '../../../../util/vs/base/common/observableInternal';
import { URI } from '../../../../util/vs/base/common/uri';
import { StringEdit, StringReplacement } from '../../../../util/vs/editor/common/core/edits/stringEdit';
@@ -25,7 +26,7 @@ describe('RejectionCollector[visualizable]', () => {
ctx => {
const rejs: (boolean | string)[] = [];
const rejectionCollector = ctx.store.add(new RejectionCollector(ctx.workspace, console.log));
const rejectionCollector = ctx.store.add(new RejectionCollector(ctx.workspace, new TestLogService()));
ctx.workspace.lastActiveDocument.recomputeInitiallyAndOnChange(ctx.store);
@@ -134,7 +135,7 @@ class Point {
`.trim()
});
const rejectionCollector = new RejectionCollector(observableWorkspace, console.log);
const rejectionCollector = new RejectionCollector(observableWorkspace, new TestLogService());
try {
const edit1 = StringReplacement.replace(OffsetRange.fromTo(96, 107), 'fo');
expect(rejectionCollector.isRejected(doc.id, edit1)).toBe(false);
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/anyDiagnosticsCompletionProvider.ts
+4 -4
View File
@@ -5,7 +5,7 @@
import { CodeActionData } from '../../../../../platform/inlineEdits/common/dataTypes/codeActionData';
import { LanguageId } from '../../../../../platform/inlineEdits/common/dataTypes/languageId';
import { ITracer } from '../../../../../util/common/tracing';
import { ILogger } from '../../../../../platform/log/common/logService';
import { CancellationToken } from '../../../../../util/vs/base/common/cancellation';
import { TextReplacement } from '../../../../../util/vs/editor/common/core/edits/textEdit';
import { Position } from '../../../../../util/vs/editor/common/core/position';
@@ -46,7 +46,7 @@ export class AnyDiagnosticCompletionProvider implements IDiagnosticCompletionPro
public readonly providerName = 'any';
constructor(private readonly _tracer: ITracer) { }
constructor(private readonly _logger: ILogger) { }
public providesCompletionsForDiagnostic(workspaceDocument: IVSCodeObservableDocument, diagnostic: Diagnostic, language: LanguageId, pos: Position): boolean {
return isDiagnosticWithinDistance(workspaceDocument, diagnostic, pos, 5);
@@ -57,7 +57,7 @@ export class AnyDiagnosticCompletionProvider implements IDiagnosticCompletionPro
for (const diagnostic of sortedDiagnostics) {
const availableCodeActions = await workspaceDocument.getCodeActions(diagnostic.range, 3, token);
if (availableCodeActions === undefined) {
log(`Fetching code actions likely timed out for \`${diagnostic.message}\``, logContext, this._tracer);
log(`Fetching code actions likely timed out for \`${diagnostic.message}\``, logContext, this._logger);
continue;
}
@@ -66,7 +66,7 @@ export class AnyDiagnosticCompletionProvider implements IDiagnosticCompletionPro
continue;
}
logList(`Found the following code action which fix \`${diagnostic.message}\``, codeActionsFixingCodeAction, logContext, this._tracer);
logList(`Found the following code action which fix \`${diagnostic.message}\``, codeActionsFixingCodeAction, logContext, this._logger);
const filteredCodeActionsWithEdit = filterCodeActions(codeActionsFixingCodeAction);
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/asyncDiagnosticsCompletionProvider.ts
+6 -6
View File
@@ -5,7 +5,7 @@
import { CodeActionData } from '../../../../../platform/inlineEdits/common/dataTypes/codeActionData';
import { LanguageId } from '../../../../../platform/inlineEdits/common/dataTypes/languageId';
import { ITracer } from '../../../../../util/common/tracing';
import { ILogger } from '../../../../../platform/log/common/logService';
import { CancellationToken } from '../../../../../util/vs/base/common/cancellation';
import { TextReplacement } from '../../../../../util/vs/editor/common/core/edits/textEdit';
import { Position } from '../../../../../util/vs/editor/common/core/position';
@@ -31,7 +31,7 @@ export class AsyncDiagnosticCompletionProvider implements IDiagnosticCompletionP
public readonly providerName = 'async';
constructor(private readonly _tracer: ITracer) { }
constructor(private readonly _logger: ILogger) { }
public providesCompletionsForDiagnostic(workspaceDocument: IVSCodeObservableDocument, diagnostic: Diagnostic, language: LanguageId, pos: Position): boolean {
if (!AsyncDiagnosticCompletionProvider.SupportedLanguages.has(language)) {
@@ -54,20 +54,20 @@ export class AsyncDiagnosticCompletionProvider implements IDiagnosticCompletionP
// fetch code actions for missing async
const availableCodeActions = await workspaceDocument.getCodeActions(missingAsyncDiagnostic.range, 3, token);
if (availableCodeActions === undefined) {
log(`Fetching code actions likely timed out for \`${missingAsyncDiagnostic.message}\``, logContext, this._tracer);
log(`Fetching code actions likely timed out for \`${missingAsyncDiagnostic.message}\``, logContext, this._logger);
return null;
}
const asyncCodeActions = getAsyncCodeActions(availableCodeActions, workspaceDocument);
if (asyncCodeActions.length === 0) {
log('No async code actions found in the available code actions', logContext, this._tracer);
log('No async code actions found in the available code actions', logContext, this._logger);
return null;
}
const asyncCodeActionToShow = asyncCodeActions[0];
const item = new AsyncDiagnosticCompletionItem(missingAsyncDiagnostic, asyncCodeActionToShow.edit, workspaceDocument);
log(`Created async completion item for: \`${missingAsyncDiagnostic.toString()}\``, logContext, this._tracer);
log(`Created async completion item for: \`${missingAsyncDiagnostic.toString()}\``, logContext, this._logger);
return item;
}
@@ -103,4 +103,4 @@ function getAsyncCodeActions(codeActions: CodeActionData[], workspaceDocument: I
}
return asyncCodeActions;
}
}
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/diagnosticsCompletions.ts
+6 -6
View File
@@ -9,9 +9,9 @@ import { DocumentId } from '../../../../../platform/inlineEdits/common/dataTypes
import { LanguageId } from '../../../../../platform/inlineEdits/common/dataTypes/languageId';
import { RootedLineEdit } from '../../../../../platform/inlineEdits/common/dataTypes/rootedLineEdit';
import { IObservableDocument } from '../../../../../platform/inlineEdits/common/observableWorkspace';
import { ILogger } from '../../../../../platform/log/common/logService';
import { min } from '../../../../../util/common/arrays';
import * as errors from '../../../../../util/common/errors';
import { ITracer } from '../../../../../util/common/tracing';
import { CancellationToken } from '../../../../../util/vs/base/common/cancellation';
import { LineEdit } from '../../../../../util/vs/editor/common/core/edits/lineEdit';
import { StringReplacement } from '../../../../../util/vs/editor/common/core/edits/stringEdit';
@@ -214,20 +214,20 @@ export class Diagnostic {
}
}
export function log(message: string, logContext?: DiagnosticInlineEditRequestLogContext, tracer?: ITracer) {
export function log(message: string, logContext?: DiagnosticInlineEditRequestLogContext, logger?: ILogger) {
if (logContext) {
const lines = message.split('\n');
lines.forEach(line => logContext.addLog(line));
}
if (tracer) {
tracer.trace(message);
if (logger) {
logger.trace(message);
}
}
export function logList(title: string, list: Array<string | { toString(): string }>, logContext?: DiagnosticInlineEditRequestLogContext, tracer?: ITracer) {
export function logList(title: string, list: Array<string | { toString(): string }>, logContext?: DiagnosticInlineEditRequestLogContext, logger?: ILogger) {
const content = `${title}${list.map(item => `\n- ${typeof item === 'string' ? item : item.toString()}`).join('')}`;
log(content, logContext, tracer);
log(content, logContext, logger);
}
// TODO: there must be a utility for this somewhere? Otherwise make them available
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/importDiagnosticsCompletionProvider.ts
+8 -8
View File
@@ -10,8 +10,8 @@ import { CodeActionData } from '../../../../../platform/inlineEdits/common/dataT
import { DocumentId } from '../../../../../platform/inlineEdits/common/dataTypes/documentId';
import { LanguageId } from '../../../../../platform/inlineEdits/common/dataTypes/languageId';
import { IObservableDocument } from '../../../../../platform/inlineEdits/common/observableWorkspace';
import { ILogger } from '../../../../../platform/log/common/logService';
import { IWorkspaceService } from '../../../../../platform/workspace/common/workspaceService';
import { ITracer } from '../../../../../util/common/tracing';
import { CancellationToken } from '../../../../../util/vs/base/common/cancellation';
import { isAbsolute } from '../../../../../util/vs/base/common/path';
import { dirname, resolvePath } from '../../../../../util/vs/base/common/resources';
@@ -190,7 +190,7 @@ export class ImportDiagnosticCompletionProvider implements IDiagnosticCompletion
private readonly _importHandlers: Map<string, ILanguageImportHandler>;
constructor(
private readonly _tracer: ITracer,
private readonly _logger: ILogger,
private readonly _workspaceService: IWorkspaceService,
private readonly _fileService: IFileSystemService,
) {
@@ -238,21 +238,21 @@ export class ImportDiagnosticCompletionProvider implements IDiagnosticCompletion
const availableCodeActions = await workspaceDocument.getCodeActions(importDiagnosticToFix.range, 3, token);
const resolveCodeActionDuration = Date.now() - startTime;
if (availableCodeActions === undefined) {
log(`Fetching code actions likely timed out for \`${importDiagnosticToFix.message}\``, logContext, this._tracer);
log(`Fetching code actions likely timed out for \`${importDiagnosticToFix.message}\``, logContext, this._logger);
return null;
}
log(`Resolving code actions for \`${importDiagnosticToFix.message}\` took \`${resolveCodeActionDuration}ms\``, logContext, this._tracer);
log(`Resolving code actions for \`${importDiagnosticToFix.message}\` took \`${resolveCodeActionDuration}ms\``, logContext, this._logger);
const availableImportCodeActions = this._getImportCodeActions(availableCodeActions, workspaceDocument, importDiagnosticToFix, this._workspaceInfo);
if (availableImportCodeActions.length === 0) {
log('No import code actions found in the available code actions', logContext, this._tracer);
log('No import code actions found in the available code actions', logContext, this._logger);
return null;
}
const sortedImportCodeActions = availableImportCodeActions.sort((a, b) => a.compareTo(b));
logList(`Sorted import code actions for \`${importDiagnosticToFix.message}\``, sortedImportCodeActions, logContext, this._tracer);
logList(`Sorted import code actions for \`${importDiagnosticToFix.message}\``, sortedImportCodeActions, logContext, this._logger);
for (const codeAction of sortedImportCodeActions) {
const importCodeActionLabel = availableImportCodeActions.length === 1 && codeAction.importSource !== ImportSource.external ? codeAction.labelShort : codeAction.labelDeduped;
@@ -260,12 +260,12 @@ export class ImportDiagnosticCompletionProvider implements IDiagnosticCompletion
const item = new ImportDiagnosticCompletionItem(codeAction, importDiagnosticToFix, importCodeActionLabel, workspaceDocument, availableImportCodeActions.length - 1);
if (this._hasImportBeenRejected(item)) {
log(`Rejected import completion item ${codeAction.labelDeduped} for ${importDiagnosticToFix.toString()}`, logContext, this._tracer);
log(`Rejected import completion item ${codeAction.labelDeduped} for ${importDiagnosticToFix.toString()}`, logContext, this._logger);
logContext.markToBeLogged();
continue;
}
log(`Created import completion item ${codeAction.labelDeduped} for ${importDiagnosticToFix.toString()}`, logContext, this._tracer);
log(`Created import completion item ${codeAction.labelDeduped} for ${importDiagnosticToFix.toString()}`, logContext, this._logger);
return item;
}
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsCompletionProcessor.ts
+21 -22
View File
@@ -13,11 +13,10 @@ import { ObservableGit } from '../../../../platform/inlineEdits/common/observabl
import { IObservableDocument } from '../../../../platform/inlineEdits/common/observableWorkspace';
import { autorunWithChanges } from '../../../../platform/inlineEdits/common/utils/observable';
import { WorkspaceDocumentEditHistory } from '../../../../platform/inlineEdits/common/workspaceEditTracker/workspaceDocumentEditTracker';
import { ILogService } from '../../../../platform/log/common/logService';
import { ILogger, ILogService } from '../../../../platform/log/common/logService';
import { ITabsAndEditorsService } from '../../../../platform/tabs/common/tabsAndEditorsService';
import { IWorkspaceService } from '../../../../platform/workspace/common/workspaceService';
import { isNotebookCell } from '../../../../util/common/notebooks';
import { createTracer, ITracer } from '../../../../util/common/tracing';
import { equals } from '../../../../util/vs/base/common/arrays';
import { findFirstMonotonous } from '../../../../util/vs/base/common/arraysFind';
import { ThrottledDelayer } from '../../../../util/vs/base/common/async';
@@ -165,7 +164,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
private readonly _workspaceDocumentEditHistory: WorkspaceDocumentEditHistory;
private readonly _currentDiagnostics = new DiagnosticsCollection();
private readonly _tracer: ITracer;
private readonly _logger: ILogger;
constructor(
private readonly _workspace: VSCodeWorkspace,
@@ -180,12 +179,12 @@ export class DiagnosticsCompletionProcessor extends Disposable {
this._workspaceDocumentEditHistory = this._register(new WorkspaceDocumentEditHistory(this._workspace, git, 100));
this._tracer = createTracer(['NES', 'DiagnosticsInlineCompletionProvider'], (s) => logService.trace(s));
this._logger = logService.createSubLogger(['NES', 'DiagnosticsInlineCompletionProvider']);
const diagnosticsExplorationEnabled = configurationService.getConfigObservable(ConfigKey.TeamInternal.InlineEditsDiagnosticsExplorationEnabled);
const importProvider = new ImportDiagnosticCompletionProvider(this._tracer.sub('Import'), workspaceService, fileSystemService);
const asyncProvider = new AsyncDiagnosticCompletionProvider(this._tracer.sub('Async'));
const importProvider = new ImportDiagnosticCompletionProvider(this._logger.createSubLogger('Import'), workspaceService, fileSystemService);
const asyncProvider = new AsyncDiagnosticCompletionProvider(this._logger.createSubLogger('Async'));
this._diagnosticsCompletionProviders = derived(reader => {
const providers: IDiagnosticCompletionProvider[] = [
@@ -194,13 +193,13 @@ export class DiagnosticsCompletionProcessor extends Disposable {
];
if (diagnosticsExplorationEnabled.read(reader)) {
providers.push(new AnyDiagnosticCompletionProvider(this._tracer.sub('All')));
providers.push(new AnyDiagnosticCompletionProvider(this._logger.createSubLogger('All')));
}
return providers;
}).recomputeInitiallyAndOnChange(this._store);
this._rejectionCollector = this._register(new RejectionCollector(this._workspace, s => this._tracer.trace(s)));
this._rejectionCollector = this._register(new RejectionCollector(this._workspace, logService));
const isValidEditor = (editor: vscode.TextEditor | undefined): editor is vscode.TextEditor => {
return !!editor && (isNotebookCell(editor.document.uri) || isEditorFromEditorGrid(editor));
@@ -220,7 +219,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
// update state because diagnostics changed
reader.store.add(runOnChange(activeDocument.diagnostics, (diagnostics) => {
this._tracer.trace(`Diagnostics changed received in processor: ${diagnostics.map(d => '\n- ' + d.message).join('')}`);
this._logger.trace(`Diagnostics changed received in processor: ${diagnostics.map(d => '\n- ' + d.message).join('')}`);
this._updateState();
}));
}));
@@ -283,7 +282,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
return;
}
this._tracer.trace('Scheduled update for diagnostics inline completion');
this._logger.trace('Scheduled update for diagnostics inline completion');
await this._worker.schedule(async (token: CancellationToken) => this._runCompletionHandler(workspaceDocument, diagnosticsSorted, cursor, log, token));
}
@@ -298,7 +297,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
const diagnosticsAfter = filterFn(diagnostics);
const diagnosticsDiff = diagnostics.filter(diagnostic => !diagnosticsAfter.includes(diagnostic));
if (diagnosticsDiff.length > 0) {
logList(message, diagnosticsDiff, logContext, this._tracer);
logList(message, diagnosticsDiff, logContext, this._logger);
}
return diagnosticsAfter;
};
@@ -319,13 +318,13 @@ export class DiagnosticsCompletionProcessor extends Disposable {
let completionItem = null;
try {
this._tracer.trace('Running diagnostics inline completion handler');
this._logger.trace('Running diagnostics inline completion handler');
completionItem = await this._getCompletionFromDiagnostics(workspaceDocument, diagnosticsSorted, cursor, log, token, telemetryBuilder);
} catch (error) {
log.setError(error);
}
this._tracer.trace('Diagnostic Providers returned completion item: ' + (completionItem ? completionItem.toString() : 'null'));
this._logger.trace('Diagnostic Providers returned completion item: ' + (completionItem ? completionItem.toString() : 'null'));
if (completionItem instanceof ImportDiagnosticCompletionItem) {
telemetryBuilder.setImportTelemetry(completionItem);
@@ -359,14 +358,14 @@ export class DiagnosticsCompletionProcessor extends Disposable {
return { item: undefined, telemetry: telemetryBuilder.addDroppedReason('wrong-document').build(), logContext, workInProgress };
}
log('following known diagnostics:\n' + this._currentDiagnostics.toString(), undefined, this._tracer);
log('following known diagnostics:\n' + this._currentDiagnostics.toString(), undefined, this._logger);
return { item: completionItem, telemetry: telemetryBuilder.build(), logContext, workInProgress };
}
private async _getCompletionFromDiagnostics(workspaceDocument: IVSCodeObservableDocument, diagnosticsSorted: Diagnostic[], pos: Position, logContext: DiagnosticInlineEditRequestLogContext, token: CancellationToken, tb: DiagnosticsCompletionHandlerTelemetry): Promise<DiagnosticCompletionItem | null> {
if (diagnosticsSorted.length === 0) {
log(`No diagnostics available for document ${workspaceDocument.id.toString()}`, logContext, this._tracer);
log(`No diagnostics available for document ${workspaceDocument.id.toString()}`, logContext, this._logger);
return null;
}
@@ -387,7 +386,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
return result;
}));
this._tracer.trace(`Provider durations: ${providerTimings.map(timing => `\n- ${timing.provider}: ${timing.duration}ms`).join('')}`);
this._logger.trace(`Provider durations: ${providerTimings.map(timing => `\n- ${timing.provider}: ${timing.duration}ms`).join('')}`);
return providerResults.filter(item => !!item) as DiagnosticCompletionItem[];
}
@@ -422,35 +421,35 @@ export class DiagnosticsCompletionProcessor extends Disposable {
private _isCompletionItemValid(item: DiagnosticCompletionItem, workspaceDocument: IObservableDocument, logContext: DiagnosticInlineEditRequestLogContext, tb: DiagnosticsCompletionHandlerTelemetry): boolean {
if (!item.diagnostic.isValid()) {
log('Diagnostic completion item is no longer valid', logContext, this._tracer);
log('Diagnostic completion item is no longer valid', logContext, this._logger);
tb.addDroppedReason('no-longer-valid', item);
logContext.markToBeLogged();
return false;
}
if (this._isDiagnosticCompletionRejected(item)) {
log('Diagnostic completion item has been rejected before', logContext, this._tracer);
log('Diagnostic completion item has been rejected before', logContext, this._logger);
tb.addDroppedReason('recently-rejected', item);
logContext.markToBeLogged();
return false;
}
if (this._isUndoRecentEdit(item)) {
log('Diagnostic completion item is an undo operation', logContext, this._tracer);
log('Diagnostic completion item is an undo operation', logContext, this._logger);
tb.addDroppedReason('undo-operation', item);
logContext.markToBeLogged();
return false;
}
if (this._hasDiagnosticRecentlyBeenAccepted(item.diagnostic)) {
log('Completion item fixing the diagnostic has been accepted recently', logContext, this._tracer);
log('Completion item fixing the diagnostic has been accepted recently', logContext, this._logger);
tb.addDroppedReason('recently-accepted', item);
logContext.markToBeLogged();
return false;
}
if (this._hasRecentlyBeenAddedWithoutNES(item)) {
log('Diagnostic has been fixed without NES recently', logContext, this._tracer);
log('Diagnostic has been fixed without NES recently', logContext, this._logger);
tb.addDroppedReason('recently-added-without-nes', item);
logContext.markToBeLogged();
return false;
@@ -458,7 +457,7 @@ export class DiagnosticsCompletionProcessor extends Disposable {
const provider = this._diagnosticsCompletionProviders.get().find(p => p.providerName === item.providerName);
if (provider && provider.isCompletionItemStillValid && !provider.isCompletionItemStillValid(item, workspaceDocument)) {
log(`${provider.providerName}: Completion item is no longer valid`, logContext, this._tracer);
log(`${provider.providerName}: Completion item is no longer valid`, logContext, this._logger);
tb.addDroppedReason(`${provider.providerName}-no-longer-valid`, item);
logContext.markToBeLogged();
return false;
extensions/copilot/src/extension/inlineEdits/vscode-node/features/diagnosticsInlineEditProvider.ts
+9 -10
View File
@@ -9,9 +9,8 @@ import { DocumentId } from '../../../../platform/inlineEdits/common/dataTypes/do
import { InlineEditRequestLogContext } from '../../../../platform/inlineEdits/common/inlineEditLogContext';
import { ObservableGit } from '../../../../platform/inlineEdits/common/observableGit';
import { ShowNextEditPreference } from '../../../../platform/inlineEdits/common/statelessNextEditProvider';
import { ILogService } from '../../../../platform/log/common/logService';
import { ILogService, ILogger } from '../../../../platform/log/common/logService';
import * as errors from '../../../../util/common/errors';
import { createTracer, ITracer } from '../../../../util/common/tracing';
import { raceCancellation, timeout } from '../../../../util/vs/base/common/async';
import { CancellationToken } from '../../../../util/vs/base/common/cancellation';
import { BugIndicatingError } from '../../../../util/vs/base/common/errors';
@@ -53,7 +52,7 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
}
private readonly _diagnosticsCompletionHandler: DiagnosticsCompletionProcessor;
private _tracer: ITracer;
private _logger: ILogger;
constructor(
workspace: VSCodeWorkspace,
@@ -63,7 +62,7 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
) {
super();
this._tracer = createTracer(['NES', 'DiagnosticsNextEditProvider'], (s) => logService.trace(s));
this._logger = logService.createSubLogger(['NES', 'DiagnosticsNextEditProvider']);
this._diagnosticsCompletionHandler = this._register(instantiationService.createInstance(DiagnosticsCompletionProcessor, workspace, git));
}
@@ -76,7 +75,7 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
try {
await timeout(delayStart);
if (cancellationToken.isCancellationRequested) {
this._tracer.trace('cancellationRequested before started');
this._logger.trace('cancellationRequested before started');
return new DiagnosticsNextEditResult(logContext.requestId, undefined);
}
@@ -100,10 +99,10 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
} catch (error) {
const errorMessage = `Error occurred while waiting for diagnostic edit: ${errors.toString(errors.fromUnknown(error))}`;
logContext.addLog(errorMessage);
this._tracer.trace(errorMessage);
this._logger.trace(errorMessage);
return new DiagnosticsNextEditResult(logContext.requestId, undefined);
} finally {
this._tracer.trace('DiagnosticsInlineCompletionProvider runUntilNextEdit complete' + (cancellationToken.isCancellationRequested ? ' (cancelled)' : ''));
this._logger.trace('DiagnosticsInlineCompletionProvider runUntilNextEdit complete' + (cancellationToken.isCancellationRequested ? ' (cancelled)' : ''));
}
}
@@ -123,7 +122,7 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
// Diagnostics might not have updated yet since accepting a diagnostics based NES
if (item && this._hasRecentlyBeenAccepted(item)) {
tb.addDroppedReason(`${item.type}:recently-accepted`);
this._tracer.trace('recently accepted');
this._logger.trace('recently accepted');
return new DiagnosticsNextEditResult(logContext.requestId, undefined, diagnosticEditResult.workInProgress);
}
@@ -131,14 +130,14 @@ export class DiagnosticsNextEditProvider extends Disposable implements INextEdit
tb.setDiagnosticRunTelemetry(telemetry);
if (!item) {
this._tracer.trace('no diagnostic edit result');
this._logger.trace('no diagnostic edit result');
return new DiagnosticsNextEditResult(logContext.requestId, undefined, diagnosticEditResult.workInProgress);
}
tb.setType(item.type);
logContext.setDiagnosticsResult(item.getRootedLineEdit());
this._tracer.trace(`created next edit result`);
this._logger.trace(`created next edit result`);
return new DiagnosticsNextEditResult(logContext.requestId, {
edit: item.toOffsetEdit(),
extensions/copilot/src/extension/inlineEdits/vscode-node/jointInlineCompletionProvider.ts
+80 -79
View File
@@ -15,11 +15,10 @@ import { InlineEditRequestLogContext } from '../../../platform/inlineEdits/commo
import { ObservableGit } from '../../../platform/inlineEdits/common/observableGit';
import { checkIfCursorAtEndOfLine, shortenOpportunityId } from '../../../platform/inlineEdits/common/utils/utils';
import { NesHistoryContextProvider } from '../../../platform/inlineEdits/common/workspaceEditTracker/nesHistoryContextProvider';
import { ILogService } from '../../../platform/log/common/logService';
import { ILogger, ILogService } from '../../../platform/log/common/logService';
import { IExperimentationService } from '../../../platform/telemetry/common/nullExperimentationService';
import * as errors from '../../../util/common/errors';
import { isNotebookCell } from '../../../util/common/notebooks';
import { createTracer, ITracer } from '../../../util/common/tracing';
import { coalesce } from '../../../util/vs/base/common/arrays';
import { assertNever, softAssert } from '../../../util/vs/base/common/assert';
import { raceCancellation, raceTimeout } from '../../../util/vs/base/common/async';
@@ -294,7 +293,7 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
return this._completionsRequestsInFlight.size > 0;
}
private _tracer = createTracer(['NES', 'JointCompletionsProvider'], (msg) => this._logService.trace(msg));
private _logger: ILogger;
//#region Model picker
public readonly onDidChangeModelInfo = this._inlineEditProvider?.onDidChangeModelInfo;
@@ -309,10 +308,12 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
private readonly _inlineEditProvider: InlineCompletionProviderImpl | undefined,
@IConfigurationService private readonly _configService: IConfigurationService,
@IExperimentationService private readonly _expService: IExperimentationService,
@ILogService private readonly _logService: ILogService,
@ILogService logService: ILogService,
) {
super();
this._logger = logService.createSubLogger(['NES', 'JointCompletionsProvider']);
// Only set up the onDidChange emitter if the inlineEditProvider has one to channel
if (this._inlineEditProvider?.onDidChange) {
this._onDidChangeEmitter = this._register(new vscode.EventEmitter<NesChangeHint>());
@@ -325,20 +326,20 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
break;
case JointCompletionsProviderTriggerChangeStrategy.NoTriggerOnRequestInFlight:
if (this._isRequestInFlight) {
this._tracer.trace('Skipping onDidChange event firing because request is in flight');
this._logger.trace('Skipping onDidChange event firing because request is in flight');
return;
}
break;
case JointCompletionsProviderTriggerChangeStrategy.NoTriggerOnCompletionsRequestInFlight:
if (this._isCompletionsRequestInFlight) {
this._tracer.trace('Skipping onDidChange event firing because completions request is in flight');
this._logger.trace('Skipping onDidChange event firing because completions request is in flight');
return;
}
break;
default:
assertNever(strategy);
}
this._tracer.trace('Firing onDidChange event');
this._logger.trace('Firing onDidChange event');
this._onDidChangeEmitter!.fire(changeHint);
}));
}
@@ -350,21 +351,21 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
}
public async provideInlineCompletionItems(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken): Promise<SingularCompletionList | undefined> {
const tracer = this._tracer.sub([shortenOpportunityId(context.requestUuid), 'provideInlineCompletionItems']);
const logger = this._logger.createSubLogger([shortenOpportunityId(context.requestUuid), 'provideInlineCompletionItems']);
const strategy = this._configService.getExperimentBasedConfig(ConfigKey.TeamInternal.InlineEditsJointCompletionsProviderStrategy, this._expService);
switch (strategy) {
case JointCompletionsProviderStrategy.Regular:
return this.provideInlineCompletionItemsRegular(document, position, context, token, tracer);
return this.provideInlineCompletionItemsRegular(document, position, context, token, logger);
case JointCompletionsProviderStrategy.CursorEndOfLine:
return this.provideInlineCompletionItemsCursorEndOfLine(document, position, context, token, tracer);
return this.provideInlineCompletionItemsCursorEndOfLine(document, position, context, token, logger);
default:
assertNever(strategy);
}
}
private async provideInlineCompletionItemsCursorEndOfLine(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, tracer: ITracer): Promise<SingularCompletionList | undefined> {
private async provideInlineCompletionItemsCursorEndOfLine(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, logger: ILogger): Promise<SingularCompletionList | undefined> {
const sw = new StopWatch();
this._requestsInFlight.add(token);
@@ -373,17 +374,17 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
});
try {
if (this._completionsProvider === undefined && this._inlineEditProvider === undefined) {
tracer.returns('neither completions nor NES provider available');
logger.trace('Return: neither completions nor NES provider available');
return undefined;
} else if (this._completionsProvider === undefined && this._inlineEditProvider !== undefined) {
tracer.trace('only NES provider is available, invoking it');
const r = await this._invokeNESProvider(tracer, document, position, false, context, token, sw);
logger.trace('only NES provider is available, invoking it');
const r = await this._invokeNESProvider(logger, document, position, false, context, token, sw);
return r ? toInlineEditsList(r) : undefined;
} else if (this._completionsProvider !== undefined && this._inlineEditProvider === undefined) {
tracer.trace('only completions provider is available, invoking it');
const r = await this._invokeCompletionsProvider(tracer, document, position, context, token, sw);
logger.trace('only completions provider is available, invoking it');
const r = await this._invokeCompletionsProvider(logger, document, position, context, token, sw);
return r ? toCompletionsList(r) : undefined;
} else {
@@ -391,17 +392,17 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
const isCursorAtEndOfLine = checkIfCursorAtEndOfLine(cursorLine, position.character);
if (isCursorAtEndOfLine) {
tracer.trace('cursor is at end of line, invoking ghost-text provider only');
const r = await this._invokeCompletionsProvider(tracer, document, position, context, token, sw);
logger.trace('cursor is at end of line, invoking ghost-text provider only');
const r = await this._invokeCompletionsProvider(logger, document, position, context, token, sw);
return r ? toCompletionsList(r) : undefined;
}
const r = await this._invokeNESProvider(tracer, document, position, false, context, token, sw);
const r = await this._invokeNESProvider(logger, document, position, false, context, token, sw);
return r ? toInlineEditsList(r) : undefined;
}
} finally {
if (!token.isCancellationRequested) {
this._tracer.trace('request in flight: false -- due to provider finishing');
this._logger.trace('request in flight: false -- due to provider finishing');
this._requestsInFlight.delete(token);
}
disp.dispose();
@@ -411,7 +412,7 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
private lastNesSuggestion: null | LastNesSuggestion = null;
private provideInlineCompletionItemsInvocationCount = 0;
private async provideInlineCompletionItemsRegular(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, tracer: ITracer): Promise<SingularCompletionList | undefined> {
private async provideInlineCompletionItemsRegular(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, logger: ILogger): Promise<SingularCompletionList | undefined> {
const invocationId = ++this.provideInlineCompletionItemsInvocationCount;
const completionsCts = new CancellationTokenSource(token);
@@ -419,10 +420,10 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
this._requestsInFlight.add(token);
const disp1 = token.onCancellationRequested(() => {
tracer.trace(`invocation #${invocationId}: request in flight: false -- due to cancellation`);
logger.trace(`invocation #${invocationId}: request in flight: false -- due to cancellation`);
this._requestsInFlight.delete(token);
});
tracer.trace(`invocation #${invocationId} started; request in flight: true`);
logger.trace(`invocation #${invocationId} started; request in flight: true`);
let saveLastNesSuggestion: null | LastNesSuggestion = null;
try {
@@ -430,11 +431,11 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
const docVersionId = document.version;
if (this.lastNesSuggestion && this.lastNesSuggestion.docUri.toString() !== document.uri.toString()) {
tracer.trace('last NES suggestion is not for the current document, ignoring');
logger.trace('last NES suggestion is not for the current document, ignoring');
this.lastNesSuggestion = null;
}
const list = await this._provideInlineCompletionItemsRegular({ document, docSnapshot }, position, this.lastNesSuggestion, context, tracer, { coreToken: token, completionsCts, nesCts });
const list = await this._provideInlineCompletionItemsRegular({ document, docSnapshot }, position, this.lastNesSuggestion, context, logger, { coreToken: token, completionsCts, nesCts });
if (token.isCancellationRequested) {
return list;
@@ -450,7 +451,7 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
}
if (firstItem.uri && firstItem.uri.toString() !== document.uri.toString()) {
tracer.trace(`The NES suggestion is for a different document (${firstItem.uri.toString()} vs ${document.uri.toString()}), not saving as last NES suggestion`);
logger.trace(`The NES suggestion is for a different document (${firstItem.uri.toString()} vs ${document.uri.toString()}), not saving as last NES suggestion`);
return list;
}
@@ -465,7 +466,7 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
return list;
} finally {
if (!token.isCancellationRequested) {
tracer.trace(`invocation #${invocationId}: request in flight: false -- due to provider finishing`);
logger.trace(`invocation #${invocationId}: request in flight: false -- due to provider finishing`);
this._requestsInFlight.delete(token);
}
disp1.dispose();
@@ -474,12 +475,12 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
if (invocationId === this.provideInlineCompletionItemsInvocationCount) {
this.lastNesSuggestion = saveLastNesSuggestion;
if (this.lastNesSuggestion) {
tracer.trace(`Set the last NES suggestion for document ${this.lastNesSuggestion.docUri.toString()}`);
logger.trace(`Set the last NES suggestion for document ${this.lastNesSuggestion.docUri.toString()}`);
} else {
tracer.trace(`Cleared the last NES suggestion`);
logger.trace(`Cleared the last NES suggestion`);
}
} else {
tracer.trace(`Not setting the last NES suggestion because a newer invocation exists`);
logger.trace(`Not setting the last NES suggestion because a newer invocation exists`);
}
completionsCts.dispose();
@@ -492,44 +493,44 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
position: vscode.Position,
lastNesSuggestion: null | LastNesSuggestion,
context: vscode.InlineCompletionContext,
tracer: ITracer,
logger: ILogger,
tokens: { coreToken: CancellationToken; completionsCts: CancellationTokenSource; nesCts: CancellationTokenSource },
): Promise<SingularCompletionList | undefined> {
const sw = new StopWatch();
if (this._completionsProvider === undefined && this._inlineEditProvider === undefined) {
tracer.returns('neither completions nor NES provider available');
logger.trace('Return: neither completions nor NES provider available');
return undefined;
}
tracer.trace('requesting completions and/or NES');
logger.trace('requesting completions and/or NES');
// we don't want to trigger completions on selection change events
const isTriggeredDueToSelectionChange = context && (context as NESInlineCompletionContext).changeHint !== undefined;
if (!lastNesSuggestion || !lastNesSuggestion.completionItem.wasShown) {
// prefer completions unless there are none
tracer.trace(`defaulting to yielding to completions; last NES suggestion is ${lastNesSuggestion ? 'not shown' : 'not available'}`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(tracer, document, position, context, tokens.completionsCts.token, sw);
const nesP = this._invokeNESProvider(tracer, document, position, true, context, tokens.nesCts.token, sw);
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, tracer, tokens);
logger.trace(`defaulting to yielding to completions; last NES suggestion is ${lastNesSuggestion ? 'not shown' : 'not available'}`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(logger, document, position, context, tokens.completionsCts.token, sw);
const nesP = this._invokeNESProvider(logger, document, position, true, context, tokens.nesCts.token, sw);
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, logger, tokens);
}
tracer.trace(`last NES suggestion is for the current document, checking if it agrees with the current suggestion`);
logger.trace(`last NES suggestion is for the current document, checking if it agrees with the current suggestion`);
const enforceCacheDelay = (lastNesSuggestion.docVersionId !== document.version);
const nesP = this._invokeNESProvider(tracer, document, position, enforceCacheDelay, context, tokens.nesCts.token, sw);
const nesP = this._invokeNESProvider(logger, document, position, enforceCacheDelay, context, tokens.nesCts.token, sw);
if (!nesP) {
tracer.trace(`no NES provider`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(tracer, document, position, context, tokens.completionsCts.token, sw);
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, tracer, tokens);
logger.trace(`no NES provider`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(logger, document, position, context, tokens.completionsCts.token, sw);
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, logger, tokens);
}
const NES_CACHE_WAIT_MS = 10;
// scoping the variables
{
tracer.trace(`giving the NES provider ${NES_CACHE_WAIT_MS}ms to return what it has in its cache`);
logger.trace(`giving the NES provider ${NES_CACHE_WAIT_MS}ms to return what it has in its cache`);
const fastNesResult = await raceCancellation(
raceTimeout(
nesP,
@@ -540,14 +541,14 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
// got nes quickly
if (fastNesResult && this.doesNesSuggestionAgree(docSnapshot, lastNesSuggestion.docWithNesEditApplied, (fastNesResult.items as NesCompletionItem[]).at(0))) {
tracer.trace('last NES suggestion agrees with the current suggestion, using NES');
logger.trace('last NES suggestion agrees with the current suggestion, using NES');
const list: SingularCompletionList = toInlineEditsList(fastNesResult);
tracer.returns(`returning NES result in ${sw.elapsed()}ms`);
logger.trace(`Return: returning NES result in ${sw.elapsed()}ms`);
return list;
}
if (tokens.coreToken.isCancellationRequested) {
tracer.trace(`suggestions request was cancelled`);
logger.trace(`suggestions request was cancelled`);
void setEndOfLifeReason(this._completionsProvider, undefined, { kind: vscode.InlineCompletionsDisposeReasonKind.TokenCancellation });
void setEndOfLifeReason(this._inlineEditProvider, nesP, { kind: vscode.InlineCompletionsDisposeReasonKind.TokenCancellation });
tokens.completionsCts.cancel();
@@ -556,8 +557,8 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
}
}
tracer.trace(`the NES provider did not return in ${NES_CACHE_WAIT_MS}ms so we are triggering the completions provider too`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(tracer, document, position, context, tokens.completionsCts.token, sw);
logger.trace(`the NES provider did not return in ${NES_CACHE_WAIT_MS}ms so we are triggering the completions provider too`);
const completionsP = isTriggeredDueToSelectionChange ? undefined : this._invokeCompletionsProvider(logger, document, position, context, tokens.completionsCts.token, sw);
const suggestionsList = await raceCancellation(
Promise.race(coalesce([
@@ -569,7 +570,7 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
// got cancelled
if (suggestionsList === undefined) {
tracer.trace(`suggestions request was cancelled`);
logger.trace(`suggestions request was cancelled`);
void setEndOfLifeReason(this._completionsProvider, completionsP, { kind: vscode.InlineCompletionsDisposeReasonKind.TokenCancellation });
void setEndOfLifeReason(this._inlineEditProvider, nesP, { kind: vscode.InlineCompletionsDisposeReasonKind.TokenCancellation });
tokens.completionsCts.cancel();
@@ -579,34 +580,34 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
// got NES first
if (suggestionsList.type === 'nes' && suggestionsList.res && this.doesNesSuggestionAgree(docSnapshot, lastNesSuggestion.docWithNesEditApplied, (suggestionsList.res.items as NesCompletionItem[]).at(0))) {
tracer.trace('last NES suggestion agrees with the current suggestion, using NES');
return this._returnNES(suggestionsList.res, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, completionsP, sw, tracer, tokens);
logger.trace('last NES suggestion agrees with the current suggestion, using NES');
return this._returnNES(suggestionsList.res, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, completionsP, sw, logger, tokens);
}
tracer.trace('falling back to the default because completions came first or NES disagreed');
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, tracer, tokens);
logger.trace('falling back to the default because completions came first or NES disagreed');
return this._returnCompletionsOrOtherwiseNES(completionsP, nesP, docSnapshot, sw, logger, tokens);
}
private _invokeNESProvider(tracer: ITracer, document: vscode.TextDocument, position: vscode.Position, enforceCacheDelay: boolean, context: vscode.InlineCompletionContext, ct: CancellationToken, sw: StopWatch) {
private _invokeNESProvider(logger: ILogger, document: vscode.TextDocument, position: vscode.Position, enforceCacheDelay: boolean, context: vscode.InlineCompletionContext, ct: CancellationToken, sw: StopWatch) {
const changeHint = context.changeHint === undefined || NesChangeHint.is(context.changeHint) ? context.changeHint as NesChangeHint | undefined : undefined;
const nesContext: NESInlineCompletionContext = { ...context, enforceCacheDelay, changeHint };
let nesP: Promise<NesCompletionList | undefined> | undefined;
if (this._inlineEditProvider) {
tracer.trace(`- requesting NES provideInlineCompletionItems`);
logger.trace(`- requesting NES provideInlineCompletionItems`);
nesP = this._inlineEditProvider.provideInlineCompletionItems(document, position, nesContext, ct);
nesP.then((nesR) => {
tracer.trace(`got NES response in ${sw.elapsed()}ms -- ${nesR === undefined ? 'undefined' : `with ${nesR.items.length} items`}`);
logger.trace(`got NES response in ${sw.elapsed()}ms -- ${nesR === undefined ? 'undefined' : `with ${nesR.items.length} items`}`);
}).catch((e) => {
tracer.trace(`NES provider errored after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
logger.trace(`NES provider errored after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
});
} else {
tracer.trace(`- no NES provider`);
logger.trace(`- no NES provider`);
nesP = undefined;
}
return nesP;
}
private _invokeCompletionsProvider(tracer: ITracer, document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, ct: CancellationToken, sw: StopWatch) {
private _invokeCompletionsProvider(logger: ILogger, document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, ct: CancellationToken, sw: StopWatch) {
let completionsP: Promise<GhostTextCompletionList | undefined> | undefined;
if (this._completionsProvider) {
this._completionsRequestsInFlight.add(ct);
@@ -616,22 +617,22 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
disp.dispose();
};
try { // in case the provider throws synchronously
tracer.trace(`- requesting completions provideInlineCompletionItems`);
logger.trace(`- requesting completions provideInlineCompletionItems`);
completionsP = this._completionsProvider.provideInlineCompletionItems(document, position, context, ct);
completionsP.then((completionsR) => {
tracer.trace(`got completions response in ${sw.elapsed()}ms -- ${completionsR === undefined ? 'undefined' : `with ${completionsR.items.length} items`}`);
logger.trace(`got completions response in ${sw.elapsed()}ms -- ${completionsR === undefined ? 'undefined' : `with ${completionsR.items.length} items`}`);
}).catch((e) => {
tracer.trace(`completions provider errored after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
logger.trace(`completions provider errored after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
}).finally(() => {
cleanup();
});
} catch (e) {
cleanup();
tracer.trace(`completions provider threw synchronously after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
logger.trace(`completions provider threw synchronously after ${sw.elapsed()}ms -- ${errors.toString(errors.fromUnknown(e))}`);
throw e;
}
} else {
tracer.trace(`- no completions provider`);
logger.trace(`- no completions provider`);
completionsP = undefined;
}
return completionsP;
@@ -642,39 +643,39 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
nesP: Promise<NesCompletionList | undefined> | undefined,
docSnapshot: StringText,
sw: StopWatch,
tracer: ITracer,
logger: ILogger,
tokens: { coreToken: CancellationToken; completionsCts: CancellationTokenSource; nesCts: CancellationTokenSource },
) {
tracer.trace(`waiting for completions and/or NES responses`);
logger.trace(`waiting for completions and/or NES responses`);
const completionsR = completionsP ? await completionsP : undefined;
tracer.trace(`completions response received`);
logger.trace(`completions response received`);
if (completionsR && completionsR.items.length > 0) {
const filteredCompletionR = JointCompletionsProvider.retainOnlyMeaningfulEdits(docSnapshot, completionsR);
if (filteredCompletionR.items.length === 0) {
tracer.trace(`all completions edits are no-op, ignoring completions response`);
logger.trace(`all completions edits are no-op, ignoring completions response`);
} else {
tracer.trace(`using completions response, cancelling NES provider`);
return this._returnCompletions(filteredCompletionR, { kind: vscode.InlineCompletionsDisposeReasonKind.LostRace }, nesP, sw, tracer, tokens);
logger.trace(`using completions response, cancelling NES provider`);
return this._returnCompletions(filteredCompletionR, { kind: vscode.InlineCompletionsDisposeReasonKind.LostRace }, nesP, sw, logger, tokens);
}
}
const nesR = nesP ? await nesP : undefined;
tracer.trace(`NES response received`);
logger.trace(`NES response received`);
if (nesR && nesR.items.length > 0) {
const filteredNesR = JointCompletionsProvider.retainOnlyMeaningfulEdits(docSnapshot, nesR);
if (filteredNesR.items.length === 0) {
tracer.trace(`all NES edits are no-op, ignoring NES response`);
logger.trace(`all NES edits are no-op, ignoring NES response`);
} else {
tracer.trace(`using NES response`);
return this._returnNES(filteredNesR, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, completionsP, sw, tracer, tokens);
logger.trace(`using NES response`);
return this._returnNES(filteredNesR, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, completionsP, sw, logger, tokens);
}
}
// return empty completions
return this._returnCompletions(completionsR ?? { items: [] }, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, nesP, sw, tracer, tokens);
return this._returnCompletions(completionsR ?? { items: [] }, { kind: vscode.InlineCompletionsDisposeReasonKind.NotTaken }, nesP, sw, logger, tokens);
}
private _returnCompletions(
@@ -682,13 +683,13 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
nesDisposeReason: vscode.InlineCompletionsDisposeReason,
nesP: Promise<NesCompletionList | undefined> | undefined,
sw: StopWatch,
tracer: ITracer,
logger: ILogger,
tokens: { coreToken: CancellationToken; completionsCts: CancellationTokenSource; nesCts: CancellationTokenSource },
) {
void setEndOfLifeReason(this._inlineEditProvider, nesP, nesDisposeReason);
tokens.nesCts.cancel(); // cancel NES request if still pending
const list: SingularCompletionList = toCompletionsList(completionsR);
tracer.returns(`use completions response in ${sw.elapsed()}ms`);
logger.trace(`Return: use completions response in ${sw.elapsed()}ms`);
return list;
}
@@ -697,13 +698,13 @@ class JointCompletionsProvider extends Disposable implements vscode.InlineComple
completionsDisposeReason: vscode.InlineCompletionsDisposeReason,
completionsP: Promise<GhostTextCompletionList | undefined> | undefined,
sw: StopWatch,
tracer: ITracer,
logger: ILogger,
tokens: { coreToken: CancellationToken; completionsCts: CancellationTokenSource; nesCts: CancellationTokenSource },
) {
void setEndOfLifeReason(this._completionsProvider, completionsP, completionsDisposeReason);
tokens.completionsCts.cancel(); // cancel completions request if still pending
const list: SingularCompletionList = toInlineEditsList(nesR);
tracer.returns(`returning NES result in ${sw.elapsed()}ms`);
logger.trace(`Return: returning NES result in ${sw.elapsed()}ms`);
return list;
}
extensions/copilot/src/extension/linkify/test/vscode-node/notebookCellLinkifier.spec.ts
+5 -1
View File
@@ -69,7 +69,8 @@ suite('Notebook Cell Linkifier', () => {
debug: () => { /* no-op */ },
trace: () => { /* no-op */ },
show: () => { /* no-op */ },
createSubLogger(): ILogger { return logger; }
createSubLogger(): ILogger { return logger; },
withExtraTarget(): ILogger { return logger; }
};
const mockLogger = new class implements ILogService {
_serviceBrand: undefined;
@@ -86,6 +87,9 @@ suite('Notebook Cell Linkifier', () => {
createSubLogger(): ILogger {
return this;
}
withExtraTarget(): ILogger {
return this;
}
}();
function normalizeParts(parts: readonly LinkifiedPart[]): LinkifiedPart[] {
extensions/copilot/src/extension/test/node/notebookPromptRendering.spec.ts
+5 -1
View File
@@ -197,7 +197,8 @@ describe('Notebook Prompt Rendering', function () {
debug: () => { /* no-op */ },
trace: () => { /* no-op */ },
show: () => { /* no-op */ },
createSubLogger(): ILogger { return mockLogger; }
createSubLogger(): ILogger { return mockLogger; },
withExtraTarget(): ILogger { return mockLogger; }
};
testingServiceCollection.define(IAlternativeNotebookContentService, new SimulationAlternativeNotebookContentService('json'));
testingServiceCollection.define(IAlternativeNotebookContentEditGenerator, new AlternativeNotebookContentEditGenerator(new SimulationAlternativeNotebookContentService('json'), new DiffServiceImpl(), new class implements ILogService {
@@ -215,6 +216,9 @@ describe('Notebook Prompt Rendering', function () {
createSubLogger(): ILogger {
return this;
}
withExtraTarget(): ILogger {
return this;
}
}(), new NullTelemetryService()));
accessor = testingServiceCollection.createTestingAccessor();
});
extensions/copilot/src/extension/xtab/node/xtabNextCursorPredictor.ts
+3 -3
View File
@@ -17,7 +17,7 @@ import { IExperimentationService } from '../../../platform/telemetry/common/null
import { fromUnknown } from '../../../util/common/errors';
import { Result } from '../../../util/common/result';
import { TokenizerType } from '../../../util/common/tokenizer';
import { ITracer } from '../../../util/common/tracing';
import { ILogger } from '../../../platform/log/common/logService';
import { assertNever } from '../../../util/vs/base/common/assert';
import { CancellationToken } from '../../../util/vs/base/common/cancellation';
import { IInstantiationService } from '../../../util/vs/platform/instantiation/common/instantiation';
@@ -66,9 +66,9 @@ export class XtabNextCursorPredictor {
}
public async predictNextCursorPosition(promptPieces: PromptPieces, parentTracer: ITracer, telemetryBuilder: StatelessNextEditTelemetryBuilder | undefined, cancellationToken: CancellationToken): Promise<Result</* zero-based line number */ number, Error>> {
public async predictNextCursorPosition(promptPieces: PromptPieces, parentTracer: ILogger, telemetryBuilder: StatelessNextEditTelemetryBuilder | undefined, cancellationToken: CancellationToken): Promise<Result</* zero-based line number */ number, Error>> {
const tracer = parentTracer.sub('predictNextCursorPosition');
const tracer = parentTracer.createSubLogger('predictNextCursorPosition');
const systemMessage = `Your task is to predict the next line number in the current file where the developer is most likely to make their next edit, using the provided context. If you don't think anywhere is a good next line jump target, just output the current line number of the cursor. Make sure to just output the line number and nothing else (no explanation, reasoning, etc.).`;
extensions/copilot/src/extension/xtab/node/xtabProvider.ts
+20 -20
View File
@@ -25,6 +25,7 @@ import { editWouldDeleteWhatWasJustInserted, editWouldDeleteWhatWasJustInserted2
import { ILanguageContextProviderService, ProviderTarget } from '../../../platform/languageContextProvider/common/languageContextProviderService';
import { ILanguageDiagnosticsService } from '../../../platform/languages/common/languageDiagnosticsService';
import { ContextKind, SnippetContext } from '../../../platform/languageServer/common/languageContextService';
import { ILogger } from '../../../platform/log/common/logService';
import { OptionalChatRequestParams, Prediction } from '../../../platform/networking/common/fetch';
import { IChatEndpoint } from '../../../platform/networking/common/networking';
import { ISimulationTestContext } from '../../../platform/simulationTestContext/common/simulationTestContext';
@@ -33,7 +34,6 @@ import { IWorkspaceService } from '../../../platform/workspace/common/workspaceS
import { raceFilter } from '../../../util/common/async';
import * as errors from '../../../util/common/errors';
import { Result } from '../../../util/common/result';
import { ITracer } from '../../../util/common/tracing';
import { assertNever } from '../../../util/vs/base/common/assert';
import { AsyncIterableObject, DeferredPromise, raceTimeout, timeout } from '../../../util/vs/base/common/async';
import { CancellationToken } from '../../../util/vs/base/common/cancellation';
@@ -114,7 +114,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
this.userInteractionMonitor.handleRejection();
}
public async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, tracer: ITracer, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult> {
public async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult> {
const telemetry = new StatelessNextEditTelemetryBuilder(request);
logContext.setProviderStartTime();
@@ -125,7 +125,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
const delaySession = this.userInteractionMonitor.createDelaySession(request.providerRequestStartDateTime);
const iterator = this.doGetNextEdit(request, delaySession, tracer, logContext, cancellationToken, telemetry, RetryState.NotRetrying.INSTANCE);
const iterator = this.doGetNextEdit(request, delaySession, logger, logContext, cancellationToken, telemetry, RetryState.NotRetrying.INSTANCE);
let res = await iterator.next(); // for-async-await loop doesn't work because we need to access the final return value
@@ -170,7 +170,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
private doGetNextEdit(
request: StatelessNextEditRequest,
delaySession: DelaySession,
tracer: ITracer,
logger: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
telemetryBuilder: StatelessNextEditTelemetryBuilder,
@@ -180,7 +180,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
request,
getOrDeduceSelectionFromLastEdit(request.getActiveDocument()),
delaySession,
tracer,
logger,
logContext,
cancellationToken,
telemetryBuilder,
@@ -192,14 +192,14 @@ export class XtabProvider implements IStatelessNextEditProvider {
request: StatelessNextEditRequest,
selection: Range | null,
delaySession: DelaySession,
parentTracer: ITracer,
parentTracer: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
telemetryBuilder: StatelessNextEditTelemetryBuilder,
retryState: RetryState.t,
): EditStreaming {
const tracer = parentTracer.sub(['XtabProvider', 'doGetNextEditWithSelection']);
const tracer = parentTracer.createSubLogger(['XtabProvider', 'doGetNextEditWithSelection']);
const activeDocument = request.getActiveDocument();
@@ -371,7 +371,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
activeDocument: StatelessNextEditDocument,
cursorPosition: Position,
promptOptions: ModelConfig,
tracer: ITracer,
tracer: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
): Promise<LanguageContextResponse | undefined> {
@@ -404,7 +404,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
delaySession: DelaySession,
activeDocument: StatelessNextEditDocument,
cursorPosition: Position,
tracer: ITracer,
tracer: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
): Promise<LanguageContextResponse | undefined> {
@@ -496,12 +496,12 @@ export class XtabProvider implements IStatelessNextEditProvider {
retryState: RetryState.t;
},
delaySession: DelaySession,
parentTracer: ITracer,
parentTracer: ILogger,
telemetryBuilder: StatelessNextEditTelemetryBuilder,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
): EditStreaming {
const tracer = parentTracer.sub('streamEditsWithFiltering');
const tracer = parentTracer.createSubLogger('streamEditsWithFiltering');
const iterator = this.streamEdits(
request,
@@ -566,12 +566,12 @@ export class XtabProvider implements IStatelessNextEditProvider {
retryState: RetryState.t;
},
delaySession: DelaySession,
parentTracer: ITracer,
parentTracer: ILogger,
telemetryBuilder: StatelessNextEditTelemetryBuilder,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
): EditStreaming {
const tracer = parentTracer.sub('streamEdits');
const tracer = parentTracer.createSubLogger('streamEdits');
const useFetcher = this.configService.getExperimentBasedConfig(ConfigKey.NextEditSuggestionsFetcher, this.expService) || undefined;
@@ -852,7 +852,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
editWindow: OffsetRange,
promptPieces: PromptPieces,
delaySession: DelaySession,
tracer: ITracer,
tracer: ILogger,
logContext: InlineEditRequestLogContext,
cancellationToken: CancellationToken,
telemetryBuilder: StatelessNextEditTelemetryBuilder,
@@ -934,7 +934,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
return new OffsetRange(areaAroundStart, areaAroundEndExcl);
}
private computeEditWindowLinesRange(currentDocument: CurrentDocument, request: StatelessNextEditRequest, tracer: ITracer, telemetry: StatelessNextEditTelemetryBuilder): OffsetRange {
private computeEditWindowLinesRange(currentDocument: CurrentDocument, request: StatelessNextEditRequest, tracer: ILogger, telemetry: StatelessNextEditTelemetryBuilder): OffsetRange {
const currentDocLines = currentDocument.lines;
const cursorLineOffset = currentDocument.cursorLineOffset;
@@ -1161,23 +1161,23 @@ export class XtabProvider implements IStatelessNextEditProvider {
}
}
private async debounce(delaySession: DelaySession, retryState: RetryState.t, tracer: ITracer, telemetry: StatelessNextEditTelemetryBuilder) {
private async debounce(delaySession: DelaySession, retryState: RetryState.t, logger: ILogger, telemetry: StatelessNextEditTelemetryBuilder) {
if (this.simulationCtx.isInSimulationTests) {
return;
}
if (retryState instanceof RetryState.Retrying) {
tracer.trace('Skipping debounce on retry');
logger.trace('Skipping debounce on retry');
return;
}
const debounceTime = delaySession.getDebounceTime();
tracer.trace(`Debouncing for ${debounceTime} ms`);
logger.trace(`Debouncing for ${debounceTime} ms`);
telemetry.setDebounceTime(debounceTime);
await timeout(debounceTime);
}
private determineArtificialDelayMs(delaySession: DelaySession, tracer: ITracer, telemetry: StatelessNextEditTelemetryBuilder): number | undefined {
private determineArtificialDelayMs(delaySession: DelaySession, logger: ILogger, telemetry: StatelessNextEditTelemetryBuilder): number | undefined {
if (this.simulationCtx.isInSimulationTests) {
return;
}
@@ -1187,7 +1187,7 @@ export class XtabProvider implements IStatelessNextEditProvider {
return undefined;
}
tracer.trace(`Enforcing artificial delay of ${artificialDelay} ms`);
logger.trace(`Enforcing artificial delay of ${artificialDelay} ms`);
telemetry.setArtificialDelay(artificialDelay);
return artificialDelay;
extensions/copilot/src/extension/xtab/test/node/xtabNextCursorPredictor.spec.ts
+8 -7
View File
@@ -15,7 +15,8 @@ import { NextCursorLinePrediction } from '../../../../platform/inlineEdits/commo
import { AggressivenessLevel, DEFAULT_OPTIONS, PromptOptions } from '../../../../platform/inlineEdits/common/dataTypes/xtabPromptOptions';
import { StatelessNextEditDocument } from '../../../../platform/inlineEdits/common/statelessNextEditProvider';
import { ITestingServicesAccessor } from '../../../../platform/test/node/services';
import { createTracer, ITracer } from '../../../../util/common/tracing';
import { ILogger } from '../../../../platform/log/common/logService';
import { TestLogService } from '../../../../platform/testing/common/testLogService';
import { CancellationToken } from '../../../../util/vs/base/common/cancellation';
import { DisposableStore } from '../../../../util/vs/base/common/lifecycle';
import { LineEdit } from '../../../../util/vs/editor/common/core/edits/lineEdit';
@@ -29,8 +30,8 @@ import { PromptPieces } from '../../common/promptCrafting';
import { CurrentDocument } from '../../common/xtabCurrentDocument';
import { XtabNextCursorPredictor } from '../../node/xtabNextCursorPredictor';
function createTestTracer(): ITracer {
return createTracer('test', () => { /* no-op log function */ });
function createTestLogger(): ILogger {
return new TestLogService();
}
function computeTokens(s: string): number {
@@ -112,7 +113,7 @@ describe('XtabNextCursorPredictor', () => {
describe('404 disabling behavior', () => {
it('should disable predictor after receiving NotFound response', async () => {
const predictor = instaService.createInstance(XtabNextCursorPredictor, computeTokens);
const tracer = createTestTracer();
const tracer = createTestLogger();
const promptPieces = createTestPromptPieces();
// First verify predictor is enabled
@@ -140,7 +141,7 @@ describe('XtabNextCursorPredictor', () => {
it('should remain disabled for subsequent calls after 404', async () => {
const predictor = instaService.createInstance(XtabNextCursorPredictor, computeTokens);
const tracer = createTestTracer();
const tracer = createTestLogger();
const promptPieces = createTestPromptPieces();
// Set up mock to return NotFound
@@ -173,7 +174,7 @@ describe('XtabNextCursorPredictor', () => {
it('should not disable predictor for other error types', async () => {
const predictor = instaService.createInstance(XtabNextCursorPredictor, computeTokens);
const tracer = createTestTracer();
const tracer = createTestLogger();
const promptPieces = createTestPromptPieces();
// Verify predictor is enabled initially
@@ -201,7 +202,7 @@ describe('XtabNextCursorPredictor', () => {
it('should return success result when prediction succeeds', async () => {
const predictor = instaService.createInstance(XtabNextCursorPredictor, computeTokens);
const tracer = createTestTracer();
const tracer = createTestLogger();
const promptPieces = createTestPromptPieces();
// Set up mock to return success with line number
extensions/copilot/src/platform/inlineEdits/common/statelessNextEditProvider.ts
+2 -2
View File
@@ -5,7 +5,6 @@
import { Raw } from '@vscode/prompt-tsx';
import { Result } from '../../../util/common/result';
import { ITracer } from '../../../util/common/tracing';
import { assert, assertNever } from '../../../util/vs/base/common/assert';
import { DeferredPromise } from '../../../util/vs/base/common/async';
import { CancellationToken, CancellationTokenSource } from '../../../util/vs/base/common/cancellation';
@@ -16,6 +15,7 @@ import { Position } from '../../../util/vs/editor/common/core/position';
import { OffsetRange } from '../../../util/vs/editor/common/core/ranges/offsetRange';
import { StringText } from '../../../util/vs/editor/common/core/text/abstractText';
import { ChatFetchResponseType, FetchResponse } from '../../chat/common/commonTypes';
import { ILogger } from '../../log/common/logService';
import { ISerializedOffsetRange, LogEntry, serializeOffsetRange } from '../../workspaceRecorder/common/workspaceLog';
import { DocumentId } from './dataTypes/documentId';
import { Edits } from './dataTypes/edit';
@@ -43,7 +43,7 @@ export type PushEdit = (edit: Result<StreamedEdit, NoNextEditReason>) => void;
export interface IStatelessNextEditProvider {
readonly ID: string;
readonly showNextEditPreference?: ShowNextEditPreference;
provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, tracer: ITracer, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult>;
provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise<StatelessNextEditResult>;
handleAcceptance?(): void;
handleRejection?(): void;
}
extensions/copilot/src/platform/inlineEdits/node/inlineEditsModelService.ts
+26 -25
View File
@@ -6,7 +6,6 @@
import type * as vscode from 'vscode';
import { filterMap } from '../../../util/common/arrays';
import * as errors from '../../../util/common/errors';
import { createTracer } from '../../../util/common/tracing';
import { pushMany } from '../../../util/vs/base/common/arrays';
import { assertNever, softAssert } from '../../../util/vs/base/common/assert';
import { Event } from '../../../util/vs/base/common/event';
@@ -16,7 +15,7 @@ import { CopilotToken } from '../../authentication/common/copilotToken';
import { ICopilotTokenStore } from '../../authentication/common/copilotTokenStore';
import { ConfigKey, ExperimentBasedConfig, IConfigurationService } from '../../configuration/common/configurationService';
import { IVSCodeExtensionContext } from '../../extContext/common/extensionContext';
import { ILogService } from '../../log/common/logService';
import { ILogger, ILogService } from '../../log/common/logService';
import { IProxyModelsService } from '../../proxyModels/common/proxyModelsService';
import { IExperimentationService } from '../../telemetry/common/nullExperimentationService';
import { ITelemetryService } from '../../telemetry/common/telemetry';
@@ -89,7 +88,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
public readonly onModelListUpdated: Event<void>;
private _tracer = createTracer(['NES', 'ModelsService'], (msg) => this._logService.trace(msg));
private _logger: ILogger;
constructor(
@ICopilotTokenStore private readonly _tokenStore: ICopilotTokenStore,
@@ -102,10 +101,12 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
) {
super();
const tracer = this._tracer.sub('constructor');
this._logger = _logService.createSubLogger(['NES', 'ModelsService']);
const logger = this._logger.createSubLogger('constructor');
this._modelsObs = derived((reader) => {
tracer.trace('computing models');
logger.trace('computing models');
return this.aggregateModels({
copilotToken: this._copilotTokenObs.read(reader),
fetchedNesModels: this._fetchedModelsObs.read(reader),
@@ -116,7 +117,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
}).recomputeInitiallyAndOnChange(this._store);
this._currentModelObs = derived<Model, void>((reader) => {
tracer.trace('computing current model');
logger.trace('computing current model');
return this._pickModel({
preferredModelName: this._preferredModelNameObs.read(reader),
models: this._modelsObs.read(reader),
@@ -124,7 +125,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
}).recomputeInitiallyAndOnChange(this._store);
this._modelInfoObs = derived((reader) => {
tracer.trace('computing model info');
logger.trace('computing model info');
return {
models: this._modelsObs.read(reader),
currentModelId: this._currentModelObs.read(reader).modelName,
@@ -184,10 +185,10 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
if (newPreferredModel.source === ModelSource.ExpConfig || // because exp-configured model already takes highest priority
(newPreferredModelId === expectedDefaultModel.modelName && !models.some(m => m.source === ModelSource.ExpConfig))
) {
this._tracer.trace(`New preferred model id ${newPreferredModelId} is the same as the default model, resetting user setting.`);
this._logger.trace(`New preferred model id ${newPreferredModelId} is the same as the default model, resetting user setting.`);
await this._configService.setConfig(ConfigKey.Advanced.InlineEditsPreferredModel, 'none');
} else {
this._tracer.trace(`New preferred model id ${newPreferredModelId} is different from the default model, updating user setting to ${newPreferredModelId}.`);
this._logger.trace(`New preferred model id ${newPreferredModelId} is different from the default model, updating user setting to ${newPreferredModelId}.`);
await this._configService.setConfig(ConfigKey.Advanced.InlineEditsPreferredModel, newPreferredModelId);
}
}
@@ -207,7 +208,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
defaultModelConfigString: string | undefined;
},
): Model[] {
const tracer = this._tracer.sub('aggregateModels');
const logger = this._logger.createSubLogger('aggregateModels');
const models: Model[] = [];
@@ -218,33 +219,33 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
if (localModelConfig) {
if (models.some(m => m.modelName === localModelConfig.modelName)) {
tracer.trace('Local model configuration already exists in the model list, skipping.');
logger.trace('Local model configuration already exists in the model list, skipping.');
} else {
tracer.trace(`Adding local model configuration: ${localModelConfig.modelName}`);
logger.trace(`Adding local model configuration: ${localModelConfig.modelName}`);
models.push({ ...localModelConfig, source: ModelSource.LocalConfig });
}
}
if (modelConfigString) {
tracer.trace('Parsing modelConfigurationString...');
logger.trace('Parsing modelConfigurationString...');
const parsedConfig = this.parseModelConfigStringSetting(ConfigKey.TeamInternal.InlineEditsXtabProviderModelConfigurationString);
if (parsedConfig && !models.some(m => m.modelName === parsedConfig.modelName)) {
tracer.trace(`Adding model from modelConfigurationString: ${parsedConfig.modelName}`);
logger.trace(`Adding model from modelConfigurationString: ${parsedConfig.modelName}`);
models.push({ ...parsedConfig, source: ModelSource.ExpConfig });
} else {
tracer.trace('No valid model found in modelConfigurationString.');
logger.trace('No valid model found in modelConfigurationString.');
}
}
const useSlashModels = this._configService.getExperimentBasedConfig(ConfigKey.TeamInternal.InlineEditsUseSlashModels, this._expService);
if (useSlashModels && fetchedNesModels && fetchedNesModels.length > 0) {
tracer.trace(`Processing ${fetchedNesModels.length} fetched models...`);
logger.trace(`Processing ${fetchedNesModels.length} fetched models...`);
const filteredFetchedModels = filterMap(fetchedNesModels, (m) => {
if (!isPromptingStrategy(m.capabilities.promptStrategy)) {
return undefined;
}
if (models.some(knownModel => knownModel.modelName === m.name)) {
tracer.trace(`Fetched model ${m.name} already exists in the model list, skipping.`);
logger.trace(`Fetched model ${m.name} already exists in the model list, skipping.`);
return undefined;
}
return {
@@ -255,18 +256,18 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
lintOptions: undefined,
} satisfies Model;
});
tracer.trace(`Adding ${filteredFetchedModels.length} fetched models after filtering.`);
logger.trace(`Adding ${filteredFetchedModels.length} fetched models after filtering.`);
pushMany(models, filteredFetchedModels);
} else {
// push default model if /models doesn't give us any models
tracer.trace(`adding built-in default model: useSlashModels ${useSlashModels}, fetchedNesModels ${fetchedNesModels}`);
logger.trace(`adding built-in default model: useSlashModels ${useSlashModels}, fetchedNesModels ${fetchedNesModels?.length ?? 'undefined'}`);
const defaultModel = this.determineDefaultModel(copilotToken, defaultModelConfigString);
if (defaultModel) {
if (models.some(m => m.modelName === defaultModel.modelName)) {
tracer.trace('Default model configuration already exists in the model list, skipping.');
logger.trace('Default model configuration already exists in the model list, skipping.');
} else {
tracer.trace(`Adding default model configuration: ${defaultModel.modelName}`);
logger.trace(`Adding default model configuration: ${defaultModel.modelName}`);
models.push(defaultModel);
}
}
@@ -276,10 +277,10 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
}
public selectedModelConfiguration(): ModelConfiguration {
const tracer = this._tracer.sub('selectedModelConfiguration');
const logger = this._logger.createSubLogger('selectedModelConfiguration');
const model = this._currentModelObs.get();
if (model) {
tracer.trace(`Selected model found: ${model.modelName}`);
logger.trace(`Selected model found: ${model.modelName}`);
return {
modelName: model.modelName,
promptingStrategy: model.promptingStrategy,
@@ -287,7 +288,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
lintOptions: model.lintOptions,
};
}
tracer.trace('No selected model found, using default model.');
logger.trace('No selected model found, using default model.');
return this.determineDefaultModel(this._copilotTokenObs.get(), this._defaultModelConfigObs.get());
}
@@ -351,7 +352,7 @@ export class InlineEditsModelService extends Disposable implements IInlineEditsM
if (expConfiguredModel) {
const isUndesiredModelId = this._undesiredModelsManager.isUndesiredModelId(expConfiguredModel.modelName);
if (isUndesiredModelId) {
this._tracer.trace(`Exp-configured model ${expConfiguredModel.modelName} is marked as undesired by the user. Skipping.`);
this._logger.trace(`Exp-configured model ${expConfiguredModel.modelName} is marked as undesired by the user. Skipping.`);
} else {
return expConfiguredModel;
}
extensions/copilot/src/platform/log/common/logService.ts
+129
View File
@@ -49,6 +49,23 @@ export interface ILogTarget {
show?(preserveFocus?: boolean): void;
}
/**
* Utility functions for creating ILogTarget instances.
*/
export namespace LogTarget {
/**
* Creates an ILogTarget from a simple callback function.
*
* @example
* logger.withExtraTarget(LogTarget.fromCallback((level, msg) => {
* console.log(`[${LogLevel[level]}] ${msg}`);
* }));
*/
export function fromCallback(fn: (level: LogLevel, message: string) => void): ILogTarget {
return { logIt: fn };
}
}
// Simple implementation of a log targe used for logging to the console.
export class ConsoleLog implements ILogTarget {
constructor(private readonly prefix?: string, private readonly minLogLevel: LogLevel = LogLevel.Warning) { }
@@ -99,9 +116,32 @@ export interface ILogger {
* Sub-loggers can be nested, and the prefixes will accumulate,
* e.g., `[Parent][Child] message`.
*
* Sub-loggers inherit extra targets from their parent.
*
* @param topic The topic name or array of topic names to prefix messages with
*/
createSubLogger(topic: string | readonly string[]): ILogger;
/**
* Returns a new logger that also logs to the specified extra target.
* The original logger is unchanged (immutable).
*
* Can be chained to add multiple targets. Sub-loggers created from this
* logger will inherit all extra targets.
*
* Errors thrown by extra targets are silently caught.
*
* @param target An ILogTarget instance
* @returns A new ILogger with the extra target attached
*
* @example
* const logger = logService
* .createSubLogger('MyFeature')
* .withExtraTarget(LogTarget.fromCallback((level, msg) => {
* logContext.trace(msg);
* }));
*/
withExtraTarget(target: ILogTarget): ILogger;
}
export class LogServiceImpl extends Disposable implements ILogService {
@@ -144,6 +184,10 @@ export class LogServiceImpl extends Disposable implements ILogService {
createSubLogger(topic: string | readonly string[]): ILogger {
return this.logger.createSubLogger(topic);
}
withExtraTarget(target: ILogTarget): ILogger {
return this.logger.withExtraTarget(target);
}
}
class LoggerImpl implements ILogger {
@@ -183,6 +227,10 @@ class LoggerImpl implements ILogger {
createSubLogger(topic: string | readonly string[]): ILogger {
return new SubLogger(this, topic);
}
withExtraTarget(target: ILogTarget): ILogger {
return new LoggerWithExtraTargets(this, [target]);
}
}
class SubLogger implements ILogger {
@@ -230,6 +278,87 @@ class SubLogger implements ILogger {
createSubLogger(topic: string | readonly string[]): ILogger {
return new SubLogger(this._parent, topic, this._prefix);
}
withExtraTarget(target: ILogTarget): ILogger {
return new LoggerWithExtraTargets(this, [target], this._prefix);
}
}
class LoggerWithExtraTargets implements ILogger {
constructor(
private readonly _parent: ILogger,
private readonly _extraTargets: readonly ILogTarget[],
private readonly _prefix: string = '',
) { }
private _notifyExtraTargets(level: LogLevel, message: string): void {
const prefixedMessage = this._prefix ? `${this._prefix} ${message}` : message;
for (const target of this._extraTargets) {
try {
target.logIt(level, prefixedMessage);
} catch {
// Silent catch - extra targets must not affect primary logging
}
}
}
trace(message: string): void {
this._notifyExtraTargets(LogLevel.Trace, message);
this._parent.trace(message);
}
debug(message: string): void {
this._notifyExtraTargets(LogLevel.Debug, message);
this._parent.debug(message);
}
info(message: string): void {
this._notifyExtraTargets(LogLevel.Info, message);
this._parent.info(message);
}
warn(message: string): void {
this._notifyExtraTargets(LogLevel.Warning, message);
this._parent.warn(message);
}
error(error: string | Error, message?: string): void {
// For extra targets, format a simple message
const errorStr = typeof error === 'string' ? error : (error.message || 'Error');
const fullMessage = message ? `${errorStr}: ${message}` : errorStr;
this._notifyExtraTargets(LogLevel.Error, fullMessage);
this._parent.error(error, message);
}
show(preserveFocus?: boolean): void {
this._parent.show(preserveFocus);
for (const target of this._extraTargets) {
try {
target.show?.(preserveFocus);
} catch {
// Silent catch
}
}
}
createSubLogger(topic: string | readonly string[]): ILogger {
// Sub-logger inherits extra targets with updated prefix
const topics = Array.isArray(topic) ? topic : [topic];
const newPrefix = this._prefix + topics.map(t => `[${t}]`).join('');
return new LoggerWithExtraTargets(
this._parent.createSubLogger(topic),
this._extraTargets,
newPrefix
);
}
withExtraTarget(target: ILogTarget): ILogger {
return new LoggerWithExtraTargets(
this._parent,
[...this._extraTargets, target],
this._prefix
);
}
}
export function collectErrorMessages(e: any): string {
extensions/copilot/src/platform/log/test/common/subLogger.spec.ts
+161 -1
View File
@@ -4,7 +4,7 @@
*--------------------------------------------------------------------------------------------*/
import { beforeEach, describe, expect, test } from 'vitest';
import { LogLevel, LogServiceImpl } from '../../common/logService';
import { ILogTarget, LogLevel, LogServiceImpl, LogTarget } from '../../common/logService';
import { TestLogTarget } from './loggerHelpers';
describe('SubLogger', () => {
@@ -157,4 +157,164 @@ describe('SubLogger', () => {
logTarget.assertHasMessage(LogLevel.Info, '[Parent][Child] child message');
});
});
describe('withExtraTarget', () => {
test('extra target receives log messages', () => {
const extraTarget = new TestLogTarget();
const logger = logService
.createSubLogger('Feature')
.withExtraTarget(extraTarget);
logger.info('test message');
// Primary target receives prefixed message
logTarget.assertHasMessage(LogLevel.Info, '[Feature] test message');
// Extra target also receives prefixed message
extraTarget.assertHasMessage(LogLevel.Info, '[Feature] test message');
});
test('withExtraTarget returns new immutable logger', () => {
const extraTarget = new TestLogTarget();
const original = logService.createSubLogger('Feature');
const withExtra = original.withExtraTarget(extraTarget);
original.info('original only');
withExtra.info('with extra');
// Extra target only receives from withExtra logger
expect(extraTarget.hasMessage(LogLevel.Info, '[Feature] original only')).toBe(false);
extraTarget.assertHasMessage(LogLevel.Info, '[Feature] with extra');
});
test('sub-loggers inherit extra targets', () => {
const extraTarget = new TestLogTarget();
const parent = logService
.createSubLogger('Parent')
.withExtraTarget(extraTarget);
const child = parent.createSubLogger('Child');
child.info('child message');
extraTarget.assertHasMessage(LogLevel.Info, '[Parent][Child] child message');
});
test('can chain multiple extra targets', () => {
const extra1 = new TestLogTarget();
const extra2 = new TestLogTarget();
const logger = logService
.createSubLogger('Feature')
.withExtraTarget(extra1)
.withExtraTarget(extra2);
logger.info('test');
extra1.assertHasMessage(LogLevel.Info, '[Feature] test');
extra2.assertHasMessage(LogLevel.Info, '[Feature] test');
});
test('extra target errors do not affect primary logging', () => {
const throwingTarget: ILogTarget = {
logIt: () => { throw new Error('Target error'); }
};
const logger = logService
.createSubLogger('Feature')
.withExtraTarget(throwingTarget);
// Should not throw
logger.info('test message');
// Primary target still receives the message
logTarget.assertHasMessage(LogLevel.Info, '[Feature] test message');
});
test('extra targets receive all log levels', () => {
const extraTarget = new TestLogTarget();
const logger = logService
.createSubLogger('Test')
.withExtraTarget(extraTarget);
logger.trace('trace msg');
logger.debug('debug msg');
logger.info('info msg');
logger.warn('warn msg');
logger.error('error msg');
extraTarget.assertHasMessage(LogLevel.Trace, '[Test] trace msg');
extraTarget.assertHasMessage(LogLevel.Debug, '[Test] debug msg');
extraTarget.assertHasMessage(LogLevel.Info, '[Test] info msg');
extraTarget.assertHasMessage(LogLevel.Warning, '[Test] warn msg');
extraTarget.assertHasMessage(LogLevel.Error, '[Test] error msg');
});
test('show() calls show on extra targets', () => {
let showCalled = false;
let preserveFocusValue: boolean | undefined;
const extraTarget: ILogTarget = {
logIt: () => { },
show: (preserveFocus) => {
showCalled = true;
preserveFocusValue = preserveFocus;
}
};
const logger = logService
.createSubLogger('Test')
.withExtraTarget(extraTarget);
logger.show(true);
expect(showCalled).toBe(true);
expect(preserveFocusValue).toBe(true);
});
test('withExtraTarget works on LogServiceImpl directly', () => {
const extraTarget = new TestLogTarget();
const logger = logService.withExtraTarget(extraTarget);
logger.info('direct message');
logTarget.assertHasMessage(LogLevel.Info, 'direct message');
extraTarget.assertHasMessage(LogLevel.Info, 'direct message');
});
});
describe('LogTarget.fromCallback', () => {
test('creates valid ILogTarget from callback', () => {
const messages: Array<{ level: LogLevel; msg: string }> = [];
const logger = logService
.createSubLogger('Feature')
.withExtraTarget(LogTarget.fromCallback((level, msg) => {
messages.push({ level, msg });
}));
logger.warn('warning message');
expect(messages).toHaveLength(1);
expect(messages[0]).toEqual({
level: LogLevel.Warning,
msg: '[Feature] warning message'
});
});
test('callback receives correct log levels', () => {
const levels: LogLevel[] = [];
const logger = logService
.withExtraTarget(LogTarget.fromCallback((level) => {
levels.push(level);
}));
logger.trace('');
logger.debug('');
logger.info('');
logger.warn('');
logger.error('');
expect(levels).toEqual([
LogLevel.Trace,
LogLevel.Debug,
LogLevel.Info,
LogLevel.Warning,
LogLevel.Error
]);
});
});
});
extensions/copilot/src/platform/notebook/test/node/alternativeContent.spec.ts
+5 -1
View File
@@ -44,7 +44,8 @@ describe('Alternative Content for Notebooks', () => {
debug: () => { /* no-op */ },
trace: () => { /* no-op */ },
show: () => { /* no-op */ },
createSubLogger(): ILogger { return mockLogger; }
createSubLogger(): ILogger { return mockLogger; },
withExtraTarget(): ILogger { return mockLogger; }
};
function getEditGenerator(provider: BaseAlternativeNotebookContentProvider) {
return new AlternativeNotebookContentEditGenerator(new class implements IAlternativeNotebookContentService {
@@ -70,6 +71,9 @@ describe('Alternative Content for Notebooks', () => {
createSubLogger(): ILogger {
return this;
}
withExtraTarget(): ILogger {
return this;
}
}(), new NullTelemetryService());
}
[true, false].forEach(applyEditsImmediately => {
extensions/copilot/src/platform/notebook/test/node/alternativeContentEditGenerator.spec.ts
+5 -1
View File
@@ -32,7 +32,8 @@ describe('Alternative Content Edit Generator', () => {
debug: () => { /* no-op */ },
trace: () => { /* no-op */ },
show: () => { /* no-op */ },
createSubLogger(): ILogger { return mockLogger; }
createSubLogger(): ILogger { return mockLogger; },
withExtraTarget(): ILogger { return mockLogger; }
};
function getEditGenerator(provider: BaseAlternativeNotebookContentProvider) {
return new AlternativeNotebookContentEditGenerator(new class implements IAlternativeNotebookContentService {
@@ -58,6 +59,9 @@ describe('Alternative Content Edit Generator', () => {
createSubLogger(): ILogger {
return this;
}
withExtraTarget(): ILogger {
return this;
}
}(), new NullTelemetryService());
}
describe(`${provider.kind} Edit Generator`, () => {
extensions/copilot/src/platform/testing/common/testLogService.ts
+4 -1
View File
@@ -3,7 +3,7 @@
* Licensed under the MIT License. See License.txt in the project root for license information.
*--------------------------------------------------------------------------------------------*/
import { ILogger, ILogService } from '../../log/common/logService';
import { ILogger, ILogService, ILogTarget } from '../../log/common/logService';
export class TestLogService implements ILogService {
_serviceBrand: undefined;
@@ -16,4 +16,7 @@ export class TestLogService implements ILogService {
createSubLogger(_topic: string | readonly string[]): ILogger {
return this;
}
withExtraTarget(_target: ILogTarget): ILogger {
return this;
}
}
extensions/copilot/src/util/common/tracing.ts
-141
View File
@@ -1,141 +0,0 @@
/*---------------------------------------------------------------------------------------------
* Copyright (c) Microsoft Corporation. All rights reserved.
* Licensed under the MIT License. See License.txt in the project root for license information.
*--------------------------------------------------------------------------------------------*/
type LogFn = (message: string) => void;
/**
* @deprecated Use `ILogger.createSubLogger` from `logService.ts` instead.
*/
export interface SubTracingOptions {
readonly extraLog?: LogFn;
}
/**
* @deprecated Use `ILogger` from `logService.ts` instead, with `createSubLogger` for topic prefixes.
*/
export interface ITracer {
trace(message: string, ...payload: unknown[]): void;
/**
* Creates a sub-tracer. Logs when the sub-tracer is created.
*
* @param name specifies sections, eg ['Git', 'PullRequest']
*/
sub(name: string | string[], opts?: SubTracingOptions): ITracer;
/**
* Creates a sub-tracer. Does NOT log when the sub-tracer is created.
*
* @param name specifies sections, eg ['Git', 'PullRequest']
*/
subNoEntry(name: string | string[], opts?: SubTracingOptions): ITracer;
throws(message?: string, ...payload: unknown[]): void;
returns(message?: string, ...payload: unknown[]): void;
}
/**
* @deprecated Use `ILogger.createSubLogger` from `logService.ts` instead.
*/
export class Tracer implements ITracer {
constructor(
private readonly section: string | string[],
private readonly logFn: LogFn,
) { }
trace(message: string, ...payload: unknown[]): void {
this.logFn(this.argsToString(message, payload));
}
private argsToString(message: string, payload: unknown[]): string {
const payloadStr = payload.length ? ` ${this.stringify(payload)}` : '';
return `[${this.sectionStr}] ${message}${payloadStr}`;
}
sub(name: string | string[], opts?: SubTracingOptions): ITracer {
const sub = this.subNoEntry(name, opts);
sub.trace('created');
return sub;
}
subNoEntry(name: string | string[], opts?: SubTracingOptions): ITracer {
const subSection = this.createSubSection(name);
const extraLog = opts?.extraLog;
const logFn: LogFn = (
extraLog === undefined
? this.logFn
: (message: string) => {
this.logFn(message);
extraLog(message);
}
);
const sub = new Tracer(subSection, logFn);
return sub;
}
throws(message?: string, ...payload: unknown[]): void {
const payloadStr = payload.length ? ` ${this.stringify(payload)}` : '';
this.logFn(`[${this.sectionStr}] Throw: ${message ? message : 'void'}${payloadStr}`);
}
returns(message?: string, ...payload: unknown[]): void {
const payloadStr = payload.length ? ` ${this.stringify(payload)}` : '';
this.logFn(`[${this.sectionStr}] Return: ${message ? message : 'void'}${payloadStr}`);
}
private get sectionStr(): string {
return Array.isArray(this.section) ? this.section.join('][') : this.section;
}
private createSubSection(name: string | string[]): string[] {
return Array.isArray(this.section) ? this.section.concat(name) : [this.section, ...(Array.isArray(name) ? name : [name])];
}
private stringify(value: unknown): string {
function stringifyObj(obj: Object): string {
const toStringValue = obj.toString();
if (toStringValue && toStringValue !== '[object Object]') {
return toStringValue;
}
if (obj instanceof Error) {
return obj.stack || obj.message;
}
return JSON.stringify(obj, null, 2);
}
if (!value) {
return JSON.stringify(value, null, 2);
}
if (typeof value === 'string') {
return value;
}
if (typeof value === 'function') {
return value.name ? `[Function: ${value.name}]` : '[Function]';
}
if (Array.isArray(value)) {
return `[${value.map(v => this.stringify(v)).join(', ')}]`;
}
if (typeof value === 'object') {
return stringifyObj(value);
}
const valueToString = value.toString();
if (valueToString && valueToString !== '[object Object]') {
return valueToString;
}
return stringifyObj(value as Object);
}
}
/**
* @deprecated Use `ILogger.createSubLogger` from `logService.ts` instead.
* Example: `logService.createSubLogger(['NES', 'Provider'])`
*/
export function createTracer(section: string | string[], logFn: (message: string) => void): ITracer {
return new Tracer(section, logFn);
}