feat: enhance telemetry with error classification and duration tracking for environment manager registration (#1292)

eleanorjboyd · web-flow · commit 8b9890a311a5 · 2026-03-03T07:14:10.000-08:00
help identify what could be causing discovery errors and which managers
may be taking a while to load
diff --git a/src/common/telemetry/constants.ts b/src/common/telemetry/constants.ts
@@ -69,7 +69,8 @@ export interface IEventNamePropertyMapping {
 
     /* __GDPR__
         "environment_manager.registered": {
-            "managerId" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" }
+            "managerId" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" },
+            "<duration>": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "eleanorjboyd" }
         }
     */
     [EventNames.ENVIRONMENT_MANAGER_REGISTERED]: {
diff --git a/src/common/telemetry/errorClassifier.ts b/src/common/telemetry/errorClassifier.ts
@@ -0,0 +1,53 @@
+import { CancellationError } from 'vscode';
+import { RpcTimeoutError } from '../../managers/common/nativePythonFinder';
+
+export type DiscoveryErrorType =
+    | 'spawn_timeout'
+    | 'spawn_enoent'
+    | 'permission_denied'
+    | 'canceled'
+    | 'parse_error'
+    | 'unknown';
+
+/**
+ * Classifies an error into a telemetry-safe category for the `errorType` property.
+ * Does NOT include raw error messages — only the category.
+ */
+export function classifyError(ex: unknown): DiscoveryErrorType {
+    if (ex instanceof CancellationError) {
+        return 'canceled';
+    }
+
+    if (ex instanceof RpcTimeoutError) {
+        return 'spawn_timeout';
+    }
+
+    if (!(ex instanceof Error)) {
+        return 'unknown';
+    }
+
+    // Check error code for spawn failures (Node.js sets `code` on spawn errors)
+    const code = (ex as NodeJS.ErrnoException).code;
+    if (code === 'ENOENT') {
+        return 'spawn_enoent';
+    }
+    if (code === 'EACCES' || code === 'EPERM') {
+        return 'permission_denied';
+    }
+
+    // Check message patterns
+    const msg = ex.message.toLowerCase();
+    if (msg.includes('timed out') || msg.includes('timeout')) {
+        return 'spawn_timeout';
+    }
+    if (msg.includes('parse') || msg.includes('unexpected token') || msg.includes('json')) {
+        return 'parse_error';
+    }
+
+    // Check error name for cancellation variants
+    if (ex.name === 'CancellationError' || ex.name === 'AbortError') {
+        return 'canceled';
+    }
+
+    return 'unknown';
+}
diff --git a/src/extension.ts b/src/extension.ts
@@ -558,15 +558,25 @@ export async function activate(context: ExtensionContext): Promise<PythonEnviron
             );
 
             sendTelemetryEvent(EventNames.EXTENSION_MANAGER_REGISTRATION_DURATION, start.elapsedTime);
-            await terminalManager.initialize(api);
-            sendManagerSelectionTelemetry(projectManager);
-            await sendProjectStructureTelemetry(projectManager, envManagers);
-            await sendEnvironmentToolUsageTelemetry(projectManager, envManagers);
-
-            // Log discovery summary to help users troubleshoot environment detection issues
-            await logDiscoverySummary(envManagers);
+            try {
+                await terminalManager.initialize(api);
+                sendManagerSelectionTelemetry(projectManager);
+                await sendProjectStructureTelemetry(projectManager, envManagers);
+                await sendEnvironmentToolUsageTelemetry(projectManager, envManagers);
+
+                // Log discovery summary to help users troubleshoot environment detection issues
+                await logDiscoverySummary(envManagers);
+            } catch (postInitError) {
+                traceError('Post-initialization tasks failed:', postInitError);
+            }
         } catch (error) {
             traceError('Failed to initialize environment managers:', error);
+            sendTelemetryEvent(
+                EventNames.EXTENSION_MANAGER_REGISTRATION_DURATION,
+                start.elapsedTime,
+                undefined,
+                error instanceof Error ? error : undefined,
+            );
             // Show a user-friendly error message
             window.showErrorMessage(
                 l10n.t(
diff --git a/src/features/envManagers.ts b/src/features/envManagers.ts
@@ -16,6 +16,7 @@ import {
     PackageManagerAlreadyRegisteredError,
 } from '../common/errors/AlreadyRegisteredError';
 import { traceError, traceVerbose } from '../common/logging';
+import { StopWatch } from '../common/stopWatch';
 import { EventNames } from '../common/telemetry/constants';
 import { sendTelemetryEvent } from '../common/telemetry/sender';
 import { getCallingExtension } from '../common/utils/frameUtils';
@@ -71,6 +72,7 @@ export class PythonEnvironmentManagers implements EnvironmentManagers {
     constructor(private readonly pm: PythonProjectManager) {}
 
     public registerEnvironmentManager(manager: EnvironmentManager): Disposable {
+        const registrationStopWatch = new StopWatch();
         const managerId = generateId(manager.name);
         if (this._environmentManagers.has(managerId)) {
             const ex = new EnvironmentManagerAlreadyRegisteredError(
@@ -105,7 +107,7 @@ export class PythonEnvironmentManagers implements EnvironmentManagers {
         this._onDidChangeEnvironmentManager.fire({ kind: 'registered', manager: mgr });
 
         if (!managerId.toLowerCase().startsWith('undefined_publisher.')) {
-            sendTelemetryEvent(EventNames.ENVIRONMENT_MANAGER_REGISTERED, undefined, {
+            sendTelemetryEvent(EventNames.ENVIRONMENT_MANAGER_REGISTERED, registrationStopWatch.elapsedTime, {
                 managerId,
             });
         }
@@ -327,6 +329,13 @@ 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))}`,
+            );
         }
 
         const key = project ? project.uri.toString() : 'global';
@@ -503,6 +512,10 @@ export class PythonEnvironmentManagers implements EnvironmentManagers {
     async getEnvironment(scope: GetEnvironmentScope): Promise<PythonEnvironment | undefined> {
         const manager = this.getEnvironmentManager(scope);
         if (!manager) {
+            traceVerbose(
+                `[getEnvironment] No manager found for scope=${scope instanceof Uri ? scope.fsPath : scope}, ` +
+                    `settingsManagerId=${getDefaultEnvManagerSetting(this.pm, scope instanceof Uri ? scope : undefined)}`,
+            );
             return undefined;
         }
 
diff --git a/src/internal.api.ts b/src/internal.api.ts
@@ -33,6 +33,7 @@ import { traceWarn } from './common/logging';
 import { StopWatch } from './common/stopWatch';
 import { EventNames } from './common/telemetry/constants';
 import { sendTelemetryEvent } from './common/telemetry/sender';
+import { classifyError } from './common/telemetry/errorClassifier';
 
 export type EnvironmentManagerScope = undefined | string | Uri | PythonEnvironment;
 export type PackageManagerScope = undefined | string | Uri | PythonEnvironment | Package;
@@ -226,14 +227,13 @@ export class InternalEnvironmentManager implements EnvironmentManager {
             }
         } catch (ex) {
             const duration = sw.elapsedTime;
-            const isTimeout = ex instanceof Error && ex.message.includes('timed out');
-            const errorType = ex instanceof Error ? ex.name : 'unknown';
+            const errorType = classifyError(ex);
             sendTelemetryEvent(
                 EventNames.ENVIRONMENT_DISCOVERY,
                 duration,
                 {
                     managerId: this.id,
-                    result: isTimeout ? 'timeout' : 'error',
+                    result: errorType === 'canceled' || errorType === 'spawn_timeout' ? 'timeout' : 'error',
                     errorType,
                 },
                 ex instanceof Error ? ex : undefined,
diff --git a/src/managers/builtin/sysPythonManager.ts b/src/managers/builtin/sysPythonManager.ts
@@ -166,13 +166,20 @@ export class SysPythonManager implements EnvironmentManager {
             const pw = this.api.getPythonProject(scope);
             if (!pw) {
                 this.log.warn(
-                    `Unable to set environment for ${scope.fsPath}: Not a python project, folder or PEP723 script.`,
-                    this.api.getPythonProjects().map((p) => p.uri.fsPath),
+                    `[SYS_SET] Unable to set environment for ${scope.fsPath}: Not a python project. ` +
+                        `Known projects: [${this.api
+                            .getPythonProjects()
+                            .map((p) => p.uri.fsPath)
+                            .join(', ')}]`,
                 );
                 return;
             }
 
             const normalizedPwPath = normalizePath(pw.uri.fsPath);
+            this.log.info(
+                `[SYS_SET] scope=${scope.fsPath}, project=${pw.uri.fsPath}, ` +
+                    `normalizedKey=${normalizedPwPath}, env=${environment?.envId?.id ?? 'undefined'}`,
+            );
             if (environment) {
                 this.fsPathToEnv.set(normalizedPwPath, environment);
             } else {
@@ -297,16 +304,28 @@ export class SysPythonManager implements EnvironmentManager {
     }
 
     private fromEnvMap(uri: Uri): PythonEnvironment | undefined {
+        const normalizedUri = normalizePath(uri.fsPath);
         // Find environment directly using the URI mapping
-        const env = this.fsPathToEnv.get(normalizePath(uri.fsPath));
+        const env = this.fsPathToEnv.get(normalizedUri);
         if (env) {
             return env;
         }
 
         // Find environment using the Python project for the Uri
         const project = this.api.getPythonProject(uri);
-        if (project) {
-            return this.fsPathToEnv.get(normalizePath(project.uri.fsPath));
+        const projectKey = project ? normalizePath(project.uri.fsPath) : undefined;
+        const projectEnv = projectKey ? this.fsPathToEnv.get(projectKey) : undefined;
+
+        this.log.info(
+            `[SYS_GET] uri=${uri.fsPath}, normalizedKey=${normalizedUri}, ` +
+                `project=${project?.uri?.fsPath ?? 'none'}, projectKey=${projectKey ?? 'none'}, ` +
+                `mapKeys=[${Array.from(this.fsPathToEnv.keys()).join(', ')}], ` +
+                `directHit=${!!env}, projectHit=${!!projectEnv}, ` +
+                `fallbackToGlobal=${!projectEnv}, globalEnv=${this.globalEnv?.envId?.id ?? 'none'}`,
+        );
+
+        if (projectEnv) {
+            return projectEnv;
         }
 
         return this.globalEnv;
diff --git a/src/test/common/telemetry/errorClassifier.unit.test.ts b/src/test/common/telemetry/errorClassifier.unit.test.ts
@@ -0,0 +1,68 @@
+import assert from 'node:assert';
+import { CancellationError } from 'vscode';
+import { classifyError } from '../../../common/telemetry/errorClassifier';
+import { RpcTimeoutError } from '../../../managers/common/nativePythonFinder';
+
+suite('Error Classifier', () => {
+    suite('classifyError', () => {
+        test('should classify CancellationError as canceled', () => {
+            assert.strictEqual(classifyError(new CancellationError()), 'canceled');
+        });
+
+        test('should classify RpcTimeoutError as spawn_timeout', () => {
+            assert.strictEqual(classifyError(new RpcTimeoutError('resolve', 30000)), 'spawn_timeout');
+        });
+
+        test('should classify non-Error values as unknown', () => {
+            assert.strictEqual(classifyError('string error'), 'unknown');
+            assert.strictEqual(classifyError(42), 'unknown');
+            assert.strictEqual(classifyError(null), 'unknown');
+            assert.strictEqual(classifyError(undefined), 'unknown');
+        });
+
+        test('should classify ENOENT errors as spawn_enoent', () => {
+            const err = new Error('spawn python ENOENT') as NodeJS.ErrnoException;
+            err.code = 'ENOENT';
+            assert.strictEqual(classifyError(err), 'spawn_enoent');
+        });
+
+        test('should classify EACCES errors as permission_denied', () => {
+            const err = new Error('permission denied') as NodeJS.ErrnoException;
+            err.code = 'EACCES';
+            assert.strictEqual(classifyError(err), 'permission_denied');
+        });
+
+        test('should classify EPERM errors as permission_denied', () => {
+            const err = new Error('operation not permitted') as NodeJS.ErrnoException;
+            err.code = 'EPERM';
+            assert.strictEqual(classifyError(err), 'permission_denied');
+        });
+
+        test('should classify timeout messages as spawn_timeout', () => {
+            assert.strictEqual(classifyError(new Error('Request timed out')), 'spawn_timeout');
+            assert.strictEqual(classifyError(new Error('Connection timeout')), 'spawn_timeout');
+        });
+
+        test('should classify parse errors as parse_error', () => {
+            assert.strictEqual(classifyError(new Error('Failed to parse output')), 'parse_error');
+            assert.strictEqual(classifyError(new Error('Unexpected token < in JSON')), 'parse_error');
+            assert.strictEqual(classifyError(new Error('Invalid JSON response')), 'parse_error');
+        });
+
+        test('should classify AbortError name as canceled', () => {
+            const err = new Error('aborted');
+            err.name = 'AbortError';
+            assert.strictEqual(classifyError(err), 'canceled');
+        });
+
+        test('should classify error with CancellationError name as canceled', () => {
+            const err = new Error('cancelled');
+            err.name = 'CancellationError';
+            assert.strictEqual(classifyError(err), 'canceled');
+        });
+
+        test('should classify unrecognized errors as unknown', () => {
+            assert.strictEqual(classifyError(new Error('something went wrong')), 'unknown');
+        });
+    });
+});
diff --git a/src/test/integration/pythonProjects.integration.test.ts b/src/test/integration/pythonProjects.integration.test.ts
@@ -185,6 +185,7 @@ suite('Integration: Python Projects', function () {
         // Track what getEnvironment returns during polling for diagnostics
         let pollCount = 0;
         let lastRetrievedId: string | undefined;
+        let lastRetrievedManagerId: string | undefined;
 
         // Wait for the environment to be retrievable with the correct ID
         // This handles async persistence across platforms
@@ -194,16 +195,18 @@ suite('Integration: Python Projects', function () {
                 const retrieved = await api.getEnvironment(project.uri);
                 pollCount++;
                 const retrievedId = retrieved?.envId?.id;
+                lastRetrievedManagerId = retrieved?.envId?.managerId;
                 if (retrievedId !== lastRetrievedId) {
                     console.log(
-                        `[TEST DEBUG] Poll #${pollCount}: getEnvironment returned envId=${retrievedId ?? 'undefined'}`,
+                        `[TEST DEBUG] Poll #${pollCount}: getEnvironment returned envId=${retrievedId ?? 'undefined'}, managerId=${lastRetrievedManagerId ?? 'undefined'}`,
                     );
                     lastRetrievedId = retrievedId;
                 }
                 return retrieved !== undefined && retrieved.envId.id === env.envId.id;
             },
             15_000,
-            `Environment was not set correctly. Expected envId: ${env.envId.id}, last retrieved: ${lastRetrievedId}`,
+            () =>
+                `Environment was not set correctly. Expected envId: ${env.envId.id} (manager: ${env.envId.managerId}), last retrieved: ${lastRetrievedId ?? 'undefined'} (manager: ${lastRetrievedManagerId ?? 'undefined'}) after ${pollCount} polls`,
         );
 
         // Final verification
@@ -285,13 +288,16 @@ suite('Integration: Python Projects', function () {
 
         // Wait for it to be set
         // Use 15s timeout - CI runners can be slow with settings persistence
+        let clearTestLastId: string | undefined;
         await waitForCondition(
             async () => {
                 const retrieved = await api.getEnvironment(project.uri);
+                clearTestLastId = retrieved?.envId?.id;
                 return retrieved !== undefined && retrieved.envId.id === env.envId.id;
             },
             15_000,
-            'Environment was not set before clearing',
+            () =>
+                `Environment was not set before clearing. Expected: ${env.envId.id} (manager: ${env.envId.managerId}), got: ${clearTestLastId ?? 'undefined'}`,
         );
 
         // Verify it was set
@@ -344,13 +350,18 @@ suite('Integration: Python Projects', function () {
 
         // Wait for it to be set
         // Use 15s timeout - CI runners can be slow with settings persistence
+        let fileTestLastId: string | undefined;
+        let fileTestLastManagerId: string | undefined;
         await waitForCondition(
             async () => {
                 const retrieved = await api.getEnvironment(project.uri);
+                fileTestLastId = retrieved?.envId?.id;
+                fileTestLastManagerId = retrieved?.envId?.managerId;
                 return retrieved !== undefined && retrieved.envId.id === env.envId.id;
             },
             15_000,
-            'Environment was not set for project',
+            () =>
+                `Environment was not set for project. Expected: ${env.envId.id} (manager: ${env.envId.managerId}), got: ${fileTestLastId ?? 'undefined'} (manager: ${fileTestLastManagerId ?? 'undefined'})`,
         );
 
         // Create a hypothetical file path inside the project
diff --git a/src/test/testUtils.ts b/src/test/testUtils.ts
@@ -48,7 +48,7 @@ export function sleep(ms: number): Promise<void> {
 export async function waitForCondition(
     condition: () => boolean | Promise<boolean>,
     timeoutMs: number = 10_000,
-    errorMessage: string = 'Condition not met within timeout',
+    errorMessage: string | (() => string) = 'Condition not met within timeout',
     pollIntervalMs: number = 100,
 ): Promise<void> {
     return new Promise<void>((resolve, reject) => {
@@ -66,7 +66,8 @@ export async function waitForCondition(
             }
 
             if (Date.now() - startTime >= timeoutMs) {
-                reject(new Error(`${errorMessage} (waited ${timeoutMs}ms)`));
+                const msg = typeof errorMessage === 'function' ? errorMessage() : errorMessage;
+                reject(new Error(`${msg} (waited ${timeoutMs}ms)`));
                 return;
             }
 

Original file line number	Diff line number	Diff line change
`@@ -69,7 +69,8 @@ export interface IEventNamePropertyMapping {`
`69`	`69`
`70`	`70`	`/* __GDPR__`
`71`	`71`	`"environment_manager.registered": {`
`72`		`- "managerId" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" }`
	`72`	`+ "managerId" : { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" },`
	`73`	`+ "<duration>": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "eleanorjboyd" }`
`73`	`74`	`}`
`74`	`75`	`*/`
`75`	`76`	`[EventNames.ENVIRONMENT_MANAGER_REGISTERED]: {`