Add more logging and only retry once if fetching interpreter information fails (#20180)

Kartik Raj · web-flow · commit 5bfc6d57338a · 2022-11-08T10:32:39.000-05:00
For microsoft/vscode-python#20147
diff --git a/src/client/common/process/rawProcessApis.ts b/src/client/common/process/rawProcessApis.ts
@@ -11,6 +11,7 @@ import { DEFAULT_ENCODING } from './constants';
 import { ExecutionResult, ObservableExecutionResult, Output, ShellOptions, SpawnOptions, StdErrError } from './types';
 import { noop } from '../utils/misc';
 import { decodeBuffer } from './decoder';
+import { traceVerbose } from '../../logging';
 
 function getDefaultOptions<T extends ShellOptions | SpawnOptions>(options: T, defaultEnv?: EnvironmentVariables): T {
     const defaultOptions = { ...options };
@@ -51,6 +52,7 @@ export function shellExec(
     disposables?: Set<IDisposable>,
 ): Promise<ExecutionResult<string>> {
     const shellOptions = getDefaultOptions(options, defaultEnv);
+    traceVerbose(`Shell Exec: ${command} with options: ${JSON.stringify(shellOptions, null, 4)}`);
     return new Promise((resolve, reject) => {
         // eslint-disable-next-line @typescript-eslint/no-explicit-any
         const callback = (e: any, stdout: any, stderr: any) => {
diff --git a/src/client/proposedApi.ts b/src/client/proposedApi.ts
@@ -274,6 +274,9 @@ export function buildProposedApi(
 
 async function resolveEnvironment(path: string, discoveryApi: IDiscoveryAPI): Promise<ResolvedEnvironment | undefined> {
     const env = await discoveryApi.resolveEnv(path);
+    if (env?.version.major === -1 || env?.version.minor === -1 || env?.version.micro === -1) {
+        traceError(`Invalid version for ${path}: ${JSON.stringify(env)}`);
+    }
     if (!env) {
         return undefined;
     }
diff --git a/src/client/pythonEnvironments/base/info/environmentInfoService.ts b/src/client/pythonEnvironments/base/info/environmentInfoService.ts
@@ -3,7 +3,7 @@
 
 import { Uri } from 'vscode';
 import { IDisposableRegistry } from '../../../common/types';
-import { createDeferred, Deferred } from '../../../common/utils/async';
+import { createDeferred, Deferred, sleep } from '../../../common/utils/async';
 import { createRunningWorkerPool, IWorkerPool, QueuePosition } from '../../../common/utils/workerPool';
 import { getInterpreterInfo, InterpreterInformation } from './interpreter';
 import { buildPythonExecInfo } from '../../exec';
@@ -102,9 +102,6 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
         this._getEnvironmentInfo(env, priority)
             .then((r) => {
                 deferred.resolve(r);
-                if (r === undefined) {
-                    this.cache.delete(normCasePath(interpreterPath));
-                }
             })
             .catch((ex) => {
                 deferred.reject(ex);
@@ -115,6 +112,7 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
     public async _getEnvironmentInfo(
         env: PythonEnvInfo,
         priority?: EnvironmentInfoServiceQueuePriority,
+        retryOnce = true,
     ): Promise<InterpreterInformation | undefined> {
         if (env.kind === PythonEnvKind.Conda && env.executable.filename === 'python') {
             const emptyInterpreterInfo: InterpreterInformation = {
@@ -166,6 +164,12 @@ class EnvironmentInfoService implements IEnvironmentInfoService {
                 traceError(reason);
             }
         }
+        if (r === undefined && retryOnce) {
+            // Retry once, in case the environment was not fully populated. Also observed in CI:
+            // https://github.com/microsoft/vscode-python/issues/20147 where running environment the first time
+            // failed due to unknown reasons.
+            return sleep(2000).then(() => this._getEnvironmentInfo(env, priority, false));
+        }
         return r;
     }
 
diff --git a/src/client/pythonEnvironments/base/locators/composite/envsCollectionCache.ts b/src/client/pythonEnvironments/base/locators/composite/envsCollectionCache.ts
@@ -3,7 +3,7 @@
 
 import { Event } from 'vscode';
 import { isTestExecution } from '../../../../common/constants';
-import { traceInfo } from '../../../../logging';
+import { traceInfo, traceVerbose } from '../../../../logging';
 import { arePathsSame, getFileInfo, pathExists } from '../../../common/externalDependencies';
 import { PythonEnvInfo } from '../../info';
 import { areEnvsDeepEqual, areSameEnv, getEnvPath } from '../../info/env';
@@ -141,6 +141,7 @@ export class PythonEnvInfoCache extends PythonEnvsWatcher<PythonEnvCollectionCha
     public addEnv(env: PythonEnvInfo, hasLatestInfo?: boolean): void {
         const found = this.envs.find((e) => areSameEnv(e, env));
         if (hasLatestInfo) {
+            traceVerbose(`Adding env to cache ${env.id}`);
             this.validatedEnvs.add(env.id!);
             this.flush(env).ignoreErrors(); // If we have latest info, flush it so it can be saved.
         }
@@ -172,13 +173,16 @@ export class PythonEnvInfoCache extends PythonEnvsWatcher<PythonEnvCollectionCha
         const env = this.envs.find((e) => arePathsSame(e.location, path)) ?? this.envs.find((e) => areSameEnv(e, path));
         if (env) {
             if (this.validatedEnvs.has(env.id!)) {
+                traceVerbose(`Found cached env for ${path}`);
                 return env;
             }
             if (await validateInfo(env)) {
+                traceVerbose(`Needed to validate ${path} with latest info`);
                 this.validatedEnvs.add(env.id!);
                 return env;
             }
         }
+        traceVerbose(`No cached env found for ${path}`);
         return undefined;
     }
 
diff --git a/src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts b/src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts
@@ -88,6 +88,7 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
         // only use cache if it has complete info on an environment.
         const cachedEnv = await this.cache.getLatestInfo(path);
         if (cachedEnv) {
+            traceVerbose(`Resolved ${path} from cache: ${JSON.stringify(cachedEnv)}`);
             return cachedEnv;
         }
         const resolved = await this.locator.resolveEnv(path).catch((ex) => {

Original file line number	Diff line number	Diff line change
`@@ -274,6 +274,9 @@ export function buildProposedApi(`
`274`	`274`
`275`	`275`	`async function resolveEnvironment(path: string, discoveryApi: IDiscoveryAPI): Promise<ResolvedEnvironment \| undefined> {`
`276`	`276`	`const env = await discoveryApi.resolveEnv(path);`
	`277`	`+ if (env?.version.major === -1 \|\| env?.version.minor === -1 \|\| env?.version.micro === -1) {`
	`278`	+ traceError(`Invalid version for ${path}: ${JSON.stringify(env)}`);
	`279`	`+ }`
`277`	`280`	`if (!env) {`
`278`	`281`	`return undefined;`
`279`	`282`	`}`
Original file line number	Diff line number	Diff line change
`@@ -88,6 +88,7 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection`
`88`	`88`	`// only use cache if it has complete info on an environment.`
`89`	`89`	`const cachedEnv = await this.cache.getLatestInfo(path);`
`90`	`90`	`if (cachedEnv) {`
	`91`	+ traceVerbose(`Resolved ${path} from cache: ${JSON.stringify(cachedEnv)}`);
`91`	`92`	`return cachedEnv;`
`92`	`93`	`}`
`93`	`94`	`const resolved = await this.locator.resolveEnv(path).catch((ex) => {`