Add more logging when resolving environments (#20165)

For #20147

src/client/common/process/internal/scripts/index.ts

@@ -43,18 +43,16 @@ export type InterpreterInfoJson = {
 
 export const OUTPUT_MARKER_SCRIPT = path.join(_SCRIPTS_DIR, 'get_output_via_markers.py');
 
-export function interpreterInfo(): [string[], (out: string) => InterpreterInfoJson | undefined] {
+export function interpreterInfo(): [string[], (out: string) => InterpreterInfoJson] {
     const script = path.join(SCRIPTS_DIR, 'interpreterInfo.py');
     const args = [script];
 
-    function parse(out: string): InterpreterInfoJson | undefined {
-        let json: InterpreterInfoJson | undefined;
+    function parse(out: string): InterpreterInfoJson {
         try {
-            json = JSON.parse(out);
+            return JSON.parse(out);
         } catch (ex) {
             throw Error(`python ${args} returned bad JSON (${out}) (${ex})`);
         }
-        return json;
     }
 
     return [args, parse];

src/client/proposedApi.ts

@@ -124,15 +124,15 @@ export function buildProposedApi(
     const disposables = serviceContainer.get<IDisposableRegistry>(IDisposableRegistry);
     const extensions = serviceContainer.get<IExtensions>(IExtensions);
     const envVarsProvider = serviceContainer.get<IEnvironmentVariablesProvider>(IEnvironmentVariablesProvider);
-    function sendApiTelemetry(apiName: string) {
+    function sendApiTelemetry(apiName: string, args?: unknown) {
         extensions
             .determineExtensionFromCallStack()
             .then((info) => {
                 sendTelemetryEvent(EventName.PYTHON_ENVIRONMENTS_API, undefined, {
                     apiName,
                     extensionId: info.extensionId,
                 });
-                traceVerbose(`Extension ${info.extensionId} accessed ${apiName}`);
+                traceVerbose(`Extension ${info.extensionId} accessed ${apiName} with args: ${JSON.stringify(args)}`);
             })
             .ignoreErrors();
     }
@@ -247,7 +247,7 @@ export function buildProposedApi(
                     }
                     path = fullyQualifiedPath;
                 }
-                sendApiTelemetry('resolveEnvironment');
+                sendApiTelemetry('resolveEnvironment', env);
                 return resolveEnvironment(path, discoveryApi);
             },
             get known(): Environment[] {

src/client/pythonEnvironments/base/info/interpreter.ts

@@ -89,13 +89,16 @@ export async function getInterpreterInfo(
     const result = await shellExecute(quoted, { timeout: timeout ?? 15000 });
     if (result.stderr) {
         traceError(
-            `Stderr when executing script with ${argv} stderr: ${result.stderr}, still attempting to parse output`,
+            `Stderr when executing script with >> ${quoted} << stderr: ${result.stderr}, still attempting to parse output`,
         );
     }
-    const json = parse(result.stdout);
-    if (!json) {
+    let json: InterpreterInfoJson;
+    try {
+        json = parse(result.stdout);
+    } catch (ex) {
+        traceError(`Failed to parse interpreter information for >> ${quoted} << with ${ex}`);
         return undefined;
     }
-    traceInfo(`Found interpreter for ${argv}`);
+    traceInfo(`Found interpreter for >> ${quoted} <<: ${JSON.stringify(json)}`);
     return extractInterpreterInfo(python.pythonExecutable, json);
 }

src/client/pythonEnvironments/base/locators/composite/envsCollectionCache.ts

@@ -211,7 +211,7 @@ export class PythonEnvInfoCache extends PythonEnvsWatcher<PythonEnvCollectionCha
 
 async function validateInfo(env: PythonEnvInfo) {
     const { ctime, mtime } = await getFileInfo(env.executable.filename);
-    if (ctime === env.executable.ctime && mtime === env.executable.mtime) {
+    if (ctime !== -1 && mtime !== -1 && ctime === env.executable.ctime && mtime === env.executable.mtime) {
         return true;
     }
     env.executable.ctime = ctime;

src/client/pythonEnvironments/base/locators/composite/envsCollectionService.ts

@@ -5,7 +5,7 @@ import { Event, EventEmitter } from 'vscode';
 import '../../../../common/extensions';
 import { createDeferred, Deferred } from '../../../../common/utils/async';
 import { StopWatch } from '../../../../common/utils/stopWatch';
-import { traceError } from '../../../../logging';
+import { traceError, traceVerbose } from '../../../../logging';
 import { sendTelemetryEvent } from '../../../../telemetry';
 import { EventName } from '../../../../telemetry/constants';
 import { normalizePath } from '../../../common/externalDependencies';
@@ -94,6 +94,7 @@ export class EnvsCollectionService extends PythonEnvsWatcher<PythonEnvCollection
             traceError(`Failed to resolve ${path}`, ex);
             return undefined;
         });
+        traceVerbose(`Resolved ${path} to ${JSON.stringify(resolved)}`);
         if (resolved) {
             this.cache.addEnv(resolved, true);
         }

src/client/pythonEnvironments/base/locators/composite/envsResolver.ts

@@ -52,6 +52,9 @@ export class PythonEnvsResolver implements IResolvingLocator {
         const kind = await identifyEnvironment(path);
         const environment = await resolveBasicEnv({ kind, executablePath, envPath });
         const info = await this.environmentInfoService.getEnvironmentInfo(environment);
+        traceVerbose(
+            `Environment resolver resolved ${path} for ${JSON.stringify(environment)} to ${JSON.stringify(info)}`,
+        );
         if (!info) {
             return undefined;
         }

src/client/pythonEnvironments/common/externalDependencies.ts

@@ -10,6 +10,7 @@ import { IDisposable, IConfigurationService } from '../../common/types';
 import { chain, iterable } from '../../common/utils/async';
 import { getOSType, OSType } from '../../common/utils/platform';
 import { IServiceContainer } from '../../ioc/types';
+import { traceError } from '../../logging';
 
 let internalServiceContainer: IServiceContainer;
 export function initializeExternalDependencies(serviceContainer: IServiceContainer): void {
@@ -116,6 +117,7 @@ export async function getFileInfo(filePath: string): Promise<{ ctime: number; mt
     } catch (ex) {
         // This can fail on some cases, such as, `reparse points` on windows. So, return the
         // time as -1. Which we treat as not set in the extension.
+        traceError(`Failed to get file info for ${filePath}`, ex);
         return { ctime: -1, mtime: -1 };
     }
 }