feat(telemetry): instrument auth recovery and workspace lifecycle

CHANGELOG.md

@@ -13,20 +13,20 @@
   machine only and never sent anywhere. Configure via the new
   `coder.telemetry.level` setting (`local` by default, `off` to disable);
   see `coder.telemetry.local` for tunables.
-- Every `coder.*` command now records a `command.invoked` telemetry event with
-  its duration and outcome, so command latency and failures are captured
-  alongside other local telemetry.
-- Extension activation, remote workspace setup phases (auth retrieval,
-  workspace lookup, workspace and agent readiness, SSH config write), and CLI
-  binary download/verify now emit local telemetry events with their duration
-  and outcome, so startup latency and failures are captured alongside other
-  local telemetry.
+- Local telemetry now records `command.invoked` for each `coder.*` command
+  with duration and outcome.
+- Local telemetry now records extension activation, remote workspace setup
+  phases (auth retrieval, workspace lookup, workspace and agent readiness,
+  SSH config write), and CLI binary download/verify with their durations
+  and outcomes.
 - Local telemetry now records `http.requests` rollups for per-route HTTP
-  health without emitting one event per request.
-- Connection lifecycle now records local telemetry: SSH process
+  health, without emitting one event per request.
+- Local telemetry now records connection lifecycle: SSH process
   discovery/loss/recovery with sampled network info, and reconnecting
-  WebSocket open, drop, reconnect, and state transitions, so connection
-  stability is captured alongside other local telemetry.
+  WebSocket open/drop/reconnect/state transitions.
+- Local telemetry now records authentication refresh and recovery prompts.
+- Local telemetry now records workspace and agent state transitions with
+  observed durations.
 
 ### Fixed
 

src/api/authInterceptor.ts

@@ -1,10 +1,12 @@
 import { type AxiosError, isAxiosError } from "axios";
 
+import { AuthTelemetry } from "../instrumentation/auth";
 import { OAuthError } from "../oauth/errors";
 import { toSafeHost } from "../util";
 
 import type * as vscode from "vscode";
 
+import type { ServiceContainer } from "../core/container";
 import type { SecretsManager } from "../core/secretsManager";
 import type { Logger } from "../logging/logger";
 import type { RequestConfigWithMeta } from "../logging/types";
@@ -28,15 +30,20 @@ export type AuthRequiredHandler = (hostname: string) => Promise<boolean>;
  */
 export class AuthInterceptor implements vscode.Disposable {
 	private readonly interceptorId: number;
+	private readonly authTelemetry: AuthTelemetry;
+	private readonly logger: Logger;
+	private readonly secretsManager: SecretsManager;
 	private authRequiredPromise: Promise<boolean> | null = null;
 
 	constructor(
 		private readonly client: CoderApi,
-		private readonly logger: Logger,
 		private readonly oauthSessionManager: OAuthSessionManager,
-		private readonly secretsManager: SecretsManager,
+		container: ServiceContainer,
 		private readonly onAuthRequired?: AuthRequiredHandler,
 	) {
+		this.logger = container.getLogger();
+		this.secretsManager = container.getSecretsManager();
+		this.authTelemetry = new AuthTelemetry(container.getTelemetryService());
 		this.interceptorId = this.client
 			.getAxiosInstance()
 			.interceptors.response.use(
@@ -68,47 +75,58 @@ export class AuthInterceptor implements vscode.Disposable {
 		}
 		const hostname = toSafeHost(baseUrl);
 
-		return this.handle401Error(error, hostname);
+		return this.recoverFromUnauthorized(error, hostname);
 	}
 
-	private async handle401Error(
+	private recoverFromUnauthorized(
 		error: AxiosError,
 		hostname: string,
 	): Promise<unknown> {
 		this.logger.debug("Received 401 response, attempting recovery");
-
-		if (await this.oauthSessionManager.isLoggedInWithOAuth(hostname)) {
-			try {
-				const newTokens = await this.oauthSessionManager.refreshToken();
-				this.client.setSessionToken(newTokens.access_token);
-				this.logger.debug("Token refresh successful, retrying request");
-				return this.retryRequest(error, newTokens.access_token);
-			} catch (refreshError) {
-				if (refreshError instanceof OAuthError) {
-					const msg = `Token refresh failed: ${refreshError.message}`;
-					if (refreshError.requiresReAuth) {
-						this.logger.warn(msg);
-					} else {
-						this.logger.error(msg);
-					}
-				} else {
-					this.logger.error("Token refresh failed:", refreshError);
-				}
-			}
-		}
-
-		if (this.onAuthRequired) {
-			const success = await this.executeAuthRequired(hostname);
-			if (success) {
-				const auth = await this.secretsManager.getSessionAuth(hostname);
+		// TODO(#925): emit a correlated received-log here once Span.log() lands.
+		return this.authTelemetry.traceAuthRecovery(async (recorder) => {
+			const isOAuth =
+				await this.oauthSessionManager.isLoggedInWithOAuth(hostname);
+			recorder.setRefreshAttempted(isOAuth);
+			const newToken = isOAuth ? await this.tryOAuthRefresh() : undefined;
+			if (newToken) {
+				recorder.setRecovery("refresh_success");
+				return this.retryRequest(error, newToken);
+			} else if (this.onAuthRequired) {
+				recorder.setRecovery("login_required");
+				const success = await this.executeAuthRequired(hostname);
+				const auth = success
+					? await this.secretsManager.getSessionAuth(hostname)
+					: undefined;
 				if (auth) {
 					this.logger.debug("Re-authentication successful, retrying request");
 					return this.retryRequest(error, auth.token);
 				}
+				throw error;
+			} else {
+				recorder.setRecovery("none");
+				throw error;
 			}
-		}
+		});
+	}
 
-		throw error;
+	/** Returns the new access token on success, or undefined when refresh fails. */
+	private async tryOAuthRefresh(): Promise<string | undefined> {
+		try {
+			const newTokens = await this.oauthSessionManager.refreshToken();
+			this.client.setSessionToken(newTokens.access_token);
+			this.logger.debug("Token refresh successful");
+			return newTokens.access_token;
+		} catch (refreshError) {
+			if (!(refreshError instanceof OAuthError)) {
+				this.logger.error("Token refresh failed:", refreshError);
+			} else if (refreshError.requiresReAuth) {
+				this.logger.warn(`Token refresh failed: ${refreshError.message}`);
+			} else {
+				this.logger.error(`Token refresh failed: ${refreshError.message}`);
+			}
+			return undefined;
+		}
 	}
 
 	/**

src/core/container.ts

@@ -99,10 +99,7 @@ export class ServiceContainer implements vscode.Disposable {
 		this.contextManager = new ContextManager(context);
 		this.oauthCallback = new OAuthCallback(context.secrets, this.logger);
 		this.loginCoordinator = new LoginCoordinator(
-			this.secretsManager,
-			this.mementoManager,
-			this.logger,
-			this.cliCredentialManager,
+			this,
 			this.oauthCallback,
 			context.extension.id,
 		);

src/extension.ts

@@ -145,9 +145,8 @@ async function doActivate(
 	// Handles 401 responses (OAuth and otherwise)
 	const authInterceptor = new AuthInterceptor(
 		client,
-		output,
 		oauthSessionManager,
-		secretsManager,
+		serviceContainer,
 		async () => {
 			await handleAuthFailure();
 			return false;

src/instrumentation/auth.ts

@@ -0,0 +1,86 @@
+import type { TelemetryReporter } from "../telemetry/reporter";
+
+export type AuthTokenRefreshTrigger = "background" | "reactive";
+export type AuthRecoveryAction = "refresh_success" | "login_required" | "none";
+export type AuthLoginPromptTrigger = "auth_required" | "missing_session";
+
+/**
+ * Why a login prompt ended without a session. `auth_failed` indicates
+ * authentication itself failed; the others are user-driven aborts.
+ */
+export type LoginPromptReason =
+	| "user_dismissed"
+	| "no_url_provided"
+	| "auth_failed";
+
+export type LoginPromptOutcome =
+	| { success: true }
+	| { success: false; reason: LoginPromptReason };
+
+/** Span annotator for the auth-recovery flow. Defaults to safe values. */
+export interface AuthRecoveryRecorder {
+	setRecovery(recovery: AuthRecoveryAction): void;
+	setRefreshAttempted(attempted: boolean): void;
+}
+
+export class AuthTelemetry {
+	public constructor(private readonly telemetry: TelemetryReporter) {}
+
+	public traceTokenRefresh<T>(
+		trigger: AuthTokenRefreshTrigger,
+		fn: () => Promise<T>,
+	): Promise<T> {
+		return this.telemetry.trace("auth.token_refreshed", fn, { trigger });
+	}
+
+	/** Logged when a refresh call joins an in-flight refresh and emits no span of its own. */
+	public tokenRefreshDeduped(trigger: AuthTokenRefreshTrigger): void {
+		this.telemetry.log("auth.token_refresh.deduped", { trigger });
+	}
+
+	/**
+	 * Wraps the auth-recovery path triggered by a 401. Initial properties
+	 * cover the throw-before-callback case.
+	 */
+	public traceAuthRecovery<T>(
+		fn: (recorder: AuthRecoveryRecorder) => Promise<T>,
+	): Promise<T> {
+		return this.telemetry.trace(
+			"auth.unauthorized_intercepted",
+			(span) =>
+				fn({
+					setRecovery: (recovery) => span.setProperty("recovery", recovery),
+					setRefreshAttempted: (attempted) =>
+						span.setProperty("refreshAttempted", attempted),
+				}),
+			{ recovery: "none", refreshAttempted: false },
+		);
+	}
+
+	/**
+	 * Records `auth.login_prompted`. `auth_failed` marks the span as failure;
+	 * other non-success reasons mark it as aborted. The reason is copied to the
+	 * span's `reason` property on failure/abort only.
+	 */
+	public traceLoginPrompt<T extends LoginPromptOutcome>(
+		trigger: AuthLoginPromptTrigger,
+		fn: () => Promise<T>,
+	): Promise<T> {
+		return this.telemetry.trace(
+			"auth.login_prompted",
+			async (span) => {
+				const result = await fn();
+				if (!result.success) {
+					span.setProperty("reason", result.reason);
+					if (result.reason === "auth_failed") {
+						span.markFailure();
+					} else {
+						span.markAborted();
+					}
+				}
+				return result;
+			},
+			{ trigger },
+		);
+	}
+}

src/instrumentation/ssh.ts

@@ -34,7 +34,7 @@ export class SshTelemetry {
 	): Promise<number | undefined> {
 		return this.#telemetry.trace("ssh.process.discovered", async (span) => {
 			const { pid, attempts } = await fn();
-			span.setProperty("found", String(pid !== undefined));
+			span.setProperty("found", pid !== undefined);
 			span.setMeasurement("attempts", attempts);
 			return pid;
 		});
@@ -79,7 +79,6 @@ export class SshTelemetry {
 	public processReplaced(): void {
 		const now = performance.now();
 		if (this.#processStartedAtMs !== undefined) {
-			const wasLost = this.#processLostAtMs !== undefined;
 			const measurements: Record<string, number> = {
 				previousUptimeMs: now - this.#processStartedAtMs,
 			};
@@ -88,7 +87,7 @@ export class SshTelemetry {
 			}
 			this.#telemetry.log(
 				"ssh.process.replaced",
-				{ wasLost: String(wasLost) },
+				{ wasLost: this.#processLostAtMs !== undefined },
 				measurements,
 			);
 		}
@@ -104,10 +103,9 @@ export class SshTelemetry {
 			return;
 		}
 		const now = performance.now();
-		const wasLost = this.#processLostAtMs !== undefined;
 		this.#telemetry.log(
 			"ssh.process.disposed",
-			{ wasLost: String(wasLost) },
+			{ wasLost: this.#processLostAtMs !== undefined },
 			{ uptimeMs: now - this.#processStartedAtMs },
 		);
 		this.#processStartedAtMs = undefined;
@@ -131,7 +129,7 @@ export class SshTelemetry {
 		this.#telemetry.log(
 			"ssh.network.sampled",
 			{
-				p2p: String(network.p2p),
+				p2p: network.p2p,
 				preferredDerp: network.preferred_derp,
 			},
 			{

src/instrumentation/websocket.ts

@@ -49,7 +49,6 @@ export class WebSocketTelemetry {
 	readonly #telemetry: TelemetryReporter;
 	#connectStartedAtMs: number | undefined;
 	#connectionOpenedAtMs: number | undefined;
-	#connectionDropEmitted = false;
 	#reconnectCycle: ReconnectCycle | undefined;
 
 	public constructor(telemetry: TelemetryReporter) {
@@ -80,7 +79,6 @@ export class WebSocketTelemetry {
 		const now = performance.now();
 		const start = this.#connectStartedAtMs ?? now;
 		this.#connectionOpenedAtMs = now;
-		this.#connectionDropEmitted = false;
 		this.#connectStartedAtMs = undefined;
 		this.#telemetry.log(
 			"connection.opened",
@@ -95,19 +93,19 @@ export class WebSocketTelemetry {
 		closeCode?: number,
 		error?: unknown,
 	): void {
-		if (
-			this.#connectionOpenedAtMs === undefined ||
-			this.#connectionDropEmitted
-		) {
+		// Capture-and-clear up-front so a throw, future await, or re-entry can't re-emit.
+		const openedAtMs = this.#connectionOpenedAtMs;
+		if (openedAtMs === undefined) {
 			return;
 		}
+		this.#connectionOpenedAtMs = undefined;
 
 		const properties: CallerProperties = { cause };
 		if (closeCode !== undefined) {
-			properties.closeCode = String(closeCode);
+			properties.closeCode = closeCode;
 		}
 		const measurements = {
-			connectionDurationMs: performance.now() - this.#connectionOpenedAtMs,
+			connectionDurationMs: performance.now() - openedAtMs,
 		};
 		if (error === undefined) {
 			this.#telemetry.log("connection.dropped", properties, measurements);
@@ -119,13 +117,11 @@ export class WebSocketTelemetry {
 				measurements,
 			);
 		}
-		this.#connectionDropEmitted = true;
 	}
 
 	public reset(): void {
 		this.#connectStartedAtMs = undefined;
 		this.#connectionOpenedAtMs = undefined;
-		this.#connectionDropEmitted = false;
 		this.#reconnectCycle = undefined;
 	}