diff --git a/CHANGELOG.md b/CHANGELOG.md index ad5ef218b9..49957df077 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/api/authInterceptor.ts b/src/api/authInterceptor.ts index d362c1d12e..ac76733627 100644 --- a/src/api/authInterceptor.ts +++ b/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; */ 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 | 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 { 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 { + 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; + } } /** diff --git a/src/core/container.ts b/src/core/container.ts index 042eb81f24..cc781a2b58 100644 --- a/src/core/container.ts +++ b/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, ); diff --git a/src/extension.ts b/src/extension.ts index 3067014c2c..6e4554ec38 100644 --- a/src/extension.ts +++ b/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; diff --git a/src/instrumentation/auth.ts b/src/instrumentation/auth.ts new file mode 100644 index 0000000000..fe3560248d --- /dev/null +++ b/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. */ +interface AuthRecoveryRecorder { + setRecovery(recovery: AuthRecoveryAction): void; + setRefreshAttempted(attempted: boolean): void; +} + +export class AuthTelemetry { + public constructor(private readonly telemetry: TelemetryReporter) {} + + public traceTokenRefresh( + trigger: AuthTokenRefreshTrigger, + fn: () => Promise, + ): Promise { + 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( + fn: (recorder: AuthRecoveryRecorder) => Promise, + ): Promise { + 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( + trigger: AuthLoginPromptTrigger, + fn: () => Promise, + ): Promise { + 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 }, + ); + } +} diff --git a/src/instrumentation/ssh.ts b/src/instrumentation/ssh.ts index 2031fed9c7..3ec3d0200d 100644 --- a/src/instrumentation/ssh.ts +++ b/src/instrumentation/ssh.ts @@ -34,7 +34,7 @@ export class SshTelemetry { ): Promise { 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 = { 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, }, { diff --git a/src/instrumentation/websocket.ts b/src/instrumentation/websocket.ts index 9d52ecddae..7c9b0efd15 100644 --- a/src/instrumentation/websocket.ts +++ b/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; } diff --git a/src/instrumentation/workspace.ts b/src/instrumentation/workspace.ts new file mode 100644 index 0000000000..6d782ff081 --- /dev/null +++ b/src/instrumentation/workspace.ts @@ -0,0 +1,164 @@ +import type { + Workspace, + WorkspaceAgent, + WorkspaceAgentLifecycle, + WorkspaceAgentStatus, + WorkspaceBuild, + WorkspaceStatus, +} from "coder/site/src/api/typesGenerated"; + +import type { TelemetryReporter } from "../telemetry/reporter"; + +/** Sentinel for `from*` before any state is observed. `"unknown"` is a real server-reported value, so avoid it. */ +const INITIAL_STATE = "none"; + +/** Statuses where a provisioner job is actively running. */ +const PROVISIONING_STATUSES: ReadonlySet = new Set([ + "pending", + "starting", + "stopping", + "canceling", + "deleting", +]); + +interface ObservedWorkspaceState { + readonly status: WorkspaceStatus; + readonly transition: WorkspaceBuild["transition"]; + readonly reason: WorkspaceBuild["reason"]; + readonly observedAtMs: number; +} + +interface ObservedAgentState { + readonly status: WorkspaceAgentStatus; + readonly lifecycleState: WorkspaceAgentLifecycle; + readonly observedAtMs: number; +} + +/** + * Emits `workspace.state_transitioned` as a workspace progresses through + * statuses, plus `observedBuildDurationMs` when a provisioner run resolves. + * Construct one per workspace; `WorkspaceMonitor` is the sole call site. + */ +export class WorkspaceStateTelemetry { + private observed: ObservedWorkspaceState | undefined; + /** Set on first observation of a provisioning status; cleared when the build resolves. */ + private buildStartedAtMs: number | undefined; + + public constructor( + private readonly telemetry: TelemetryReporter, + private readonly workspaceName: string, + ) {} + + public observe(workspace: Workspace): void { + const { status, transition, reason } = workspace.latest_build; + const previous = this.observed; + if ( + previous?.status === status && + previous.transition === transition && + previous.reason === reason + ) { + return; + } + + const now = performance.now(); + const measurements: Record = previous + ? { observedDurationMs: now - previous.observedAtMs } + : {}; + + const wasProvisioning = + previous && PROVISIONING_STATUSES.has(previous.status); + const isProvisioning = PROVISIONING_STATUSES.has(status); + if (isProvisioning) { + this.buildStartedAtMs ??= now; + } else { + if (wasProvisioning && this.buildStartedAtMs !== undefined) { + measurements.observedBuildDurationMs = now - this.buildStartedAtMs; + } + this.buildStartedAtMs = undefined; + } + + this.telemetry.log( + "workspace.state_transitioned", + { + workspaceName: this.workspaceName, + from: previous?.status ?? INITIAL_STATE, + to: status, + transition, + reason, + }, + measurements, + ); + this.observed = { status, transition, reason, observedAtMs: now }; + } +} + +/** + * Emits `workspace.agent.state_transitioned` as the agent's `status` and + * `lifecycle_state` change. The agent has two state dimensions so the event + * carries qualified `fromStatus`/`toStatus` and `fromLifecycleState`/ + * `toLifecycleState` properties. Construct one per workspace. + */ +export class WorkspaceAgentTelemetry { + private observed: ObservedAgentState | undefined; + + public constructor( + private readonly telemetry: TelemetryReporter, + private readonly workspaceName: string, + ) {} + + public observe(agent: WorkspaceAgent): void { + const previous = this.observed; + if ( + previous?.status === agent.status && + previous.lifecycleState === agent.lifecycle_state + ) { + return; + } + const now = performance.now(); + + this.telemetry.log( + "workspace.agent.state_transitioned", + { + workspaceName: this.workspaceName, + agentName: agent.name, + fromStatus: previous?.status ?? INITIAL_STATE, + toStatus: agent.status, + fromLifecycleState: previous?.lifecycleState ?? INITIAL_STATE, + toLifecycleState: agent.lifecycle_state, + }, + previous ? { observedDurationMs: now - previous.observedAtMs } : {}, + ); + this.observed = { + status: agent.status, + lifecycleState: agent.lifecycle_state, + observedAtMs: now, + }; + } + + public reset(): void { + this.observed = undefined; + } +} + +/** + * Wraps user-initiated workspace operations (start, update) as traced spans. + * Stateless; safe to construct per call site. + */ +export class WorkspaceOperationTelemetry { + public constructor( + private readonly telemetry: TelemetryReporter, + private readonly workspaceName: string, + ) {} + + public traceUpdateTriggered(fn: () => Promise): Promise { + return this.telemetry.trace("workspace.update.triggered", fn, { + workspaceName: this.workspaceName, + }); + } + + public traceStartTriggered(fn: () => Promise): Promise { + return this.telemetry.trace("workspace.start.triggered", fn, { + workspaceName: this.workspaceName, + }); + } +} diff --git a/src/login/loginCoordinator.ts b/src/login/loginCoordinator.ts index 018d9558ee..c36c6f6938 100644 --- a/src/login/loginCoordinator.ts +++ b/src/login/loginCoordinator.ts @@ -5,6 +5,11 @@ import * as vscode from "vscode"; import { CoderApi } from "../api/coderApi"; import { needToken } from "../api/utils"; import { CertificateError } from "../error/certificateError"; +import { + AuthTelemetry, + type AuthLoginPromptTrigger, + type LoginPromptReason, +} from "../instrumentation/auth"; import { OAuthAuthorizer } from "../oauth/authorizer"; import { buildOAuthTokenData } from "../oauth/utils"; import { withOptionalProgress } from "../progress"; @@ -15,6 +20,7 @@ import { vscodeProposed } from "../vscodeProposed"; import type { User } from "coder/site/src/api/typesGenerated"; import type { CliCredentialManager } from "../core/cliCredentialManager"; +import type { ServiceContainer } from "../core/container"; import type { MementoManager } from "../core/mementoManager"; import type { OAuthTokenData, SecretsManager } from "../core/secretsManager"; import type { Deployment } from "../deployment/types"; @@ -22,7 +28,7 @@ import type { Logger } from "../logging/logger"; import type { OAuthCallback } from "../oauth/oauthCallback"; type LoginResult = - | { success: false } + | { success: false; reason: LoginPromptReason } | { success: true; user: User; token: string; oauth?: OAuthTokenData }; export interface LoginOptions { @@ -38,19 +44,26 @@ export interface LoginOptions { export class LoginCoordinator implements vscode.Disposable { private loginQueue: Promise = Promise.resolve(); private readonly oauthAuthorizer: OAuthAuthorizer; + private readonly authTelemetry: AuthTelemetry; + private readonly secretsManager: SecretsManager; + private readonly mementoManager: MementoManager; + private readonly logger: Logger; + private readonly cliCredentialManager: CliCredentialManager; constructor( - private readonly secretsManager: SecretsManager, - private readonly mementoManager: MementoManager, - private readonly logger: Logger, - private readonly cliCredentialManager: CliCredentialManager, + container: ServiceContainer, oauthCallback: OAuthCallback, extensionId: string, ) { + this.secretsManager = container.getSecretsManager(); + this.mementoManager = container.getMementoManager(); + this.logger = container.getLogger(); + this.cliCredentialManager = container.getCliCredentialManager(); + this.authTelemetry = new AuthTelemetry(container.getTelemetryService()); this.oauthAuthorizer = new OAuthAuthorizer( - secretsManager, + this.secretsManager, oauthCallback, - logger, + this.logger, extensionId, ); } @@ -79,7 +92,19 @@ export class LoginCoordinator implements vscode.Disposable { /** * Shows dialog then login - for system-initiated auth (remote, OAuth refresh). */ - public async ensureLoggedInWithDialog( + public ensureLoggedInWithDialog( + options: LoginOptions & { + message?: string; + detailPrefix?: string; + trigger: AuthLoginPromptTrigger; + }, + ): Promise { + return this.authTelemetry.traceLoginPrompt(options.trigger, () => + this.performLoginDialog(options), + ); + } + + private async performLoginDialog( options: LoginOptions & { message?: string; detailPrefix?: string }, ): Promise { const { safeHostname, url, detailPrefix, message } = options; @@ -97,7 +122,7 @@ export class LoginCoordinator implements vscode.Disposable { }, "Login", ) - .then(async (action) => { + .then(async (action): Promise => { if (action === "Login") { // Proceed with the login flow, handling logging in from another window const storedAuth = @@ -108,7 +133,7 @@ export class LoginCoordinator implements vscode.Disposable { storedAuth?.url, ); if (!newUrl) { - throw new Error("URL must be provided"); + return { success: false, reason: "no_url_provided" }; } const result = await this.attemptLogin( @@ -120,10 +145,9 @@ export class LoginCoordinator implements vscode.Disposable { await this.persistSessionAuth(result, safeHostname, newUrl); return result; - } else { - // User cancelled - return { success: false } as const; } + // User cancelled + return { success: false, reason: "user_dismissed" }; }); // Race between user clicking login and cross-window detection @@ -290,7 +314,7 @@ export class LoginCoordinator implements vscode.Disposable { case "legacy": return this.loginWithToken(client); case undefined: - return { success: false }; // User aborted + return { success: false, reason: "user_dismissed" }; } } @@ -303,7 +327,7 @@ export class LoginCoordinator implements vscode.Disposable { return { success: true, token: "", user }; } catch (err) { this.showAuthError(err, isAutoLogin); - return { success: false }; + return { success: false, reason: "auth_failed" }; } } @@ -324,7 +348,7 @@ export class LoginCoordinator implements vscode.Disposable { return "unauthorized"; } this.showAuthError(err, isAutoLogin); - return { success: false }; + return { success: false, reason: "auth_failed" }; } } @@ -406,7 +430,7 @@ export class LoginCoordinator implements vscode.Disposable { return { success: true, user, token: validatedToken ?? "" }; } - return { success: false }; + return { success: false, reason: "user_dismissed" }; } /** @@ -446,7 +470,7 @@ export class LoginCoordinator implements vscode.Disposable { `${title}: ${getErrorMessage(error, "Unknown error")}`, ); } - return { success: false }; + return { success: false, reason: "auth_failed" }; } } diff --git a/src/oauth/sessionManager.ts b/src/oauth/sessionManager.ts index 32ab7e7810..a0968915f4 100644 --- a/src/oauth/sessionManager.ts +++ b/src/oauth/sessionManager.ts @@ -1,4 +1,8 @@ import { CoderApi } from "../api/coderApi"; +import { + AuthTelemetry, + type AuthTokenRefreshTrigger, +} from "../instrumentation/auth"; import { DEFAULT_OAUTH_SCOPES, REFRESH_GRANT_TYPE } from "./constants"; import { OAuthError, parseOAuthError } from "./errors"; @@ -64,6 +68,7 @@ export class OAuthSessionManager implements vscode.Disposable { container.getSecretsManager(), container.getLogger(), onAuthRequired, + new AuthTelemetry(container.getTelemetryService()), ); manager.setupTokenListener(); manager.scheduleNextRefresh(); @@ -75,6 +80,7 @@ export class OAuthSessionManager implements vscode.Disposable { private readonly secretsManager: SecretsManager, private readonly logger: Logger, private readonly onAuthRequired: () => Promise, + private readonly authTelemetry: AuthTelemetry, ) {} /** @@ -218,7 +224,7 @@ export class OAuthSessionManager implements vscode.Disposable { this.refreshTimer = undefined; - this.refreshToken() + this.refreshToken("background") .then(() => { this.logger.debug("Background token refresh succeeded"); }) @@ -342,17 +348,22 @@ export class OAuthSessionManager implements vscode.Disposable { * Refresh the access token using the stored refresh token. * Uses a shared promise to handle concurrent refresh attempts. */ - public async refreshToken(): Promise { + public async refreshToken( + trigger: AuthTokenRefreshTrigger = "reactive", + ): Promise { if (this.refreshPromise) { this.logger.debug( "Token refresh already in progress, waiting for result", ); + this.authTelemetry.tokenRefreshDeduped(trigger); return this.refreshPromise; } const deployment = this.requireDeployment(); // Assign synchronously before any async work to prevent race conditions - this.refreshPromise = this.executeTokenRefresh(deployment); + this.refreshPromise = this.authTelemetry.traceTokenRefresh(trigger, () => + this.executeTokenRefresh(deployment), + ); return this.refreshPromise; } diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 045ba8de8c..61cbb38937 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -195,6 +195,7 @@ export class Remote { try { // Create OAuth session manager for this remote deployment + const telemetry = this.serviceContainer.getTelemetryService(); const remoteOAuthManager = OAuthSessionManager.create( { url: baseUrl, safeHostname: parts.safeHostname }, this.serviceContainer, @@ -216,16 +217,15 @@ export class Remote { baseUrl, token, this.logger, - this.serviceContainer.getTelemetryService(), + telemetry, ); disposables.push(workspaceClient); // Create 401 interceptor - handles auth failures with re-login dialog const authInterceptor = new AuthInterceptor( workspaceClient, - this.logger, remoteOAuthManager, - this.secretsManager, + this.serviceContainer, async () => { const result = await this.showSessionExpiredDialog(context); return result.success; @@ -313,8 +313,7 @@ export class Remote { const monitor = await WorkspaceMonitor.create( workspace, workspaceClient, - this.logger, - this.contextManager, + this.serviceContainer, ); disposables.push( monitor, @@ -332,8 +331,8 @@ export class Remote { args.startupMode, binaryPath, featureSet, - this.logger, cliAuth, + this.serviceContainer, ); disposables.push(stateMachine); @@ -642,6 +641,7 @@ export class Remote { url: context.baseUrl, message: "Your session expired...", detailPrefix: `You must log in to access ${context.workspaceName}.`, + trigger: "auth_required", }); } @@ -655,6 +655,7 @@ export class Remote { url, message, detailPrefix: `You must log in to access ${context.workspaceName}.`, + trigger: "missing_session", }); // Dispose before retrying since setup will create new disposables. diff --git a/src/remote/workspaceStateMachine.ts b/src/remote/workspaceStateMachine.ts index 0b9a299b30..b9ebb991cf 100644 --- a/src/remote/workspaceStateMachine.ts +++ b/src/remote/workspaceStateMachine.ts @@ -13,6 +13,10 @@ import { streamAgentLogs, streamBuildLogs, } from "../api/workspace"; +import { + WorkspaceAgentTelemetry, + WorkspaceOperationTelemetry, +} from "../instrumentation/workspace"; import { maybeAskAgent } from "../promptUtils"; import { vscodeProposed } from "../vscodeProposed"; @@ -25,6 +29,7 @@ import type { } from "coder/site/src/api/typesGenerated"; import type { CoderApi } from "../api/coderApi"; +import type { ServiceContainer } from "../core/container"; import type { StartupMode } from "../core/mementoManager"; import type { FeatureSet } from "../featureSet"; import type { Logger } from "../logging/logger"; @@ -39,20 +44,32 @@ export class WorkspaceStateMachine implements vscode.Disposable { private readonly terminal: TerminalOutputChannel; private readonly buildLogStream = new LazyStream(); private readonly agentLogStream = new LazyStream(); + private readonly agentTelemetry: WorkspaceAgentTelemetry; + private readonly operationTelemetry: WorkspaceOperationTelemetry; private agent: { id: string; name: string } | undefined; private workspace: Workspace | undefined; + private readonly logger: Logger; + constructor( private readonly parts: AuthorityParts, private readonly workspaceClient: CoderApi, private startupMode: StartupMode, private readonly binaryPath: string, private readonly featureSet: FeatureSet, - private readonly logger: Logger, private readonly cliAuth: CliAuth, + container: ServiceContainer, ) { + this.logger = container.getLogger(); this.terminal = new TerminalOutputChannel("Coder: Workspace Build"); + const telemetry = container.getTelemetryService(); + const workspaceName = `${parts.username}/${parts.workspace}`; + this.agentTelemetry = new WorkspaceAgentTelemetry(telemetry, workspaceName); + this.operationTelemetry = new WorkspaceOperationTelemetry( + telemetry, + workspaceName, + ); } /** @@ -77,7 +94,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { if (updated) { workspace = updated; // Agent IDs may have changed after an update. - this.agent = undefined; + this.resetAgent(); if (workspace.latest_build.status !== "running") return false; } break; @@ -106,7 +123,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { if (updated) { workspace = updated; // Agent IDs may have changed after an update. - this.agent = undefined; + this.resetAgent(); if (workspace.latest_build.status !== "running") return false; break; } @@ -119,7 +136,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { case "starting": case "stopping": { // Clear the agent since its ID could change after a restart - this.agent = undefined; + this.resetAgent(); this.agentLogStream.close(); progress.report({ message: `building ${workspaceName} (${workspace.latest_build.status})...`, @@ -164,6 +181,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { `Agent ${this.agent.name} not found in ${workspaceName} resources`, ); } + this.agentTelemetry.observe(agent); switch (agent.status) { case "connecting": @@ -268,7 +286,9 @@ export class WorkspaceStateMachine implements vscode.Disposable { mode: this.startupMode, status: workspace.latest_build.status, }); - await startWorkspace(this.buildCliContext(workspace)); + await this.operationTelemetry.traceStartTriggered(() => + startWorkspace(this.buildCliContext(workspace)), + ); this.logger.info(`${workspaceName} start initiated`); } @@ -286,7 +306,10 @@ export class WorkspaceStateMachine implements vscode.Disposable { status: workspace.latest_build.status, }); try { - this.workspace = await updateWorkspace(this.buildCliContext(workspace)); + this.workspace = await this.operationTelemetry.traceUpdateTriggered(() => + updateWorkspace(this.buildCliContext(workspace)), + ); + this.logger.info(`${workspaceName} update initiated`); return this.workspace; } catch (error) { if (error instanceof WorkspaceUpdateCancelledError) { @@ -330,6 +353,11 @@ export class WorkspaceStateMachine implements vscode.Disposable { return this.workspace; } + private resetAgent(): void { + this.agent = undefined; + this.agentTelemetry.reset(); + } + dispose(): void { this.buildLogStream.close(); this.agentLogStream.close(); diff --git a/src/telemetry/event.ts b/src/telemetry/event.ts index 54e5159e30..1749a068a2 100644 --- a/src/telemetry/event.ts +++ b/src/telemetry/event.ts @@ -6,8 +6,13 @@ import { toError } from "../error/errorUtils"; /** Telemetry level, mirrors `coder.telemetry.level`. Ordered: off < local. */ export type TelemetryLevel = "off" | "local"; +/** Value types accepted from callers; the framework stringifies at the wire boundary. */ +export type CallerPropertyValue = string | number | boolean; + /** Caller properties. `result` is framework-managed on traced events. */ -export type CallerProperties = Record & { result?: never }; +export type CallerProperties = Record & { + result?: never; +}; /** Caller measurements. `durationMs` is framework-managed on traced events. */ export type CallerMeasurements = Record & { diff --git a/src/telemetry/service.ts b/src/telemetry/service.ts index 05ac148267..a9099fc86e 100644 --- a/src/telemetry/service.ts +++ b/src/telemetry/service.ts @@ -11,13 +11,14 @@ import { buildErrorBlock, type CallerMeasurements, type CallerProperties, + type CallerPropertyValue, type SessionContext, type TelemetryEvent, type TelemetryLevel, type TelemetrySink, } from "./event"; import { newSpanId, newTraceId } from "./ids"; -import { NOOP_SPAN, type Span } from "./span"; +import { NOOP_SPAN, type Span, type SpanResult } from "./span"; import type { TelemetryReporter } from "./reporter"; @@ -29,6 +30,16 @@ const LEVEL_ORDER: Readonly> = { const readLevel = (): TelemetryLevel => readTelemetryLevel(vscode.workspace.getConfiguration()); +const normalizeProps = ( + props: Record, +): Record => { + const out: Record = {}; + for (const [k, v] of Object.entries(props)) { + out[k] = typeof v === "string" ? v : String(v); + } + return out; +}; + /** Trace context shared by all events in one trace. */ interface SpanOptions { traceId: string; @@ -88,7 +99,12 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { if (this.#level === "off") { return; } - this.#safeEmit(newSpanId(), eventName, properties, measurements); + this.#safeEmit( + newSpanId(), + eventName, + normalizeProps(properties), + measurements, + ); } public logError( @@ -100,9 +116,13 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { if (this.#level === "off") { return; } - this.#safeEmit(newSpanId(), eventName, properties, measurements, { - error, - }); + this.#safeEmit( + newSpanId(), + eventName, + normalizeProps(properties), + measurements, + { error }, + ); } /** @@ -120,10 +140,16 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { if (this.#level === "off") { return fn(NOOP_SPAN); } - return this.#startSpan(eventName, fn, properties, measurements, { - traceId: newTraceId(), - traceLevel: this.#level, - }); + return this.#startSpan( + eventName, + fn, + normalizeProps(properties), + measurements, + { + traceId: newTraceId(), + traceLevel: this.#level, + }, + ); } public async dispose(): Promise { @@ -148,7 +174,8 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { const spanMeasurements = { ...measurements }; const { traceId, traceLevel } = spanOpts; let completed = false; - let aborted = false; + // `markFailure` wins over `markAborted` regardless of call order. + let mark: "aborted" | "error" | undefined; const warnPostEmit = (op: string, name: string): void => { this.logger.warn( `Telemetry span '${eventName}' ${op}('${name}') called after emit; mutation dropped`, @@ -161,24 +188,25 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { phase: ( phaseName: string, phaseFn: (childSpan: Span) => Promise, - phaseProps: Record = {}, + phaseProps: CallerProperties = {}, phaseMeasurements: Record = {}, ): Promise => { const safeName = this.#sanitizePhaseName(phaseName); return this.#startSpan( `${eventName}.${safeName}`, phaseFn, - phaseProps, + normalizeProps(phaseProps), phaseMeasurements, { traceId, parentEventId: eventId, traceLevel }, ); }, - setProperty(name: string, value: string): void { + setProperty(name: string, value: CallerPropertyValue): void { if (completed) { warnPostEmit("setProperty", name); return; } - spanProperties[name] = value; + spanProperties[name] = + typeof value === "string" ? value : String(value); }, setMeasurement(name: string, value: number): void { if (completed) { @@ -192,7 +220,14 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { warnPostEmit("markAborted", ""); return; } - aborted = true; + mark ??= "aborted"; + }, + markFailure(): void { + if (completed) { + warnPostEmit("markFailure", ""); + return; + } + mark = "error"; }, }; return this.#emitTimed( @@ -202,7 +237,7 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { spanProperties, spanMeasurements, spanOpts, - () => aborted, + () => mark ?? "success", ).finally(() => { completed = true; }); @@ -226,13 +261,10 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { properties: Record, measurements: Record, spanOpts: SpanOptions, - isAborted: () => boolean, + resolveResult: () => SpanResult, ): Promise { const start = performance.now(); - const send = ( - result: "success" | "error" | "aborted", - error?: unknown, - ): void => + const send = (result: SpanResult, error?: unknown): void => this.#safeEmit( eventId, eventName, @@ -242,7 +274,7 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { ); try { const value = await fn(); - send(isAborted() ? "aborted" : "success"); + send(resolveResult()); return value; } catch (err) { send("error", err); diff --git a/src/telemetry/span.ts b/src/telemetry/span.ts index a3e5973a46..303db591e3 100644 --- a/src/telemetry/span.ts +++ b/src/telemetry/span.ts @@ -1,4 +1,18 @@ -import type { CallerMeasurements, CallerProperties } from "./event"; +import type { + CallerMeasurements, + CallerProperties, + CallerPropertyValue, +} from "./event"; + +/** + * Final disposition recorded on a traced event's `result` property. + * - `success`: ran to completion as intended. + * - `aborted`: ended early by a user-initiated cancel. + * - `error`: the operation failed. Thrown exceptions populate the event's + * `error` block; `markFailure()` does not. This matches + * OpenTelemetry's "Status: Error + optional exception event". + */ +export type SpanResult = "success" | "aborted" | "error"; /** * Parent span handle. Children's `eventName` composes as `${parent.eventName}.${phaseName}`. @@ -17,11 +31,13 @@ export interface Span { measurements?: CallerMeasurements, ): Promise; /** Add or replace a property on the event emitted for this span. */ - setProperty(name: string, value: string): void; + setProperty(name: string, value: CallerPropertyValue): void; /** Add or replace a measurement on the event emitted for this span. */ setMeasurement(name: string, value: number): void; /** Flip this span's `result` from `success` to `aborted` on normal return. */ markAborted(): void; + /** Flip `result` to `error` for a failure captured in the return value. See `SpanResult`. */ + markFailure(): void; } /** No-op `Span` used when telemetry is off. Runs phase fns but emits nothing. */ @@ -33,6 +49,7 @@ export const NOOP_SPAN: Span = { return fn(NOOP_SPAN); }, markAborted: () => undefined, + markFailure: () => undefined, setProperty: () => undefined, setMeasurement: () => undefined, }; diff --git a/src/workspace/workspaceMonitor.ts b/src/workspace/workspaceMonitor.ts index 4fca7473ec..150fac1e9b 100644 --- a/src/workspace/workspaceMonitor.ts +++ b/src/workspace/workspaceMonitor.ts @@ -6,6 +6,7 @@ import { formatDistanceToNowStrict } from "date-fns"; import * as vscode from "vscode"; import { createWorkspaceIdentifier, errToStr } from "../api/api-helper"; +import { WorkspaceStateTelemetry } from "../instrumentation/workspace"; import { areNotificationsDisabled, areUpdateNotificationsDisabled, @@ -13,6 +14,7 @@ import { import { vscodeProposed } from "../vscodeProposed"; import type { CoderApi } from "../api/coderApi"; +import type { ServiceContainer } from "../core/container"; import type { ContextManager } from "../core/contextManager"; import type { Logger } from "../logging/logger"; import type { UnidirectionalStream } from "../websocket/eventStreamConnection"; @@ -42,16 +44,24 @@ export class WorkspaceMonitor implements vscode.Disposable { // For logging. private readonly name: string; + private readonly telemetry: WorkspaceStateTelemetry; + private readonly logger: Logger; + private readonly contextManager: ContextManager; private latestWorkspace: Workspace; private constructor( workspace: Workspace, private readonly client: CoderApi, - private readonly logger: Logger, - private readonly contextManager: ContextManager, + container: ServiceContainer, ) { + this.logger = container.getLogger(); + this.contextManager = container.getContextManager(); this.name = createWorkspaceIdentifier(workspace); + this.telemetry = new WorkspaceStateTelemetry( + container.getTelemetryService(), + this.name, + ); this.latestWorkspace = workspace; const statusBarItem = vscode.window.createStatusBarItem( @@ -75,21 +85,15 @@ export class WorkspaceMonitor implements vscode.Disposable { static async create( workspace: Workspace, client: CoderApi, - logger: Logger, - contextManager: ContextManager, + container: ServiceContainer, ): Promise { - const monitor = new WorkspaceMonitor( - workspace, - client, - logger, - contextManager, - ); + const monitor = new WorkspaceMonitor(workspace, client, container); // Initialize websocket connection const socket = await client.watchWorkspace(workspace); socket.addEventListener("open", () => { - logger.info(`Monitoring ${monitor.name}...`); + monitor.logger.info(`Monitoring ${monitor.name}...`); }); socket.addEventListener("message", (event) => { @@ -134,6 +138,7 @@ export class WorkspaceMonitor implements vscode.Disposable { } private update(workspace: Workspace) { + this.telemetry.observe(workspace); this.latestWorkspace = workspace; this.updateContext(workspace); this.updateStatusBar(workspace); diff --git a/test/mocks/telemetry.ts b/test/mocks/telemetry.ts index 619c119e87..3d954d32c5 100644 --- a/test/mocks/telemetry.ts +++ b/test/mocks/telemetry.ts @@ -8,7 +8,7 @@ import { } from "@/telemetry/event"; import { TelemetryService } from "@/telemetry/service"; -import { createMockLogger } from "./testHelpers"; +import { createMockLogger, MockConfigurationProvider } from "./testHelpers"; /** * In-memory `TelemetrySink` for tests. Captures every written event and @@ -33,6 +33,17 @@ export class TestSink implements TelemetrySink { eventsNamed(name: string): TelemetryEvent[] { return this.events.filter((e) => e.eventName === name); } + + /** Returns the single event with `name`, throwing if not exactly one. */ + expectOne(name: string): TelemetryEvent { + const matches = this.eventsNamed(name); + if (matches.length !== 1) { + throw new Error( + `Expected exactly 1 '${name}' event, got ${matches.length}`, + ); + } + return matches[0]; + } } export function createTestTelemetryService( @@ -44,3 +55,18 @@ export function createTestTelemetryService( createMockLogger(), ); } + +/** Sets `coder.telemetry.level=local` so emissions reach the sink. */ +export function enableLocalTelemetry(): void { + new MockConfigurationProvider().set("coder.telemetry.level", "local"); +} + +/** Bundles `enableLocalTelemetry` + a fresh sink + service. */ +export function createTelemetryHarness(): { + sink: TestSink; + service: TelemetryService; +} { + enableLocalTelemetry(); + const sink = new TestSink(); + return { sink, service: createTestTelemetryService(sink) }; +} diff --git a/test/mocks/testHelpers.ts b/test/mocks/testHelpers.ts index 91f919dbfc..b9a8aa9399 100644 --- a/test/mocks/testHelpers.ts +++ b/test/mocks/testHelpers.ts @@ -8,6 +8,7 @@ import axios, { import { vi } from "vitest"; import * as vscode from "vscode"; +import { createTestTelemetryService } from "./telemetry"; import { window as vscodeWindow } from "./vscode.runtime"; import type { Experiment, User } from "coder/site/src/api/typesGenerated"; @@ -16,8 +17,13 @@ import type { IncomingMessage } from "node:http"; import type { CoderApi } from "@/api/coderApi"; import type { CliCredentialManager } from "@/core/cliCredentialManager"; +import type { ServiceContainer } from "@/core/container"; +import type { ContextManager } from "@/core/contextManager"; +import type { MementoManager } from "@/core/mementoManager"; +import type { SecretsManager } from "@/core/secretsManager"; import type { Logger } from "@/logging/logger"; import type { NetworkInfo } from "@/remote/sshProcess"; +import type { TelemetryService } from "@/telemetry/service"; import type { EventHandler, EventPayloadMap, @@ -25,6 +31,17 @@ import type { UnidirectionalStream, } from "@/websocket/eventStreamConnection"; +/** + * Subset of `ContextManager`'s public API that mocks (e.g. `MockContextManager`) + * implement. Used by `createMockServiceContainer` so tests can pass either the + * real class or a mock without resorting to `unknown`. + */ +interface ContextManagerLike { + set(key: string, value: boolean): void; + get(key: string): boolean; + dispose(): void; +} + export function makeNetworkInfo( overrides: Partial = {}, ): NetworkInfo { @@ -443,6 +460,43 @@ export function createMockLogger(): Logger { }; } +/** + * Minimal `ServiceContainer` stub for tests. Pass only the services the unit + * under test reads; unset services throw on access so a missing dependency + * surfaces as a clear error rather than a downstream `undefined` deref. + */ +export function createMockServiceContainer( + overrides: { + telemetry?: TelemetryService; + logger?: Logger; + secretsManager?: SecretsManager; + mementoManager?: MementoManager; + cliCredentialManager?: CliCredentialManager; + contextManager?: ContextManagerLike; + } = {}, +): ServiceContainer { + const telemetry = overrides.telemetry ?? createTestTelemetryService(); + const logger = overrides.logger ?? createMockLogger(); + const require = (name: string, value: T | undefined): T => { + if (value === undefined) { + throw new Error(`createMockServiceContainer: '${name}' was not provided`); + } + return value; + }; + return { + getTelemetryService: () => telemetry, + getLogger: () => logger, + getSecretsManager: () => + require("secretsManager", overrides.secretsManager), + getMementoManager: () => + require("mementoManager", overrides.mementoManager), + getCliCredentialManager: () => + require("cliCredentialManager", overrides.cliCredentialManager), + getContextManager: () => + require("contextManager", overrides.contextManager) as ContextManager, + } as ServiceContainer; +} + /** Update the mocked active color theme and fire onDidChangeActiveColorTheme. */ export function setActiveColorTheme(kind: vscode.ColorThemeKind): void { vscodeWindow.__setActiveColorThemeKind(kind); diff --git a/test/unit/api/authInterceptor.test.ts b/test/unit/api/authInterceptor.test.ts index e2b8ed3c71..b744030dd8 100644 --- a/test/unit/api/authInterceptor.test.ts +++ b/test/unit/api/authInterceptor.test.ts @@ -7,9 +7,15 @@ import { } from "@/api/authInterceptor"; import { SecretsManager } from "@/core/secretsManager"; +import { + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; import { createAxiosError, createMockLogger, + createMockServiceContainer, InMemoryMemento, InMemorySecretStorage, MockOAuthSessionManager, @@ -21,7 +27,9 @@ import { } from "../oauth/testUtils"; import type { CoderApi } from "@/api/coderApi"; +import type { AuthRecoveryAction } from "@/instrumentation/auth"; import type { OAuthSessionManager } from "@/oauth/sessionManager"; +import type { TelemetryService } from "@/telemetry/service"; /** * Creates a mock axios instance with controllable interceptors. @@ -84,6 +92,7 @@ const ONE_HOUR_MS = 60 * 60 * 1000; function createTestContext() { vi.resetAllMocks(); + enableLocalTelemetry(); const secretStorage = new InMemorySecretStorage(); const memento = new InMemoryMemento(); @@ -136,12 +145,14 @@ function createTestContext() { }; /** Creates interceptor with optional callback */ - const createInterceptor = (onAuthRequired?: AuthRequiredHandler) => + const createInterceptor = ( + onAuthRequired?: AuthRequiredHandler, + telemetry?: TelemetryService, + ) => new AuthInterceptor( mockCoderApi, - logger, mockOAuthManager as unknown as OAuthSessionManager, - secretsManager, + createMockServiceContainer({ telemetry, logger, secretsManager }), onAuthRequired, ); @@ -182,7 +193,7 @@ describe("AuthInterceptor", () => { }); describe("401 handling with OAuth", () => { - it("refreshes token and retries request", async () => { + it("refreshes token and retries the request", async () => { const { mockCoderApi, mockOAuthManager, @@ -424,4 +435,132 @@ describe("AuthInterceptor", () => { expect(axiosInstance.getInterceptorCount()).toBe(0); }); }); + + describe("telemetry", () => { + interface RecoveryCase { + name: string; + arrange: (ctx: ReturnType) => Promise; + withCallback: boolean; + callbackResult?: boolean; + expectThrow: boolean; + expected: { + recovery: AuthRecoveryAction; + refreshAttempted: "true" | "false"; + result: "success" | "error"; + }; + } + + it.each([ + { + name: "OAuth refresh succeeds: recovery=refresh_success", + arrange: async (ctx) => { + await ctx.setupOAuthTokens(); + ctx.mockOAuthManager.refreshToken.mockResolvedValue( + createMockTokenResponse({ access_token: "new" }), + ); + vi.spyOn(ctx.axiosInstance, "request").mockResolvedValue({ + status: 200, + }); + }, + withCallback: false, + expectThrow: false, + expected: { + recovery: "refresh_success", + refreshAttempted: "true", + result: "success", + }, + }, + { + name: "no OAuth + callback declines: recovery=login_required", + arrange: () => Promise.resolve(), + withCallback: true, + callbackResult: false, + expectThrow: true, + expected: { + recovery: "login_required", + refreshAttempted: "false", + result: "error", + }, + }, + { + name: "no OAuth + no callback: recovery=none", + arrange: () => Promise.resolve(), + withCallback: false, + expectThrow: true, + expected: { + recovery: "none", + refreshAttempted: "false", + result: "error", + }, + }, + { + name: "OAuth refresh fails + callback declines: refreshAttempted=true, recovery=login_required", + arrange: async (ctx) => { + await ctx.setupOAuthTokens(); + ctx.mockOAuthManager.refreshToken.mockRejectedValue( + new Error("refresh failed"), + ); + }, + withCallback: true, + callbackResult: false, + expectThrow: true, + expected: { + recovery: "login_required", + refreshAttempted: "true", + result: "error", + }, + }, + ])( + "$name", + async ({ + arrange, + withCallback, + callbackResult, + expectThrow, + expected, + }) => { + const sink = new TestSink(); + const ctx = createTestContext(); + await arrange(ctx); + const onAuthRequired = withCallback + ? vi.fn().mockResolvedValue(callbackResult) + : undefined; + ctx.createInterceptor(onAuthRequired, createTestTelemetryService(sink)); + + const trigger = ctx.axiosInstance.triggerResponseError( + createAxiosError(401, "Unauthorized"), + ); + if (expectThrow) { + await expect(trigger).rejects.toThrow(); + } else { + await trigger; + } + + expect( + sink.expectOne("auth.unauthorized_intercepted").properties, + ).toMatchObject(expected); + }, + ); + + it("includes durationMs on the recovery span", async () => { + const sink = new TestSink(); + const ctx = createTestContext(); + await ctx.setupOAuthTokens(); + ctx.mockOAuthManager.refreshToken.mockResolvedValue( + createMockTokenResponse({ access_token: "new" }), + ); + vi.spyOn(ctx.axiosInstance, "request").mockResolvedValue({ + status: 200, + }); + ctx.createInterceptor(undefined, createTestTelemetryService(sink)); + + await ctx.axiosInstance.triggerResponseError( + createAxiosError(401, "Unauthorized"), + ); + + expect( + sink.expectOne("auth.unauthorized_intercepted").measurements.durationMs, + ).toEqual(expect.any(Number)); + }); + }); }); diff --git a/test/unit/deployment/deploymentManager.test.ts b/test/unit/deployment/deploymentManager.test.ts index 87b4872e2e..eeef697ee3 100644 --- a/test/unit/deployment/deploymentManager.test.ts +++ b/test/unit/deployment/deploymentManager.test.ts @@ -7,6 +7,7 @@ import { DeploymentManager } from "@/deployment/deploymentManager"; import { createMockLogger, + createMockServiceContainer, createMockUser, InMemoryMemento, InMemorySecretStorage, @@ -15,9 +16,8 @@ import { MockOAuthSessionManager, } from "../../mocks/testHelpers"; -import type { ServiceContainer } from "@/core/container"; -import type { ContextManager } from "@/core/contextManager"; import type { OAuthSessionManager } from "@/oauth/sessionManager"; +import type { TelemetryService } from "@/telemetry/service"; import type { WorkspaceProvider } from "@/workspace/workspacesProvider"; // Mock CoderApi.create to return our mock client for validation @@ -70,16 +70,14 @@ function createTestContext() { setDeploymentUrl: vi.fn(), }; - const container = { - getSecretsManager: () => secretsManager, - getMementoManager: () => mementoManager, - getContextManager: () => contextManager as unknown as ContextManager, - getLogger: () => logger, - getTelemetryService: () => telemetryService, - }; - const manager = DeploymentManager.create( - container as unknown as ServiceContainer, + createMockServiceContainer({ + telemetry: telemetryService as unknown as TelemetryService, + logger, + secretsManager, + mementoManager, + contextManager, + }), mockClient as unknown as CoderApi, mockOAuthSessionManager as unknown as OAuthSessionManager, [mockWorkspaceProvider as unknown as WorkspaceProvider], diff --git a/test/unit/instrumentation/ssh.test.ts b/test/unit/instrumentation/ssh.test.ts index 423a3ba9fa..a49912d166 100644 --- a/test/unit/instrumentation/ssh.test.ts +++ b/test/unit/instrumentation/ssh.test.ts @@ -2,25 +2,28 @@ import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { SshTelemetry } from "@/instrumentation/ssh"; -import { createTestTelemetryService, TestSink } from "../../mocks/telemetry"; -import { - makeNetworkInfo, - MockConfigurationProvider, -} from "../../mocks/testHelpers"; +import { createTelemetryHarness } from "../../mocks/telemetry"; +import { makeNetworkInfo } from "../../mocks/testHelpers"; function setup() { - new MockConfigurationProvider().set("coder.telemetry.level", "local"); - const sink = new TestSink(); - return { ssh: new SshTelemetry(createTestTelemetryService(sink)), sink }; + const { sink, service } = createTelemetryHarness(); + return { ssh: new SshTelemetry(service), sink }; +} + +interface DiscoveryCase { + pid: number | undefined; + attempts: number; + found: string; +} + +interface DisposedCase { + name: string; + lose: boolean; + wasLost: string; } describe("SshTelemetry", () => { describe("traceProcessDiscovery", () => { - interface DiscoveryCase { - pid: number | undefined; - attempts: number; - found: string; - } it.each([ { pid: 123, attempts: 2, found: "true" }, { pid: undefined, attempts: 5, found: "false" }, @@ -148,11 +151,6 @@ describe("SshTelemetry", () => { expect(sink.events).toHaveLength(0); }); - interface DisposedCase { - name: string; - lose: boolean; - wasLost: string; - } it.each([ { name: "from a healthy state", lose: false, wasLost: "false" }, { name: "after the process was lost", lose: true, wasLost: "true" }, diff --git a/test/unit/instrumentation/websocket.test.ts b/test/unit/instrumentation/websocket.test.ts index 01374fc856..0af7a2a7be 100644 --- a/test/unit/instrumentation/websocket.test.ts +++ b/test/unit/instrumentation/websocket.test.ts @@ -3,13 +3,11 @@ import { describe, expect, it } from "vitest"; import { WebSocketTelemetry } from "@/instrumentation/websocket"; import { ConnectionState } from "@/websocket/reconnectingWebSocket"; -import { createTestTelemetryService, TestSink } from "../../mocks/telemetry"; -import { MockConfigurationProvider } from "../../mocks/testHelpers"; +import { createTelemetryHarness } from "../../mocks/telemetry"; function setup() { - new MockConfigurationProvider().set("coder.telemetry.level", "local"); - const sink = new TestSink(); - return { ws: new WebSocketTelemetry(createTestTelemetryService(sink)), sink }; + const { sink, service } = createTelemetryHarness(); + return { ws: new WebSocketTelemetry(service), sink }; } describe("WebSocketTelemetry", () => { diff --git a/test/unit/login/loginCoordinator.test.ts b/test/unit/login/loginCoordinator.test.ts index cf376a9775..69e9c594df 100644 --- a/test/unit/login/loginCoordinator.test.ts +++ b/test/unit/login/loginCoordinator.test.ts @@ -7,12 +7,14 @@ import { SecretsManager } from "@/core/secretsManager"; import { getHeaders } from "@/headers"; import { LoginCoordinator } from "@/login/loginCoordinator"; import { OAuthCallback } from "@/oauth/oauthCallback"; -import { maybeAskAuthMethod } from "@/promptUtils"; +import { maybeAskAuthMethod, maybeAskUrl } from "@/promptUtils"; +import { createTestTelemetryService, TestSink } from "../../mocks/telemetry"; import { createAxiosError, createMockCliCredentialManager, createMockLogger, + createMockServiceContainer, createMockUser, InMemoryMemento, InMemorySecretStorage, @@ -21,6 +23,8 @@ import { MockUserInteraction, } from "../../mocks/testHelpers"; +import type { TelemetryService } from "@/telemetry/service"; + // Hoisted mock adapter implementation const mockAxiosAdapterImpl = vi.hoisted( () => (config: Record) => @@ -98,7 +102,7 @@ const TEST_HOSTNAME = "coder.example.com"; /** * Creates a fresh test context with all dependencies. */ -function createTestContext() { +function createTestContext(telemetry?: TelemetryService) { vi.resetAllMocks(); const mockAdapter = (axios as MockedAxios).__mockAdapter; @@ -121,10 +125,13 @@ function createTestContext() { const mockCredentialManager = createMockCliCredentialManager(); const coordinator = new LoginCoordinator( - secretsManager, - mementoManager, - logger, - mockCredentialManager, + createMockServiceContainer({ + telemetry, + logger, + secretsManager, + mementoManager, + cliCredentialManager: mockCredentialManager, + }), oauthCallback, "coder.coder-remote", ); @@ -153,6 +160,7 @@ function createTestContext() { mockGetAuthenticatedUser, mockConfig, userInteraction, + logger, secretsManager, oauthCallback, mementoManager, @@ -306,26 +314,10 @@ describe("LoginCoordinator", () => { }); it("logs warning instead of showing dialog for autoLogin", async () => { - const { - mockConfig, - secretsManager, - oauthCallback, - mementoManager, - mockAuthFailure, - } = createTestContext(); + const { mockConfig, logger, coordinator, mockAuthFailure } = + createTestContext(); mockConfig.set("coder.tlsCertFile", "/path/to/cert.pem"); mockConfig.set("coder.tlsKeyFile", "/path/to/key.pem"); - - const logger = createMockLogger(); - const coordinator = new LoginCoordinator( - secretsManager, - mementoManager, - logger, - createMockCliCredentialManager(), - oauthCallback, - "coder.coder-remote", - ); - mockAuthFailure("Certificate error"); const result = await coordinator.ensureLoggedIn({ @@ -353,6 +345,7 @@ describe("LoginCoordinator", () => { const result = await coordinator.ensureLoggedInWithDialog({ url: TEST_URL, safeHostname: TEST_HOSTNAME, + trigger: "auth_required", }); expect(result.success).toBe(false); @@ -544,4 +537,98 @@ describe("LoginCoordinator", () => { expect(result).toEqual({ success: true, user, token: "stored-token" }); }); }); + + describe("telemetry", () => { + const dialogOptions = (trigger: "auth_required" | "missing_session") => ({ + url: TEST_URL, + safeHostname: TEST_HOSTNAME, + trigger, + }); + + const enableMTLS = (mockConfig: MockConfigurationProvider) => { + mockConfig.set("coder.tlsCertFile", "/path/to/cert.pem"); + mockConfig.set("coder.tlsKeyFile", "/path/to/key.pem"); + }; + + interface PromptCase { + name: string; + arrange: (ctx: ReturnType) => void; + trigger: "auth_required" | "missing_session"; + expected: { + result: "success" | "aborted" | "error"; + reason?: "user_dismissed" | "no_url_provided" | "auth_failed"; + }; + } + + it.each([ + { + name: "user dismisses the dialog: aborted + user_dismissed", + arrange: (ctx) => + ctx.userInteraction.setResponse("Authentication Required", undefined), + trigger: "missing_session", + expected: { result: "aborted", reason: "user_dismissed" }, + }, + { + name: "authentication fails: error + auth_failed", + arrange: (ctx) => { + enableMTLS(ctx.mockConfig); + ctx.mockAuthFailure("Certificate error"); + vi.mocked(maybeAskUrl).mockResolvedValue(TEST_URL); + ctx.userInteraction.setResponse("Authentication Required", "Login"); + }, + trigger: "auth_required", + expected: { result: "error", reason: "auth_failed" }, + }, + { + name: "user cancels URL prompt: aborted + no_url_provided", + arrange: (ctx) => { + enableMTLS(ctx.mockConfig); + vi.mocked(maybeAskUrl).mockResolvedValue(undefined); + ctx.userInteraction.setResponse("Authentication Required", "Login"); + }, + trigger: "auth_required", + expected: { result: "aborted", reason: "no_url_provided" }, + }, + { + name: "happy path: success and no reason", + arrange: (ctx) => { + enableMTLS(ctx.mockConfig); + ctx.mockSuccessfulAuth(); + vi.mocked(maybeAskUrl).mockResolvedValue(TEST_URL); + ctx.userInteraction.setResponse("Authentication Required", "Login"); + }, + trigger: "auth_required", + expected: { result: "success" }, + }, + ])("$name", async ({ arrange, trigger, expected }) => { + const sink = new TestSink(); + const ctx = createTestContext(createTestTelemetryService(sink)); + arrange(ctx); + + await ctx.coordinator.ensureLoggedInWithDialog(dialogOptions(trigger)); + + const event = sink.expectOne("auth.login_prompted"); + expect(event.properties).toMatchObject({ trigger, ...expected }); + if (expected.reason === undefined) { + expect(event.properties.reason).toBeUndefined(); + } + expect(event.error).toBeUndefined(); + }); + + it("includes durationMs on the prompt span", async () => { + const sink = new TestSink(); + const { userInteraction, coordinator } = createTestContext( + createTestTelemetryService(sink), + ); + userInteraction.setResponse("Authentication Required", undefined); + + await coordinator.ensureLoggedInWithDialog( + dialogOptions("missing_session"), + ); + + expect( + sink.expectOne("auth.login_prompted").measurements.durationMs, + ).toEqual(expect.any(Number)); + }); + }); }); diff --git a/test/unit/oauth/sessionManager.test.ts b/test/unit/oauth/sessionManager.test.ts index 5cb1af2f23..fda3faae22 100644 --- a/test/unit/oauth/sessionManager.test.ts +++ b/test/unit/oauth/sessionManager.test.ts @@ -5,12 +5,17 @@ import { } from "axios"; import { describe, expect, it, vi } from "vitest"; -import { type SecretsManager, type SessionAuth } from "@/core/secretsManager"; +import { type SessionAuth } from "@/core/secretsManager"; import { DEFAULT_OAUTH_SCOPES } from "@/oauth/constants"; import { OAuthSessionManager } from "@/oauth/sessionManager"; import { - type createMockLogger, + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; +import { + createMockServiceContainer, setupAxiosMockRoutes, } from "../../mocks/testHelpers"; @@ -25,8 +30,8 @@ import { TEST_URL, } from "./testUtils"; -import type { ServiceContainer } from "@/core/container"; import type { Deployment } from "@/deployment/types"; +import type { TelemetryService } from "@/telemetry/service"; vi.mock("axios", async () => { const actual = await vi.importActual("axios"); @@ -58,25 +63,17 @@ const REFRESH_BUFFER_MS = 5 * 60 * 1000; // Tokens refresh 5 minutes before expi const ONE_HOUR_MS = 60 * 60 * 1000; const BACKGROUND_REFRESH_INTERVAL_MS = 5 * 60 * 1000; -function createMockServiceContainer( - secretsManager: SecretsManager, - logger: ReturnType, -): ServiceContainer { - return { - getSecretsManager: () => secretsManager, - getLogger: () => logger, - } as ServiceContainer; -} - function createTestContext(deployment: Deployment = createTestDeployment()) { vi.resetAllMocks(); const base = createBaseTestContext(); - const container = createMockServiceContainer( - base.secretsManager, - base.logger, - ); - const manager = OAuthSessionManager.create(deployment, container); + const buildContainer = (telemetry?: TelemetryService) => + createMockServiceContainer({ + secretsManager: base.secretsManager, + logger: base.logger, + telemetry, + }); + const manager = OAuthSessionManager.create(deployment, buildContainer()); /** Sets up OAuth session auth */ const setupOAuthSession = async ( @@ -102,7 +99,8 @@ function createTestContext(deployment: Deployment = createTestDeployment()) { const createManager = ( d: Deployment = deployment, onAuthRequired: () => Promise = () => Promise.resolve(), - ) => OAuthSessionManager.create(d, container, onAuthRequired); + telemetry?: TelemetryService, + ) => OAuthSessionManager.create(d, buildContainer(telemetry), onAuthRequired); /** * Sets up a complete OAuth operation test context. @@ -481,4 +479,66 @@ describe("OAuthSessionManager", () => { expect(result).toBe(true); }); }); + + describe("telemetry", () => { + const setupWithSink = async ( + tokenEndpoint: unknown = createMockTokenResponse({ access_token: "new" }), + ) => { + enableLocalTelemetry(); + const sink = new TestSink(); + const ctx = createTestContext(); + const manager = ctx.createManager( + createTestDeployment(), + () => Promise.resolve(), + createTestTelemetryService(sink), + ); + await ctx.setupForOAuthOperation({ "/oauth2/token": tokenEndpoint }); + return { manager, sink }; + }; + + it.each(["reactive", "background"] as const)( + "emits auth.token_refreshed with trigger=%s", + async (trigger) => { + const { manager, sink } = await setupWithSink(); + + await manager.refreshToken(trigger); + + const event = sink.expectOne("auth.token_refreshed"); + expect(event.properties).toMatchObject({ trigger, result: "success" }); + expect(event.measurements.durationMs).toEqual(expect.any(Number)); + }, + ); + + it("emits auth.token_refreshed with result=error when refresh fails", async () => { + const { manager, sink } = await setupWithSink( + createOAuthAxiosError("invalid_grant"), + ); + + await expect(manager.refreshToken("reactive")).rejects.toThrow(); + + const event = sink.expectOne("auth.token_refreshed"); + expect(event.properties).toMatchObject({ + trigger: "reactive", + result: "error", + }); + expect(event.measurements.durationMs).toEqual(expect.any(Number)); + }); + + it("emits auth.token_refresh.deduped for callers that join an in-flight refresh", async () => { + const { manager, sink } = await setupWithSink(); + + const [first, second] = await Promise.all([ + manager.refreshToken("background"), + manager.refreshToken("reactive"), + ]); + + expect(first).toBe(second); + expect(sink.eventsNamed("auth.token_refreshed")).toHaveLength(1); + expect( + sink.expectOne("auth.token_refresh.deduped").properties, + ).toMatchObject({ + trigger: "reactive", + }); + }); + }); }); diff --git a/test/unit/remote/sshProcess.test.ts b/test/unit/remote/sshProcess.test.ts index 5c33612d6a..4525f997c9 100644 --- a/test/unit/remote/sshProcess.test.ts +++ b/test/unit/remote/sshProcess.test.ts @@ -12,7 +12,11 @@ import { } from "@/remote/sshProcess"; import { NOOP_TELEMETRY_REPORTER } from "@/telemetry/reporter"; -import { createTestTelemetryService, TestSink } from "../../mocks/telemetry"; +import { + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; import { createMockLogger, makeNetworkInfo, @@ -44,7 +48,7 @@ describe("SshProcessMonitor", () => { statusBar = new MockStatusBarItem(); // Provide default threshold config so getThresholdConfig() works, // and enable telemetry so traces are emitted to the test sink. - new MockConfigurationProvider().set("coder.telemetry.level", "local"); + enableLocalTelemetry(); // Default: process found immediately vi.mocked(find).mockResolvedValue([ @@ -216,7 +220,7 @@ describe("SshProcessMonitor", () => { monitor.onPidChange((pid) => pids.push(pid)); // Wait for reconnection to find new PID - await waitFor(() => pids.includes(888), 200); + await waitUntil(() => pids.includes(888), { timeout: 200 }); // Should NOT fire undefined - we keep showing last status while searching expect(pids).toContain(888); @@ -346,18 +350,15 @@ describe("SshProcessMonitor", () => { it("emits found=false when discovery is abandoned by dispose", async () => { const sink = new TestSink(); const telemetry = createTestTelemetryService(sink); - vol.fromJSON({ - "/logs/ms-vscode-remote.remote-ssh/1-Remote - SSH.log": - "-> socksPort 12345 ->", - }); + vol.fromJSON(sshLog); vi.mocked(find).mockResolvedValue([]); const monitor = createMonitor({ telemetry }); - // Allow at least one discovery iteration to start, then abandon it. - await new Promise((r) => setTimeout(r, 30)); + // `find` always returns []; dispose ends the polling loop and + // finalises the span with `found: false`. monitor.dispose(); - await waitFor( + await waitUntil( () => sink.eventsNamed("ssh.process.discovered").length > 0, ); expect(sink.eventsNamed("ssh.process.discovered")[0]).toMatchObject({ @@ -398,7 +399,7 @@ describe("SshProcessMonitor", () => { telemetry, }); await waitForEvent(monitor.onPidChange); - await waitFor(() => sink.eventsNamed("ssh.process.lost").length > 0); + await waitUntil(() => sink.eventsNamed("ssh.process.lost").length > 0); monitor.dispose(); const disposed = sink.eventsNamed("ssh.process.disposed"); @@ -408,30 +409,31 @@ describe("SshProcessMonitor", () => { it("emits missing_network_info as the loss cause when reads fail repeatedly", async () => { vi.useFakeTimers(); - const sink = new TestSink(); - const telemetry = createTestTelemetryService(sink); - vol.fromJSON(sshLog); - // No /network/999.json. Every read fails until threshold is reached. - vi.mocked(find).mockResolvedValue([ - { pid: 999, ppid: 1, name: "ssh", cmd: "ssh" }, - ]); - - const monitor = createMonitor({ - networkInfoPath: "/network", - networkPollInterval: 10, - telemetry, - }); + try { + const sink = new TestSink(); + const telemetry = createTestTelemetryService(sink); + vol.fromJSON(sshLog); + // No /network/999.json. Every read fails until threshold is reached. + vi.mocked(find).mockResolvedValue([ + { pid: 999, ppid: 1, name: "ssh", cmd: "ssh" }, + ]); - await vi.advanceTimersByTimeAsync(500); - await vi.waitFor(() => - expect(sink.eventsNamed("ssh.process.lost").length).toBeGreaterThan(0), - ); + const monitor = createMonitor({ + networkInfoPath: "/network", + networkPollInterval: 10, + telemetry, + }); - expect(sink.eventsNamed("ssh.process.lost")[0].properties).toMatchObject({ - cause: "missing_network_info", - }); + await vi.advanceTimersByTimeAsync(500); + expect(sink.eventsNamed("ssh.process.lost").length).toBeGreaterThan(0); + expect( + sink.eventsNamed("ssh.process.lost")[0].properties, + ).toMatchObject({ cause: "missing_network_info" }); - monitor.dispose(); + monitor.dispose(); + } finally { + vi.useRealTimers(); + } }); it("emits ssh.process.replaced (not recovered) when a different PID takes over", async () => { @@ -451,7 +453,9 @@ describe("SshProcessMonitor", () => { telemetry, }); await waitForEvent(monitor.onPidChange); - await waitFor(() => sink.eventsNamed("ssh.process.replaced").length > 0); + await waitUntil( + () => sink.eventsNamed("ssh.process.replaced").length > 0, + ); // Halt monitoring before the negative assertion so the 888 loop // can't race ahead and emit its own lost/recovered cycle. monitor.dispose(); @@ -482,7 +486,7 @@ describe("SshProcessMonitor", () => { telemetry, }); await waitForEvent(monitor.onPidChange); - await waitFor( + await waitUntil( () => sink.eventsNamed("ssh.process.lost").length > 0 && sink.eventsNamed("ssh.process.recovered").length > 0, @@ -511,7 +515,7 @@ describe("SshProcessMonitor", () => { networkPollInterval: 10, telemetry, }); - await waitFor(() => sink.eventsNamed("ssh.network.sampled").length > 0); + await waitUntil(() => sink.eventsNamed("ssh.network.sampled").length > 0); expect(sink.eventsNamed("ssh.network.sampled")[0]).toMatchObject({ properties: { p2p: "true", preferredDerp: "NYC" }, @@ -643,7 +647,7 @@ describe("SshProcessMonitor", () => { codeLogDir: "/logs/window1", networkInfoPath: "/network", }); - await waitFor(() => statusBar.text.includes("Direct")); + await waitUntil(() => statusBar.text.includes("Direct")); expect(statusBar.text).toContain("Direct"); expect(statusBar.text).toContain("25.50ms"); @@ -665,7 +669,7 @@ describe("SshProcessMonitor", () => { codeLogDir: "/logs/window1", networkInfoPath: "/network", }); - await waitFor(() => statusBar.text.includes("SFO")); + await waitUntil(() => statusBar.text.includes("SFO")); expect(statusBar.text).toContain("SFO"); expect(tooltipText()).toContain("relay"); @@ -682,7 +686,7 @@ describe("SshProcessMonitor", () => { codeLogDir: "/logs/window1", networkInfoPath: "/network", }); - await waitFor(() => statusBar.text.includes("Coder Connect")); + await waitUntil(() => statusBar.text.includes("Coder Connect")); expect(statusBar.text).toContain("Coder Connect"); }); @@ -1002,10 +1006,9 @@ describe("SshProcessMonitor", () => { ); startWithNetwork({ latency: 200 }); - await waitFor( - () => statusBar.backgroundColor instanceof ThemeColor, - 2000, - ); + await waitUntil(() => statusBar.backgroundColor instanceof ThemeColor, { + timeout: 2000, + }); expect(statusBar.command).toBe("coder.pingWorkspace"); }); }); @@ -1046,6 +1049,18 @@ function mockReaddirOrder(dirPath: string, files: string[]): void { ); } +/** Poll `cond` via `vi.waitFor` until it returns truthy. */ +async function waitUntil( + cond: () => boolean, + options?: { timeout?: number }, +): Promise { + await vi.waitFor(() => { + if (!cond()) { + throw new Error("waitUntil: condition not met"); + } + }, options); +} + /** Wait for a VS Code event to fire once */ function waitForEvent( event: (listener: (e: T) => void) => { dispose(): void }, @@ -1064,18 +1079,3 @@ function waitForEvent( }); }); } - -/** Poll for a condition to become true */ -async function waitFor( - condition: () => boolean, - timeout = 1000, - interval = 5, -): Promise { - const start = Date.now(); - while (!condition()) { - if (Date.now() - start > timeout) { - throw new Error(`waitFor timed out after ${timeout}ms`); - } - await new Promise((r) => setTimeout(r, interval)); - } -} diff --git a/test/unit/remote/workspaceStateMachine.test.ts b/test/unit/remote/workspaceStateMachine.test.ts index fb82c42b81..fe96e5f340 100644 --- a/test/unit/remote/workspaceStateMachine.test.ts +++ b/test/unit/remote/workspaceStateMachine.test.ts @@ -17,8 +17,14 @@ import { workspace as createWorkspace, } from "@repo/mocks"; +import { + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; import { createMockLogger, + createMockServiceContainer, MockProgress, MockTerminalOutputChannel, MockUserInteraction, @@ -32,6 +38,7 @@ import type { import type { CoderApi } from "@/api/coderApi"; import type { StartupMode } from "@/core/mementoManager"; import type { FeatureSet } from "@/featureSet"; +import type { TelemetryService } from "@/telemetry/service"; import type { AuthorityParts } from "@/util"; vi.mock("@/api/workspace", async (importActual) => { @@ -77,7 +84,11 @@ function runningWorkspace( }); } -function setup(startupMode: StartupMode = "start") { +function setup( + startupMode: StartupMode = "start", + telemetry?: TelemetryService, +) { + enableLocalTelemetry(); const progress = new MockProgress<{ message?: string }>(); const userInteraction = new MockUserInteraction(); const sm = new WorkspaceStateMachine( @@ -86,8 +97,8 @@ function setup(startupMode: StartupMode = "start") { startupMode, "/usr/bin/coder", {} as FeatureSet, - createMockLogger(), { mode: "url", url: "https://test.coder.com" }, + createMockServiceContainer({ telemetry, logger: createMockLogger() }), ); return { sm, progress, userInteraction }; } @@ -370,6 +381,136 @@ describe("WorkspaceStateMachine", () => { } }); + describe("telemetry", () => { + const stoppedWorkspace = () => + createWorkspace({ latest_build: { status: "stopped" } }); + + it.each<{ + name: string; + eventName: "workspace.start.triggered" | "workspace.update.triggered"; + mode: StartupMode; + workspace: () => Workspace; + mock: typeof startWorkspace | typeof updateWorkspace; + }>([ + { + name: "workspace.start.triggered on stopped workspace", + eventName: "workspace.start.triggered", + mode: "start", + workspace: stoppedWorkspace, + mock: startWorkspace, + }, + { + name: "workspace.update.triggered on running workspace in update mode", + eventName: "workspace.update.triggered", + mode: "update", + workspace: runningWorkspace, + mock: updateWorkspace, + }, + ])( + "emits $name with duration on success", + async ({ eventName, mode, workspace, mock }) => { + const sink = new TestSink(); + const { sm, progress } = setup(mode, createTestTelemetryService(sink)); + + await sm.processWorkspace(workspace(), progress); + + expect(mock).toHaveBeenCalledOnce(); + const event = sink.expectOne(eventName); + expect(event.properties.result).toBe("success"); + expect(event.measurements.durationMs).toEqual(expect.any(Number)); + }, + ); + + it("emits result=error when the triggered action throws", async () => { + const sink = new TestSink(); + const { sm, progress } = setup( + "update", + createTestTelemetryService(sink), + ); + vi.mocked(updateWorkspace).mockRejectedValueOnce( + new Error("update failed"), + ); + + // The state machine catches the failure and falls back to the + // existing template version, so processWorkspace resolves. + await sm.processWorkspace(runningWorkspace(), progress); + + const event = sink.expectOne("workspace.update.triggered"); + expect(event.properties.result).toBe("error"); + expect(event.error).toEqual({ message: "update failed" }); + }); + + it("emits agent state transitions with observed duration", async () => { + const sink = new TestSink(); + const { sm, progress } = setup("start", createTestTelemetryService(sink)); + + await sm.processWorkspace( + runningWorkspace({ status: "connecting", lifecycle_state: "created" }), + progress, + ); + await sm.processWorkspace(runningWorkspace(), progress); + + const events = sink.eventsNamed("workspace.agent.state_transitioned"); + expect(events).toHaveLength(2); + expect(events[0].properties).toMatchObject({ + fromStatus: "none", + toStatus: "connecting", + fromLifecycleState: "none", + toLifecycleState: "created", + }); + expect(events[1].properties).toMatchObject({ + fromStatus: "connecting", + toStatus: "connected", + fromLifecycleState: "created", + toLifecycleState: "ready", + }); + expect(events[1].measurements.observedDurationMs).toEqual( + expect.any(Number), + ); + }); + + it("resets agent telemetry on restart so the next transition emits from 'none'", async () => { + const sink = new TestSink(); + const { sm, progress } = setup("start", createTestTelemetryService(sink)); + + // The build log stream is closed when we return to running; give the + // mock something disposable so close() doesn't blow up. + vi.mocked(streamBuildLogs).mockResolvedValueOnce({ + close: vi.fn(), + } as never); + + // Establish a baseline: connected/ready. + await sm.processWorkspace(runningWorkspace(), progress); + + // Workspace enters a build state; resetAgent fires. + await sm.processWorkspace( + createWorkspace({ latest_build: { status: "stopping" } }), + progress, + ); + + // Next agent observation must restart from "none", not the prior baseline. + await sm.processWorkspace( + runningWorkspace({ status: "connecting", lifecycle_state: "created" }), + progress, + ); + + const events = sink.eventsNamed("workspace.agent.state_transitioned"); + expect(events).toHaveLength(2); + expect(events[0].properties).toMatchObject({ + fromStatus: "none", + toStatus: "connected", + fromLifecycleState: "none", + toLifecycleState: "ready", + }); + expect(events[1].properties).toMatchObject({ + fromStatus: "none", + toStatus: "connecting", + fromLifecycleState: "none", + toLifecycleState: "created", + }); + }); + }); + describe("agent selection", () => { it("throws when user declines agent selection", async () => { vi.mocked(maybeAskAgent).mockResolvedValue(undefined); diff --git a/test/unit/telemetry/service.test.ts b/test/unit/telemetry/service.test.ts index 97a030777f..ba0934175b 100644 --- a/test/unit/telemetry/service.test.ts +++ b/test/unit/telemetry/service.test.ts @@ -124,12 +124,7 @@ describe("TelemetryService", () => { }); it("forwards caller measurements alongside the framework-set durationMs", async () => { - await h.service.trace( - "auth.token_refresh", - () => Promise.resolve(), - {}, - { attempts: 2 }, - ); + await h.service.trace("op", () => Promise.resolve(), {}, { attempts: 2 }); const [event] = h.sink.events; expect(event.measurements.attempts).toBe(2); @@ -305,6 +300,7 @@ describe("TelemetryService", () => { escapedSpan?.setProperty("late", "ignored"); escapedSpan?.setMeasurement("lateMs", 99); escapedSpan?.markAborted(); + escapedSpan?.markFailure(); // Mutations dropped: emitted event is unchanged. expect(h.sink.events[0].properties.late).toBeUndefined(); @@ -312,7 +308,7 @@ describe("TelemetryService", () => { expect(h.sink.events[0].properties.result).toBe("success"); // Each post-emit mutation logs a warning. - expect(vi.mocked(h.logger.warn).mock.calls.length).toBe(warnBefore + 3); + expect(vi.mocked(h.logger.warn).mock.calls.length).toBe(warnBefore + 4); expect(vi.mocked(h.logger.warn).mock.calls[warnBefore][0]).toContain( "setProperty", ); @@ -322,6 +318,9 @@ describe("TelemetryService", () => { expect(vi.mocked(h.logger.warn).mock.calls[warnBefore + 2][0]).toContain( "markAborted", ); + expect(vi.mocked(h.logger.warn).mock.calls[warnBefore + 3][0]).toContain( + "markFailure", + ); }); it("markAborted flips result to 'aborted' on normal return", async () => { @@ -352,6 +351,45 @@ describe("TelemetryService", () => { }); }); + it("markFailure flips result to 'error' on normal return without an error block", async () => { + await h.service.trace("op", (span) => { + span.markFailure(); + return Promise.resolve(); + }); + + expect(h.sink.events[0]).toMatchObject({ + eventName: "op", + properties: { result: "error" }, + }); + expect(h.sink.events[0].error).toBeUndefined(); + }); + + it("markFailure overrides markAborted (failure wins over abort)", async () => { + await h.service.trace("op", (span) => { + span.markAborted(); + span.markFailure(); + return Promise.resolve(); + }); + + expect(h.sink.events[0].properties.result).toBe("error"); + }); + + it("thrown errors take precedence over markFailure (error block is preserved)", async () => { + const boom = new Error("kaboom"); + await expect( + h.service.trace("op", (span) => { + span.markFailure(); + return Promise.reject(boom); + }), + ).rejects.toBe(boom); + + expect(h.sink.events[0]).toMatchObject({ + eventName: "op", + properties: { result: "error" }, + error: { message: "kaboom" }, + }); + }); + it("on phase failure: completed phases emit success, parent emits an error summary, error rethrown, later phases never run", async () => { const boom = new Error("phase-2-broke"); diff --git a/test/unit/websocket/reconnectingWebSocket.test.ts b/test/unit/websocket/reconnectingWebSocket.test.ts index bfc87936ee..769625ab4c 100644 --- a/test/unit/websocket/reconnectingWebSocket.test.ts +++ b/test/unit/websocket/reconnectingWebSocket.test.ts @@ -11,11 +11,12 @@ import { type SocketFactory, } from "@/websocket/reconnectingWebSocket"; -import { createTestTelemetryService, TestSink } from "../../mocks/telemetry"; import { - createMockLogger, - MockConfigurationProvider, -} from "../../mocks/testHelpers"; + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; +import { createMockLogger } from "../../mocks/testHelpers"; import type { CloseEvent, Event as WsEvent } from "ws"; @@ -594,8 +595,11 @@ describe("ReconnectingWebSocket", () => { }); describe("Telemetry wiring", () => { + beforeEach(() => { + enableLocalTelemetry(); + }); + it("walks the state machine through a full reconnect lifecycle", async () => { - new MockConfigurationProvider().set("coder.telemetry.level", "local"); const sink = new TestSink(); const telemetry = createTestTelemetryService(sink); const { ws, sockets } = await createReconnectingWebSocket({ telemetry }); @@ -641,7 +645,6 @@ describe("ReconnectingWebSocket", () => { }); it("emits a normal-close drop and disconnects on server-initiated close", async () => { - new MockConfigurationProvider().set("coder.telemetry.level", "local"); const sink = new TestSink(); const telemetry = createTestTelemetryService(sink); const { ws, sockets } = await createReconnectingWebSocket({ telemetry }); @@ -669,7 +672,6 @@ describe("ReconnectingWebSocket", () => { }); it("records certificate_refresh as the reconnect reason on successful refresh", async () => { - new MockConfigurationProvider().set("coder.telemetry.level", "local"); const sink = new TestSink(); const telemetry = createTestTelemetryService(sink); const sockets: MockSocket[] = []; diff --git a/test/unit/workspace/workspaceMonitor.test.ts b/test/unit/workspace/workspaceMonitor.test.ts index fb2b9cc710..feee1aa035 100644 --- a/test/unit/workspace/workspaceMonitor.test.ts +++ b/test/unit/workspace/workspaceMonitor.test.ts @@ -6,6 +6,12 @@ import { WorkspaceMonitor } from "@/workspace/workspaceMonitor"; import { workspace as createWorkspace } from "@repo/mocks"; import { + createTestTelemetryService, + enableLocalTelemetry, + TestSink, +} from "../../mocks/telemetry"; +import { + createMockServiceContainer, MockConfigurationProvider, MockContextManager, MockEventStream, @@ -19,7 +25,7 @@ import type { } from "coder/site/src/api/typesGenerated"; import type { CoderApi } from "@/api/coderApi"; -import type { ContextManager } from "@/core/contextManager"; +import type { TelemetryService } from "@/telemetry/service"; function workspaceEvent( overrides?: Parameters[0], @@ -36,7 +42,11 @@ describe("WorkspaceMonitor", () => { vi.resetAllMocks(); }); - async function setup(stream = new MockEventStream()) { + async function setup( + stream = new MockEventStream(), + telemetry?: TelemetryService, + initialWorkspace: Workspace = createWorkspace(), + ) { const config = new MockConfigurationProvider(); const statusBar = new MockStatusBarItem(); const contextManager = new MockContextManager(); @@ -50,14 +60,139 @@ describe("WorkspaceMonitor", () => { }), } as unknown as CoderApi; const monitor = await WorkspaceMonitor.create( - createWorkspace(), + initialWorkspace, client, - createMockLogger(), - contextManager as unknown as ContextManager, + createMockServiceContainer({ + telemetry, + logger: createMockLogger(), + contextManager, + }), ); return { monitor, client, stream, config, statusBar, contextManager }; } + describe("telemetry", () => { + const buildSinkContext = () => { + enableLocalTelemetry(); + return { + stream: new MockEventStream(), + sink: new TestSink(), + }; + }; + + it("emits initial state plus subsequent transitions with duration", async () => { + const { stream, sink } = buildSinkContext(); + + await setup( + stream, + createTestTelemetryService(sink), + createWorkspace({ latest_build: { status: "running" } }), + ); + stream.pushMessage( + workspaceEvent({ + latest_build: { + status: "stopping", + transition: "stop", + reason: "autostop", + }, + }), + ); + + const events = sink.eventsNamed("workspace.state_transitioned"); + expect(events).toHaveLength(2); + expect(events[0].properties).toMatchObject({ + from: "none", + to: "running", + }); + expect(events[0].measurements.observedDurationMs).toBeUndefined(); + expect(events[1]).toMatchObject({ + properties: { + from: "running", + to: "stopping", + transition: "stop", + reason: "autostop", + }, + measurements: { observedDurationMs: expect.any(Number) }, + }); + }); + + it("dedupes on (status, transition, reason); re-emits when only reason changes", async () => { + const { stream, sink } = buildSinkContext(); + + await setup( + stream, + createTestTelemetryService(sink), + createWorkspace({ + latest_build: { + status: "stopping", + transition: "stop", + reason: "autostop", + }, + }), + ); + // Same status with a different reason: must not dedupe. + stream.pushMessage( + workspaceEvent({ + latest_build: { + status: "stopping", + transition: "stop", + reason: "initiator", + }, + }), + ); + // Identical to the previous: deduped. + stream.pushMessage( + workspaceEvent({ + latest_build: { + status: "stopping", + transition: "stop", + reason: "initiator", + }, + }), + ); + + const reasons = sink + .eventsNamed("workspace.state_transitioned") + .map((e) => e.properties.reason); + expect(reasons).toEqual(["autostop", "initiator"]); + }); + + it("emits observedBuildDurationMs on the event that resolves a build run", async () => { + const { stream, sink } = buildSinkContext(); + + await setup( + stream, + createTestTelemetryService(sink), + createWorkspace({ latest_build: { status: "pending" } }), + ); + stream.pushMessage( + workspaceEvent({ latest_build: { status: "starting" } }), + ); + stream.pushMessage( + workspaceEvent({ latest_build: { status: "running" } }), + ); + stream.pushMessage( + workspaceEvent({ latest_build: { status: "stopping" } }), + ); + + const events = sink.eventsNamed("workspace.state_transitioned"); + // pending and starting are intermediate; only running carries observedBuildDurationMs. + expect(events.map((e) => e.properties.to)).toEqual([ + "pending", + "starting", + "running", + "stopping", + ]); + expect(events[0].measurements.observedBuildDurationMs).toBeUndefined(); + expect(events[1].measurements.observedBuildDurationMs).toBeUndefined(); + expect(events[2].measurements.observedBuildDurationMs).toEqual( + expect.any(Number), + ); + // Next build cycle resets; stopping doesn't carry the previous duration. + expect(events[3].measurements.observedBuildDurationMs).toBeUndefined(); + }); + }); + describe("websocket lifecycle", () => { it("fires onChange when a workspace message arrives", async () => { const { monitor, stream } = await setup();