Add more logging for auto selection of interpreters

.github/PULL_REQUEST_TEMPLATE.md

@@ -7,6 +7,8 @@ For #
 - [ ] Pull request represents a single change (i.e. not fixing disparate/unrelated things in a single PR)
 - [ ] Title summarizes what is changing
 - [ ] Has a [news entry](https://github.com/Microsoft/vscode-python/tree/master/news) file (remember to thank yourself!)
+- [ ] Has sufficient logging.
+- [ ] Has telemetry for enhancements.
 - [ ] Unit tests & system/integration tests are added/updated
 - [ ] [Test plan](https://github.com/Microsoft/vscode-python/blob/master/.github/test_plan.md) is updated as appropriate
 - [ ] [`package-lock.json`](https://github.com/Microsoft/vscode-python/blob/master/package-lock.json) has been regenerated by running `npm install` (if dependencies have changed)

src/client/common/logger.ts

@@ -110,6 +110,7 @@ function trace(message: string, options: LogOptions = LogOptions.None, logLevel?
         const originalMethod = descriptor.value;
         // tslint:disable-next-line:no-function-expression no-any
         descriptor.value = function (...args: any[]) {
+            const className = _ && _.constructor ? _.constructor.name : '';
             // tslint:disable-next-line:no-any
             function writeSuccess(returnValue?: any) {
                 if (logLevel === LogLevel.Error) {
@@ -123,6 +124,7 @@ function trace(message: string, options: LogOptions = LogOptions.None, logLevel?
             // tslint:disable-next-line:no-any
             function writeToLog(returnValue?: any, ex?: Error) {
                 const messagesToLog = [message];
+                messagesToLog.push(`Class name = ${className}`);
                 if ((options && LogOptions.Arguments) === LogOptions.Arguments) {
                     messagesToLog.push(argsToLogString(args));
                 }

src/client/interpreter/autoSelection/index.ts

@@ -10,6 +10,8 @@ import { IWorkspaceService } from '../../common/application/types';
 import '../../common/extensions';
 import { IFileSystem } from '../../common/platform/types';
 import { IPersistentState, IPersistentStateFactory, Resource } from '../../common/types';
+import { captureTelemetry } from '../../telemetry';
+import { PYTHON_INTERPRETER_AUTO_SELECTION } from '../../telemetry/constants';
 import { IInterpreterHelper, PythonInterpreter } from '../contracts';
 import { AutoSelectionRule, IInterpreterAutoSelectionRule, IInterpreterAutoSelectionService, IInterpreterAutoSeletionProxyService } from './types';
 
@@ -61,6 +63,7 @@ export class InterpreterAutoSelectionService implements IInterpreterAutoSelectio
         currentPathInterpreter.setNextRule(winRegInterpreter);
         winRegInterpreter.setNextRule(systemInterpreter);
     }
+    @captureTelemetry(PYTHON_INTERPRETER_AUTO_SELECTION, { rule: AutoSelectionRule.all }, true)
     public async autoSelectInterpreter(resource: Resource): Promise<void> {
         Promise.all(this.rules.map(item => item.autoSelectInterpreter(undefined))).ignoreErrors();
         await this.initializeStore();

src/client/interpreter/autoSelection/rules/baseRule.ts

@@ -6,6 +6,7 @@
 import { inject, injectable, unmanaged } from 'inversify';
 import { compare } from 'semver';
 import '../../../common/extensions';
+import { traceDecorators, traceVerbose } from '../../../common/logger';
 import { IFileSystem } from '../../../common/platform/types';
 import { IPersistentState, IPersistentStateFactory, Resource } from '../../../common/types';
 import { StopWatch } from '../../../common/utils/stopWatch';
@@ -23,28 +24,33 @@ export enum NextAction {
 export abstract class BaseRuleService implements IInterpreterAutoSelectionRule {
     protected nextRule?: IInterpreterAutoSelectionRule;
     private readonly stateStore: IPersistentState<PythonInterpreter | undefined>;
-    constructor(@unmanaged() private readonly ruleName: AutoSelectionRule,
+    constructor(@unmanaged() protected readonly ruleName: AutoSelectionRule,
         @inject(IFileSystem) private readonly fs: IFileSystem,
         @inject(IPersistentStateFactory) stateFactory: IPersistentStateFactory) {
         this.stateStore = stateFactory.createGlobalPersistentState<PythonInterpreter | undefined>(`InterpreterAutoSeletionRule-${this.ruleName}`, undefined);
     }
     public setNextRule(rule: IInterpreterAutoSelectionRule): void {
         this.nextRule = rule;
     }
+    @traceDecorators.verbose('autoSelectInterpreter')
     public async autoSelectInterpreter(resource: Resource, manager?: IInterpreterAutoSelectionService): Promise<void> {
         await this.clearCachedInterpreterIfInvalid(resource);
         const stopWatch = new StopWatch();
         const action = await this.onAutoSelectInterpreter(resource, manager);
+        traceVerbose(`Rule = ${this.ruleName}, result = ${action}`);
         const identified = action === NextAction.runNextRule;
         sendTelemetryEvent(PYTHON_INTERPRETER_AUTO_SELECTION, { elapsedTime: stopWatch.elapsedTime }, { rule: this.ruleName, identified });
         if (action === NextAction.runNextRule) {
             await this.next(resource, manager);
         }
     }
     public getPreviouslyAutoSelectedInterpreter(_resource: Resource): PythonInterpreter | undefined {
-        return this.stateStore.value;
+        const value = this.stateStore.value;
+        traceVerbose(`Current value for rule ${this.ruleName} is ${value ? JSON.stringify(value) : 'nothing'}`);
+        return value;
     }
     protected abstract onAutoSelectInterpreter(resource: Resource, manager?: IInterpreterAutoSelectionService): Promise<NextAction>;
+    @traceDecorators.verbose('setGlobalInterpreter')
     protected async setGlobalInterpreter(interpreter?: PythonInterpreter, manager?: IInterpreterAutoSelectionService): Promise<boolean> {
         await this.cacheSelectedInterpreter(undefined, interpreter);
         if (!interpreter || !manager || !interpreter.version) {
@@ -77,6 +83,7 @@ export abstract class BaseRuleService implements IInterpreterAutoSelectionRule {
         await this.stateStore.updateValue(interpreter);
     }
     protected async next(resource: Resource, manager?: IInterpreterAutoSelectionService): Promise<void> {
+        traceVerbose(`Executing next rule from ${this.ruleName}`);
         return this.nextRule && manager ? this.nextRule.autoSelectInterpreter(resource, manager) : undefined;
     }
 }

src/client/interpreter/autoSelection/rules/cached.ts

@@ -4,6 +4,7 @@
 'use strict';
 
 import { inject, injectable, named } from 'inversify';
+import { traceVerbose } from '../../../common/logger';
 import { IFileSystem } from '../../../common/platform/types';
 import { IPersistentStateFactory, Resource } from '../../../common/types';
 import { IInterpreterHelper } from '../../contracts';
@@ -29,6 +30,7 @@ export class CachedInterpretersAutoSelectionRule extends BaseRuleService {
             .filter(item => !!item)
             .map(item => item!);
         const bestInterpreter = this.helper.getBestInterpreter(cachedInterpreters);
+        traceVerbose(`Selected Interpreter from ${this.ruleName}, ${bestInterpreter ? JSON.stringify(bestInterpreter) : 'Nothing Selected'}`);
         return await this.setGlobalInterpreter(bestInterpreter, manager) ? NextAction.exit : NextAction.runNextRule;
     }
 }

src/client/interpreter/autoSelection/rules/currentPath.ts

@@ -4,6 +4,7 @@
 'use strict';
 
 import { inject, injectable, named } from 'inversify';
+import { traceVerbose } from '../../../common/logger';
 import { IFileSystem } from '../../../common/platform/types';
 import { IPersistentStateFactory, Resource } from '../../../common/types';
 import { CURRENT_PATH_SERVICE, IInterpreterHelper, IInterpreterLocatorService } from '../../contracts';
@@ -23,6 +24,7 @@ export class CurrentPathInterpretersAutoSelectionRule extends BaseRuleService {
     protected async onAutoSelectInterpreter(resource: Resource, manager?: IInterpreterAutoSelectionService): Promise<NextAction> {
         const interpreters = await this.currentPathInterpreterLocator.getInterpreters(resource);
         const bestInterpreter = this.helper.getBestInterpreter(interpreters);
+        traceVerbose(`Selected Interpreter from ${this.ruleName}, ${bestInterpreter ? JSON.stringify(bestInterpreter) : 'Nothing Selected'}`);
         return await this.setGlobalInterpreter(bestInterpreter, manager) ? NextAction.exit : NextAction.runNextRule;
     }
 }

src/client/interpreter/autoSelection/rules/system.ts

@@ -4,6 +4,7 @@
 'use strict';
 
 import { inject, injectable } from 'inversify';
+import { traceVerbose } from '../../../common/logger';
 import { IFileSystem } from '../../../common/platform/types';
 import { IPersistentStateFactory, Resource } from '../../../common/types';
 import { IInterpreterHelper, IInterpreterService, InterpreterType } from '../../contracts';
@@ -27,6 +28,7 @@ export class SystemWideInterpretersAutoSelectionRule extends BaseRuleService {
             int.type !== InterpreterType.Venv &&
             int.type !== InterpreterType.PipEnv);
         const bestInterpreter = this.helper.getBestInterpreter(filteredInterpreters);
+        traceVerbose(`Selected Interpreter from ${this.ruleName}, ${bestInterpreter ? JSON.stringify(bestInterpreter) : 'Nothing Selected'}`);
         return await this.setGlobalInterpreter(bestInterpreter, manager) ? NextAction.exit : NextAction.runNextRule;
     }
 }

src/client/interpreter/autoSelection/rules/winRegistry.ts

@@ -4,6 +4,7 @@
 'use strict';
 
 import { inject, injectable, named } from 'inversify';
+import { traceVerbose } from '../../../common/logger';
 import { IFileSystem, IPlatformService } from '../../../common/platform/types';
 import { IPersistentStateFactory, Resource } from '../../../common/types';
 import { OSType } from '../../../common/utils/platform';
@@ -28,6 +29,7 @@ export class WindowsRegistryInterpretersAutoSelectionRule extends BaseRuleServic
         }
         const interpreters = await this.winRegInterpreterLocator.getInterpreters(resource);
         const bestInterpreter = this.helper.getBestInterpreter(interpreters);
+        traceVerbose(`Selected Interpreter from ${this.ruleName}, ${bestInterpreter ? JSON.stringify(bestInterpreter) : 'Nothing Selected'}`);
         return await this.setGlobalInterpreter(bestInterpreter, manager) ? NextAction.exit : NextAction.runNextRule;
     }
 }

src/client/interpreter/autoSelection/rules/workspaceEnv.ts

@@ -6,6 +6,7 @@
 import { inject, injectable, named } from 'inversify';
 import { Uri } from 'vscode';
 import { IWorkspaceService } from '../../../common/application/types';
+import { traceVerbose } from '../../../common/logger';
 import { IFileSystem, IPlatformService } from '../../../common/platform/types';
 import { IPersistentStateFactory, Resource } from '../../../common/types';
 import { createDeferredFromPromise } from '../../../common/utils/async';
@@ -60,6 +61,7 @@ export class WorkspaceVirtualEnvInterpretersAutoSelectionRule extends BaseRuleSe
             await this.cacheSelectedInterpreter(workspacePath.folderUri, bestInterpreter);
             await manager.setWorkspaceInterpreter(workspacePath.folderUri!, bestInterpreter);
         }
+        traceVerbose(`Selected Interpreter from ${this.ruleName}, ${bestInterpreter ? JSON.stringify(bestInterpreter) : 'Nothing Selected'}`);
         return NextAction.runNextRule;
     }
     protected async getWorkspaceVirtualEnvInterpreters(resource: Resource): Promise<PythonInterpreter[] | undefined> {

src/client/interpreter/autoSelection/types.ts

@@ -33,6 +33,7 @@ export interface IInterpreterAutoSelectionService extends IInterpreterAutoSeleti
 }
 
 export enum AutoSelectionRule {
+    all = 'all',
     currentPath = 'currentPath',
     workspaceVirtualEnvs = 'workspaceEnvs',
     settings = 'settings',