diff --git a/src/extension/inlineEdits/common/editRebase.ts b/src/extension/inlineEdits/common/editRebase.ts index fbb3889eb1..4222e78272 100644 --- a/src/extension/inlineEdits/common/editRebase.ts +++ b/src/extension/inlineEdits/common/editRebase.ts @@ -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 { } } -export function tryRebase(originalDocument: string, editWindow: OffsetRange | undefined, originalEdits: readonly StringReplacement[], detailedEdits: AnnotatedStringReplacement[][], 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[][], 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[][], 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[][], 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; } diff --git a/src/extension/inlineEdits/common/rejectionCollector.ts b/src/extension/inlineEdits/common/rejectionCollector.ts index baf512ff77..8bfcb1fd2f 100644 --- a/src/extension/inlineEdits/common/rejectionCollector.ts +++ b/src/extension/inlineEdits/common/rejectionCollector.ts @@ -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(); - 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); diff --git a/src/extension/inlineEdits/node/nextEditCache.ts b/src/extension/inlineEdits/node/nextEditCache.ts index e8231861e1..17fc5ab921 100644 --- a/src/extension/inlineEdits/node/nextEditCache.ts +++ b/src/extension/inlineEdits/node/nextEditCache.ts @@ -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, - 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; } } diff --git a/src/extension/inlineEdits/node/nextEditProvider.ts b/src/extension/inlineEdits/node/nextEditProvider.ts index 1e56b34dc5..582512368f 100644 --- a/src/extension/inlineEdits/node/nextEditProvider.ts +++ b/src/extension/inlineEdits/node/nextEditProvider.ts @@ -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 this._logService.trace(s))); + private readonly _rejectionCollector = this._register(new RejectionCollector(this._workspace, this._logService)); private readonly _nextEditCache: NextEditCache; private _pendingStatelessNextEditRequest: StatelessNextEditRequest | null = null; @@ -89,7 +88,7 @@ export class NextEditProvider extends Disposable implements INextEditProvider 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 { + 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 { - 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 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> { + private async fetchNextEdit(req: NextEditFetchRequest, doc: IObservableDocument, nesConfigs: INesConfigs, shouldExpandEditWindow: boolean, parentLogger: ILogger, telemetryBuilder: LlmNESTelemetryBuilder, cancellationToken: CancellationToken): Promise> { 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 { 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 { 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 { - 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 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 { + async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, _logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise { const telemetryBuilder = new StatelessNextEditTelemetryBuilder(request); diff --git a/src/extension/inlineEdits/test/common/editRebase.spec.ts b/src/extension/inlineEdits/test/common/editRebase.spec.ts index 02a96c28bf..aea5f43b6d 100644 --- a/src/extension/inlineEdits/test/common/editRebase.spec.ts +++ b/src/extension/inlineEdits/test/common/editRebase.spec.ts @@ -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; 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; 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; 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; expect(result[0].rebasedEditIndex).toBe(0); diff --git a/src/extension/inlineEdits/test/node/nextEditProviderCaching.spec.ts b/src/extension/inlineEdits/test/node/nextEditProviderCaching.spec.ts index 8cdfbcc183..a4a0e781c5 100644 --- a/src/extension/inlineEdits/test/node/nextEditProviderCaching.spec.ts +++ b/src/extension/inlineEdits/test/node/nextEditProviderCaching.spec.ts @@ -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( [ diff --git a/src/extension/inlineEdits/test/node/rejectionCollector.spec.ts b/src/extension/inlineEdits/test/node/rejectionCollector.spec.ts index 0e078b3663..b7c1bc1cf3 100644 --- a/src/extension/inlineEdits/test/node/rejectionCollector.spec.ts +++ b/src/extension/inlineEdits/test/node/rejectionCollector.spec.ts @@ -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); diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/anyDiagnosticsCompletionProvider.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/anyDiagnosticsCompletionProvider.ts index 2d1cf5ca3c..0b4f525275 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/anyDiagnosticsCompletionProvider.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/anyDiagnosticsCompletionProvider.ts @@ -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); diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/asyncDiagnosticsCompletionProvider.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/asyncDiagnosticsCompletionProvider.ts index 9c6e043003..2bcb86482d 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/asyncDiagnosticsCompletionProvider.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/asyncDiagnosticsCompletionProvider.ts @@ -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; -} \ No newline at end of file +} diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/diagnosticsCompletions.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/diagnosticsCompletions.ts index e1d4acfb2a..a6e527e0d0 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/diagnosticsCompletions.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/diagnosticsCompletions.ts @@ -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, logContext?: DiagnosticInlineEditRequestLogContext, tracer?: ITracer) { +export function logList(title: string, list: Array, 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 diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/importDiagnosticsCompletionProvider.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/importDiagnosticsCompletionProvider.ts index 90f4aba674..9c6c314649 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/importDiagnosticsCompletionProvider.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsBasedCompletions/importDiagnosticsCompletionProvider.ts @@ -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; 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; } diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsCompletionProcessor.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsCompletionProcessor.ts index d688028e84..609cd49282 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsCompletionProcessor.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsCompletionProcessor.ts @@ -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 { 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; diff --git a/src/extension/inlineEdits/vscode-node/features/diagnosticsInlineEditProvider.ts b/src/extension/inlineEdits/vscode-node/features/diagnosticsInlineEditProvider.ts index b3b081f108..380956a50b 100644 --- a/src/extension/inlineEdits/vscode-node/features/diagnosticsInlineEditProvider.ts +++ b/src/extension/inlineEdits/vscode-node/features/diagnosticsInlineEditProvider.ts @@ -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(), diff --git a/src/extension/inlineEdits/vscode-node/jointInlineCompletionProvider.ts b/src/extension/inlineEdits/vscode-node/jointInlineCompletionProvider.ts index 3f00e61fe8..35502813ad 100644 --- a/src/extension/inlineEdits/vscode-node/jointInlineCompletionProvider.ts +++ b/src/extension/inlineEdits/vscode-node/jointInlineCompletionProvider.ts @@ -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()); @@ -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 { - 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 { + private async provideInlineCompletionItemsCursorEndOfLine(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, logger: ILogger): Promise { 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 { + private async provideInlineCompletionItemsRegular(document: vscode.TextDocument, position: vscode.Position, context: vscode.InlineCompletionContext, token: vscode.CancellationToken, logger: ILogger): Promise { 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 { 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 | 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 | 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 | 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 | 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 | 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; } diff --git a/src/extension/linkify/test/vscode-node/notebookCellLinkifier.spec.ts b/src/extension/linkify/test/vscode-node/notebookCellLinkifier.spec.ts index 6a79e44649..41e950390a 100644 --- a/src/extension/linkify/test/vscode-node/notebookCellLinkifier.spec.ts +++ b/src/extension/linkify/test/vscode-node/notebookCellLinkifier.spec.ts @@ -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[] { diff --git a/src/extension/test/node/notebookPromptRendering.spec.ts b/src/extension/test/node/notebookPromptRendering.spec.ts index 193596a105..224290dff8 100644 --- a/src/extension/test/node/notebookPromptRendering.spec.ts +++ b/src/extension/test/node/notebookPromptRendering.spec.ts @@ -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(); }); diff --git a/src/extension/xtab/node/xtabNextCursorPredictor.ts b/src/extension/xtab/node/xtabNextCursorPredictor.ts index 10c9f6d029..c93aa766d2 100644 --- a/src/extension/xtab/node/xtabNextCursorPredictor.ts +++ b/src/extension/xtab/node/xtabNextCursorPredictor.ts @@ -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> { + public async predictNextCursorPosition(promptPieces: PromptPieces, parentTracer: ILogger, telemetryBuilder: StatelessNextEditTelemetryBuilder | undefined, cancellationToken: CancellationToken): Promise> { - 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.).`; diff --git a/src/extension/xtab/node/xtabProvider.ts b/src/extension/xtab/node/xtabProvider.ts index 926d93649b..ba04863436 100644 --- a/src/extension/xtab/node/xtabProvider.ts +++ b/src/extension/xtab/node/xtabProvider.ts @@ -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 { + public async provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise { 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 { @@ -404,7 +404,7 @@ export class XtabProvider implements IStatelessNextEditProvider { delaySession: DelaySession, activeDocument: StatelessNextEditDocument, cursorPosition: Position, - tracer: ITracer, + tracer: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken, ): Promise { @@ -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; diff --git a/src/extension/xtab/test/node/xtabNextCursorPredictor.spec.ts b/src/extension/xtab/test/node/xtabNextCursorPredictor.spec.ts index 6068df1fa3..fa02d48c8a 100644 --- a/src/extension/xtab/test/node/xtabNextCursorPredictor.spec.ts +++ b/src/extension/xtab/test/node/xtabNextCursorPredictor.spec.ts @@ -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 diff --git a/src/platform/inlineEdits/common/statelessNextEditProvider.ts b/src/platform/inlineEdits/common/statelessNextEditProvider.ts index 895c4f3515..9c2d098111 100644 --- a/src/platform/inlineEdits/common/statelessNextEditProvider.ts +++ b/src/platform/inlineEdits/common/statelessNextEditProvider.ts @@ -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) => void; export interface IStatelessNextEditProvider { readonly ID: string; readonly showNextEditPreference?: ShowNextEditPreference; - provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, tracer: ITracer, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise; + provideNextEdit(request: StatelessNextEditRequest, pushEdit: PushEdit, logger: ILogger, logContext: InlineEditRequestLogContext, cancellationToken: CancellationToken): Promise; handleAcceptance?(): void; handleRejection?(): void; } diff --git a/src/platform/inlineEdits/node/inlineEditsModelService.ts b/src/platform/inlineEdits/node/inlineEditsModelService.ts index 797feefecb..1921396db4 100644 --- a/src/platform/inlineEdits/node/inlineEditsModelService.ts +++ b/src/platform/inlineEdits/node/inlineEditsModelService.ts @@ -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; - 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((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; } diff --git a/src/platform/log/common/logService.ts b/src/platform/log/common/logService.ts index df8b851745..52a3af9ca4 100644 --- a/src/platform/log/common/logService.ts +++ b/src/platform/log/common/logService.ts @@ -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 { diff --git a/src/platform/log/test/common/subLogger.spec.ts b/src/platform/log/test/common/subLogger.spec.ts index dfb9299107..f7baf50974 100644 --- a/src/platform/log/test/common/subLogger.spec.ts +++ b/src/platform/log/test/common/subLogger.spec.ts @@ -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 + ]); + }); + }); }); diff --git a/src/platform/notebook/test/node/alternativeContent.spec.ts b/src/platform/notebook/test/node/alternativeContent.spec.ts index e155f02750..0437eb4e30 100644 --- a/src/platform/notebook/test/node/alternativeContent.spec.ts +++ b/src/platform/notebook/test/node/alternativeContent.spec.ts @@ -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 => { diff --git a/src/platform/notebook/test/node/alternativeContentEditGenerator.spec.ts b/src/platform/notebook/test/node/alternativeContentEditGenerator.spec.ts index 695efd9cb5..5a8945fc95 100644 --- a/src/platform/notebook/test/node/alternativeContentEditGenerator.spec.ts +++ b/src/platform/notebook/test/node/alternativeContentEditGenerator.spec.ts @@ -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`, () => { diff --git a/src/platform/testing/common/testLogService.ts b/src/platform/testing/common/testLogService.ts index f4aa387f84..65e8d49b64 100644 --- a/src/platform/testing/common/testLogService.ts +++ b/src/platform/testing/common/testLogService.ts @@ -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; + } } diff --git a/src/util/common/tracing.ts b/src/util/common/tracing.ts deleted file mode 100644 index 7197e202d8..0000000000 --- a/src/util/common/tracing.ts +++ /dev/null @@ -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); -}