feat: comprehensive logging overhaul for better diagnostics

- Add extension initialization progress logging (native finder, manager
  registration, env selection, setup complete with timings)
- Add discovery START/END logging in InternalEnvironmentManager.refresh()
- Fix wrong log levels: traceError→traceWarn for non-error conditions
  (uvPythonInstaller, nativePythonFinder), traceInfo→traceVerbose for
  clipboard operations
- Add distinguishing context to terminal env var injector catch handlers
- Add environment creation logging in envCommands
- Promote setEnvironment logging to traceInfo and log unconditionally
- Add pyenv discovery source logging for all lookup paths
- Enhance discovery summary to include managers with 0 environments
- Update tests to match traceError→traceWarn change

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Co-authored-by: eleanorjboyd <26030610+eleanorjboyd@users.noreply.github.com>

Author: Copilot

src/common/telemetry/helpers.ts

@@ -169,11 +169,9 @@ export async function logDiscoverySummary(envManagers: EnvironmentManagers): Pro
         try {
             const envs = await manager.getEnvironments('all');
             totalEnvCount += envs.length;
-            if (envs.length > 0) {
-                managerSummaries.push(`${manager.displayName}: ${envs.length}`);
-            }
+            managerSummaries.push(`${manager.displayName}: ${envs.length}`);
         } catch {
-            // Discovery errors are already logged by InternalEnvironmentManager.refresh()
+            managerSummaries.push(`${manager.displayName}: error`);
         }
     }
 

src/extension.ts

@@ -573,10 +573,12 @@ export async function activate(context: ExtensionContext): Promise<PythonEnviron
         context.subscriptions.push({ dispose: clearHangWatchdog });
         try {
             // This is the finder that is used by all the built in environment managers
+            traceInfo('Initializing Python environment tool (native finder)...');
             const petStart = new StopWatch();
             let nativeFinder: NativePythonFinder;
             try {
                 nativeFinder = await createNativePythonFinder(outputChannel, api, context);
+                traceInfo(`Python environment tool initialized (${(petStart.elapsedTime / 1000).toFixed(1)}s)`);
                 sendTelemetryEvent(EventNames.PET_INIT_DURATION, petStart.elapsedTime, { result: 'success' });
             } catch (petError) {
                 sendTelemetryEvent(
@@ -592,6 +594,7 @@ export async function activate(context: ExtensionContext): Promise<PythonEnviron
             sysPythonManager.resolve(sysMgr);
             // Each manager registers independently — one failure must not block the others.
             failureStage = 'managerRegistration';
+            traceInfo('Registering environment managers...');
             await Promise.all([
                 safeRegister(
                     'system',
@@ -609,9 +612,12 @@ export async function activate(context: ExtensionContext): Promise<PythonEnviron
                 ),
                 safeRegister('shellStartupVars', shellStartupVarsMgr.initialize()),
             ]);
+            traceInfo('Environment managers registered.');
 
             failureStage = 'envSelection';
+            traceInfo('Applying initial environment selection...');
             await applyInitialEnvironmentSelection(envManagers, projectManager, nativeFinder, api, start.elapsedTime);
+            traceInfo('Initial environment selection applied.');
 
             // Register manager-agnostic terminal watcher for package-modifying commands
             failureStage = 'terminalWatcher';
@@ -627,6 +633,7 @@ export async function activate(context: ExtensionContext): Promise<PythonEnviron
                 result: 'success',
             });
             clearHangWatchdog();
+            traceInfo(`Extension setup complete (${(start.elapsedTime / 1000).toFixed(1)}s total)`);
             try {
                 await terminalManager.initialize(api);
                 sendManagerSelectionTelemetry(projectManager);

src/features/envCommands.ts

@@ -153,6 +153,7 @@ export async function createEnvironmentCommand(
         if (projects.length === 0) {
             const env = await manager.create('global', undefined);
             if (env) {
+                traceInfo(`Environment created: ${env.displayName}`);
                 await em.setEnvironments('global', env);
             }
             return env;
@@ -162,6 +163,7 @@ export async function createEnvironmentCommand(
                 const scope = selected.length === 0 ? 'global' : selected.map((p) => p.uri);
                 const env = await manager.create(scope, undefined);
                 if (env) {
+                    traceInfo(`Environment created: ${env.displayName}`);
                     await em.setEnvironmentsIfUnset(scope, env);
                 }
                 return env;
@@ -216,6 +218,9 @@ export async function createAnyEnvironmentCommand(
         const manager = em.managers.find((m) => m.id === managerId);
         if (manager) {
             const env = await manager.create('global', { ...options });
+            if (env) {
+                traceInfo(`Environment created: ${env.displayName}`);
+            }
             if (select && env) {
                 await manager.set(undefined, env);
             }
@@ -270,6 +275,9 @@ export async function createAnyEnvironmentCommand(
                     selected.map((p) => p.uri),
                     { ...options, quickCreate },
                 );
+                if (env) {
+                    traceInfo(`Environment created: ${env.displayName}`);
+                }
                 if (select && env) {
                     await em.setEnvironments(
                         selected.map((p) => p.uri),
@@ -739,12 +747,12 @@ export async function copyPathToClipboard(item: unknown): Promise<void> {
     if (item instanceof ProjectItem) {
         const projectPath = item.project.uri.fsPath;
         await clipboardWriteText(projectPath);
-        traceInfo(`Copied project path to clipboard: ${projectPath}`);
+        traceVerbose(`Copied project path to clipboard: ${projectPath}`);
     } else if (item instanceof ProjectEnvironment || item instanceof PythonEnvTreeItem) {
         const run = item.environment.execInfo.run;
         const envPath = run.executable;
         await clipboardWriteText(envPath);
-        traceInfo(`Copied environment path to clipboard: ${envPath}`);
+        traceVerbose(`Copied environment path to clipboard: ${envPath}`);
     } else {
         traceVerbose(`Invalid context for copy path to clipboard: ${item}`);
     }

src/features/envManagers.ts

@@ -15,7 +15,7 @@ import {
     EnvironmentManagerAlreadyRegisteredError,
     PackageManagerAlreadyRegisteredError,
 } from '../common/errors/AlreadyRegisteredError';
-import { traceError, traceVerbose } from '../common/logging';
+import { traceError, traceInfo, traceVerbose } from '../common/logging';
 import { StopWatch } from '../common/stopWatch';
 import { EventNames } from '../common/telemetry/constants';
 import { sendTelemetryEvent } from '../common/telemetry/sender';
@@ -315,6 +315,10 @@ export class PythonEnvironmentManagers implements EnvironmentManagers {
             return;
         }
         await manager.set(scope, environment);
+        traceInfo(
+            `[setEnvironment] env=${environment?.displayName ?? 'none'} (${environment?.envId?.id ?? 'undefined'}), ` +
+                `scope=${scope instanceof Uri ? scope.fsPath : scope ?? 'global'}, manager=${manager.id}`,
+        );
 
         const project = scope ? this.pm.get(scope) : undefined;
         // Only persist to settings when explicitly requested
@@ -330,11 +334,8 @@ export class PythonEnvironmentManagers implements EnvironmentManagers {
                 ]);
             }
             traceVerbose(
-                `[setEnvironment] scope=${scope instanceof Uri ? scope.fsPath : scope}, ` +
-                    `env=${environment?.envId?.id ?? 'undefined'}, manager=${manager.id}, ` +
-                    `project=${project?.uri?.toString() ?? 'none'}, ` +
-                    `packageManager=${this.getPackageManager(environment)?.id ?? 'UNDEFINED'}, ` +
-                    `settingsPersisted=${!!(project && this.getPackageManager(environment))}`,
+                `[setEnvironment] Settings persisted: project=${project?.uri?.toString() ?? 'none'}, ` +
+                    `packageManager=${this.getPackageManager(environment)?.id ?? 'UNDEFINED'}`,
             );
         }
 

src/features/terminal/terminalEnvVarInjector.ts

@@ -48,7 +48,7 @@ export class TerminalEnvVarInjector implements Disposable {
                 if (!args.uri) {
                     // No specific URI, reload all workspaces
                     this.updateEnvironmentVariables().catch((error) => {
-                        traceError('Failed to update environment variables:', error);
+                        traceError('Failed to update environment variables (global reload):', error);
                     });
                     return;
                 }
@@ -57,7 +57,7 @@ export class TerminalEnvVarInjector implements Disposable {
                 if (!affectedWorkspace) {
                     // No workspace folder found for this URI, reloading all workspaces
                     this.updateEnvironmentVariables().catch((error) => {
-                        traceError('Failed to update environment variables:', error);
+                        traceError('Failed to update environment variables (no workspace folder for URI):', error);
                     });
                     return;
                 }
@@ -79,7 +79,7 @@ export class TerminalEnvVarInjector implements Disposable {
                     this.clearWorkspaceVariables(affectedWorkspace);
                 } else {
                     this.updateEnvironmentVariables(affectedWorkspace).catch((error) => {
-                        traceError('Failed to update environment variables:', error);
+                        traceError(`Failed to update environment variables for workspace: ${affectedWorkspace?.name}`, error);
                     });
                 }
             }),
@@ -93,7 +93,7 @@ export class TerminalEnvVarInjector implements Disposable {
                         'TerminalEnvVarInjector: python.envFile or python.terminal.useEnvFile setting changed, updating environment variables',
                     );
                     this.updateEnvironmentVariables().catch((error) => {
-                        traceError('Failed to update environment variables:', error);
+                        traceError('Failed to update environment variables (settings change):', error);
                     });
                 }
             }),

src/internal.api.ts

@@ -29,7 +29,7 @@ import {
 } from './api';
 import { ISSUES_URL } from './common/constants';
 import { CreateEnvironmentNotSupported, RemoveEnvironmentNotSupported } from './common/errors/NotSupportedError';
-import { traceWarn } from './common/logging';
+import { traceInfo, traceWarn } from './common/logging';
 import { StopWatch } from './common/stopWatch';
 import { EventNames } from './common/telemetry/constants';
 import { sendTelemetryEvent } from './common/telemetry/sender';
@@ -206,12 +206,14 @@ export class InternalEnvironmentManager implements EnvironmentManager {
     }
 
     async refresh(options: RefreshEnvironmentsScope): Promise<void> {
+        traceInfo(`[${this.displayName}] Discovering environments...`);
         const sw = new StopWatch();
         const SLOW_DISCOVERY_THRESHOLD_MS = 15000;
         try {
             await this.manager.refresh(options);
             const envs = await this.manager.getEnvironments('all').catch(() => []);
             const duration = sw.elapsedTime;
+            traceInfo(`[${this.displayName}] Discovery complete: ${envs.length} environments found (${(duration / 1000).toFixed(1)}s)`);
             sendTelemetryEvent(EventNames.ENVIRONMENT_DISCOVERY, duration, {
                 managerId: this.id,
                 result: 'success',

src/managers/builtin/uvPythonInstaller.ts

@@ -10,7 +10,7 @@ import {
 } from 'vscode';
 import { spawnProcess } from '../../common/childProcess.apis';
 import { Common, UvInstallStrings } from '../../common/localize';
-import { traceError, traceInfo, traceLog } from '../../common/logging';
+import { traceError, traceInfo, traceLog, traceWarn } from '../../common/logging';
 import { getGlobalPersistentState } from '../../common/persistentState';
 import { executeTask, onDidEndTaskProcess } from '../../common/tasks.apis';
 import { EventNames } from '../../common/telemetry/constants';
@@ -82,7 +82,7 @@ async function getUvInstallCommand(): Promise<{ executable: string; args: string
     }
 
     // Default to curl and let it fail with a clear error if neither is available
-    traceError('Neither curl nor wget found, attempting curl anyway');
+    traceWarn('Neither curl nor wget found, attempting curl anyway');
     return {
         executable: 'sh',
         args: ['-c', 'curl -LsSf https://astral.sh/uv/install.sh | sh'],

src/managers/common/nativePythonFinder.ts

@@ -1384,7 +1384,7 @@ function getWorkspaceSearchPaths(scope?: Uri): string[] {
 
         if (inspection?.globalValue && !workspaceSearchPathsGlobalWarningShown) {
             workspaceSearchPathsGlobalWarningShown = true;
-            traceError(
+            traceWarn(
                 'python-envs.workspaceSearchPaths is set at the user/global level, but this setting can only be set at the workspace or workspace folder level.',
             );
         }

src/managers/pyenv/pyenvUtils.ts

@@ -138,6 +138,7 @@ export async function getPyenv(): Promise<string | undefined> {
         if (pyenvRoot) {
             const pyenvPath = path.join(pyenvRoot, 'bin', pyenvBin);
             if (await fs.exists(pyenvPath)) {
+                traceInfo(`Using pyenv from PYENV_ROOT: ${pyenvPath}`);
                 return pyenvPath;
             }
         }
@@ -146,22 +147,26 @@ export async function getPyenv(): Promise<string | undefined> {
         if (home) {
             const pyenvPath = path.join(home, '.pyenv', 'bin', pyenvBin);
             if (await fs.exists(pyenvPath)) {
+                traceInfo(`Using pyenv from home directory: ${pyenvPath}`);
                 return pyenvPath;
             }
 
             if (isWindows()) {
                 const pyenvPathWin = path.join(home, '.pyenv', 'pyenv-win', 'bin', pyenvBin);
                 if (await fs.exists(pyenvPathWin)) {
+                    traceInfo(`Using pyenv-win from home directory: ${pyenvPathWin}`);
                     return pyenvPathWin;
                 }
             }
         }
 
         pyenvPath = await findPyenv();
         if (pyenvPath) {
+            traceInfo(`Using pyenv from PATH: ${pyenvPath}`);
             return pyenvPath;
         }
 
+        traceInfo('pyenv not found in PYENV_ROOT, home directory, or PATH');
         return undefined;
     } catch (ex) {
         const err = ex instanceof Error ? ex : new Error(String(ex));
@@ -268,6 +273,7 @@ export async function refreshPyenv(
         }
     });
 
+    traceInfo(`Pyenv discovery complete: ${collection.length} environments found`);
     return sortEnvironments(collection);
 }
 

src/test/managers/common/nativePythonFinder.getAllExtraSearchPaths.unit.test.ts

@@ -331,8 +331,8 @@ suite('getAllExtraSearchPaths Integration Tests', () => {
             assert.deepStrictEqual(result, []);
             // Check that error was logged with key terms - don't be brittle about exact wording
             assert(
-                mockTraceError.calledWith(sinon.match(/workspaceSearchPaths.*global.*level/i)),
-                'Should log error about incorrect setting level',
+                mockTraceWarn.calledWith(sinon.match(/workspaceSearchPaths.*global.*level/i)),
+                'Should log warning about incorrect setting level',
             );
         });
 
@@ -350,16 +350,16 @@ suite('getAllExtraSearchPaths Integration Tests', () => {
             await getAllExtraSearchPaths();
             await getAllExtraSearchPaths();
 
-            // Assert - error should only be logged once, not three times
-            const matchingCalls = mockTraceError
+            // Assert - warning should only be logged once, not three times
+            const matchingCalls = mockTraceWarn
                 .getCalls()
                 .filter((call: sinon.SinonSpyCall) =>
                     /workspaceSearchPaths.*global.*level/i.test(String(call.args[0])),
                 );
             assert.strictEqual(
                 matchingCalls.length,
                 1,
-                `Expected exactly 1 error about workspaceSearchPaths global level, got ${matchingCalls.length}`,
+                `Expected exactly 1 warning about workspaceSearchPaths global level, got ${matchingCalls.length}`,
             );
         });