feat: add telemetry for PET initialization duration and improve timeout handling (#1390)

30s timeout → retry → 30s timeout allows for faster feedback and quicker success

Author: eleanorjboyd

src/common/telemetry/constants.ts

@@ -74,6 +74,14 @@ export enum EventNames {
      * - reason: string ('tool_not_found')
      */
     MANAGER_REGISTRATION_SKIPPED = 'MANAGER_REGISTRATION.SKIPPED',
+    /**
+     * Telemetry event for PET (Python Environment Tools) initialization timing.
+     * Tracks how long it takes to create and start the native Python finder.
+     * Properties:
+     * - result: 'success' | 'error' | 'timeout'
+     * - errorType: string (classified error category, on failure only)
+     */
+    PET_INIT_DURATION = 'PET.INIT_DURATION',
 }
 
 // Map all events to their properties
@@ -302,4 +310,16 @@ export interface IEventNamePropertyMapping {
         managerName: string;
         reason: 'tool_not_found';
     };
+
+    /* __GDPR__
+        "pet.init_duration": {
+            "result": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" },
+            "errorType": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "owner": "eleanorjboyd" },
+            "<duration>": { "classification": "SystemMetaData", "purpose": "FeatureInsight", "isMeasurement": true, "owner": "eleanorjboyd" }
+        }
+    */
+    [EventNames.PET_INIT_DURATION]: {
+        result: 'success' | 'error' | 'timeout';
+        errorType?: string;
+    };
 }

src/extension.ts

@@ -545,7 +545,20 @@ 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
-            const nativeFinder: NativePythonFinder = await createNativePythonFinder(outputChannel, api, context);
+            const petStart = new StopWatch();
+            let nativeFinder: NativePythonFinder;
+            try {
+                nativeFinder = await createNativePythonFinder(outputChannel, api, context);
+                sendTelemetryEvent(EventNames.PET_INIT_DURATION, petStart.elapsedTime, { result: 'success' });
+            } catch (petError) {
+                sendTelemetryEvent(
+                    EventNames.PET_INIT_DURATION,
+                    petStart.elapsedTime,
+                    { result: 'error', errorType: classifyError(petError) },
+                    petError instanceof Error ? petError : undefined,
+                );
+                throw petError;
+            }
             context.subscriptions.push(nativeFinder);
             const sysMgr = new SysPythonManager(nativeFinder, api, outputChannel);
             sysPythonManager.resolve(sysMgr);

src/managers/common/nativePythonFinder.ts

@@ -17,21 +17,23 @@ import { noop } from './utils';
 
 // Timeout constants for JSON-RPC requests (in milliseconds)
 const CONFIGURE_TIMEOUT_MS = 30_000; // 30 seconds for configuration
-const REFRESH_TIMEOUT_MS = 120_000; // 2 minutes for full refresh
+const MAX_CONFIGURE_TIMEOUT_MS = 60_000; // Max configure timeout after retries (60s)
+const REFRESH_TIMEOUT_MS = 30_000; // 30 seconds for full refresh (with 1 retry = 60s max)
 const RESOLVE_TIMEOUT_MS = 30_000; // 30 seconds for single resolve
 
 // Restart/recovery constants
 const MAX_RESTART_ATTEMPTS = 3;
 const RESTART_BACKOFF_BASE_MS = 1_000; // 1 second base, exponential: 1s, 2s, 4s
 const MAX_CONFIGURE_TIMEOUTS_BEFORE_KILL = 2; // Kill on the 2nd consecutive timeout
+const MAX_REFRESH_RETRIES = 1; // Retry refresh once after timeout
 
 /**
  * Computes the configure timeout with exponential backoff.
  * @param retryCount Number of consecutive configure timeouts so far
- * @returns Timeout in milliseconds: 30s, 60s, 120s, ... capped at REFRESH_TIMEOUT_MS
+ * @returns Timeout in milliseconds: 30s, 60s, capped at MAX_CONFIGURE_TIMEOUT_MS (60s)
  */
 export function getConfigureTimeoutMs(retryCount: number): number {
-    return Math.min(CONFIGURE_TIMEOUT_MS * Math.pow(2, retryCount), REFRESH_TIMEOUT_MS);
+    return Math.min(CONFIGURE_TIMEOUT_MS * Math.pow(2, retryCount), MAX_CONFIGURE_TIMEOUT_MS);
 }
 
 /**
@@ -563,6 +565,41 @@ class NativePythonFinderImpl implements NativePythonFinder {
     }
 
     private async doRefresh(options?: NativePythonEnvironmentKind | Uri[]): Promise<NativeInfo[]> {
+        let lastError: unknown;
+
+        for (let attempt = 0; attempt <= MAX_REFRESH_RETRIES; attempt++) {
+            try {
+                return await this.doRefreshAttempt(options, attempt);
+            } catch (ex) {
+                lastError = ex;
+
+                // Only retry on timeout errors
+                if (ex instanceof RpcTimeoutError && ex.method !== 'configure') {
+                    if (attempt < MAX_REFRESH_RETRIES) {
+                        this.outputChannel.warn(
+                            `[pet] Refresh timed out (attempt ${attempt + 1}/${MAX_REFRESH_RETRIES + 1}), restarting and retrying...`,
+                        );
+                        // Kill and restart for retry
+                        this.killProcess();
+                        this.processExited = true;
+                        continue;
+                    }
+                    // Final attempt failed
+                    this.outputChannel.error(`[pet] Refresh failed after ${MAX_REFRESH_RETRIES + 1} attempts`);
+                }
+                // Non-timeout errors or final timeout - rethrow
+                throw ex;
+            }
+        }
+
+        // Should not reach here, but TypeScript needs this
+        throw lastError;
+    }
+
+    private async doRefreshAttempt(
+        options: NativePythonEnvironmentKind | Uri[] | undefined,
+        attempt: number,
+    ): Promise<NativeInfo[]> {
         await this.ensureProcessRunning();
         const disposables: Disposable[] = [];
         const unresolved: Promise<void>[] = [];
@@ -610,6 +647,9 @@ class NativePythonFinderImpl implements NativePythonFinder {
 
             // Reset restart attempts on successful refresh
             this.restartAttempts = 0;
+            if (attempt > 0) {
+                this.outputChannel.info(`[pet] Refresh succeeded on retry attempt ${attempt + 1}`);
+            }
         } catch (ex) {
             // On refresh timeout (not configure — configure handles its own timeout),
             // kill the hung process so next request triggers restart

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

@@ -37,14 +37,12 @@ suite('getConfigureTimeoutMs', () => {
         assert.strictEqual(getConfigureTimeoutMs(1), 60_000);
     });
 
-    test('doubles again on second retry (120s)', () => {
-        assert.strictEqual(getConfigureTimeoutMs(2), 120_000);
-    });
-
-    test('caps at REFRESH_TIMEOUT_MS (120s) for higher retries', () => {
-        // 30_000 * 2^3 = 240_000, but capped at 120_000
-        assert.strictEqual(getConfigureTimeoutMs(3), 120_000);
-        assert.strictEqual(getConfigureTimeoutMs(10), 120_000);
+    test('caps at MAX_CONFIGURE_TIMEOUT_MS (60s) for higher retries', () => {
+        // 30_000 * 2^2 = 120_000, but capped at 60_000
+        assert.strictEqual(getConfigureTimeoutMs(2), 60_000);
+        // 30_000 * 2^3 = 240_000, but capped at 60_000
+        assert.strictEqual(getConfigureTimeoutMs(3), 60_000);
+        assert.strictEqual(getConfigureTimeoutMs(10), 60_000);
     });
 });