Add more logging and only retry once if fetching interpreter informat…

…ion fails (#20180)

For #20147

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) => {

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;
     }

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;
     }
 

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;
     }
 

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) => {