diff --git a/CHANGELOG.md b/CHANGELOG.md index ad5ef218b9..3e52bcd579 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,20 +13,18 @@ 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. ### Fixed diff --git a/src/api/authInterceptor.ts b/src/api/authInterceptor.ts index d362c1d12e..9fc71148ab 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,63 @@ 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); + // TODO(#925): emit a correlated received-log here once Span.log() lands. + return this.authTelemetry.traceAuthRecovery(async (recorder) => { + // 1) OAuth refresh path. + const isOAuth = + await this.oauthSessionManager.isLoggedInWithOAuth(hostname); + recorder.setRefreshAttempted(isOAuth); + if (isOAuth) { + const newToken = await this.tryOAuthRefresh(); + if (newToken) { + recorder.setRecovery("refresh_success"); + return this.retryRequest(error, newToken); } } - } - if (this.onAuthRequired) { + // 2) Interactive re-auth fallback. + if (!this.onAuthRequired) { + recorder.setRecovery("none"); + throw error; + } + recorder.setRecovery("login_required"); const success = await this.executeAuthRequired(hostname); - if (success) { - const auth = await this.secretsManager.getSessionAuth(hostname); - if (auth) { - this.logger.debug("Re-authentication successful, retrying request"); - return this.retryRequest(error, auth.token); - } + const auth = success + ? await this.secretsManager.getSessionAuth(hostname) + : undefined; + if (!auth) { + throw error; } - } + this.logger.debug("Re-authentication successful, retrying request"); + return this.retryRequest(error, auth.token); + }); + } - 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..8586869249 100644 --- a/src/core/container.ts +++ b/src/core/container.ts @@ -1,6 +1,7 @@ import * as vscode from "vscode"; import { CoderApi } from "../api/coderApi"; +import { AuthTelemetry } from "../instrumentation/auth"; import { LoginCoordinator } from "../login/loginCoordinator"; import { OAuthCallback } from "../oauth/oauthCallback"; import { buildSession, extractExtensionVersion } from "../telemetry/event"; @@ -103,6 +104,7 @@ export class ServiceContainer implements vscode.Disposable { this.mementoManager, this.logger, this.cliCredentialManager, + new AuthTelemetry(this.telemetryService), 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..15e8ffcfd1 --- /dev/null +++ b/src/instrumentation/auth.ts @@ -0,0 +1,81 @@ +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"; + +export type LoginPromptReason = + | "user_dismissed" + | "no_url_provided" + | "auth_failed"; + +export type LoginPromptOutcome = + | { success: true } + | { success: false; reason: LoginPromptReason }; + +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 logTokenRefreshDeduped(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/login/loginCoordinator.ts b/src/login/loginCoordinator.ts index 018d9558ee..67dc5693ed 100644 --- a/src/login/loginCoordinator.ts +++ b/src/login/loginCoordinator.ts @@ -18,11 +18,16 @@ import type { CliCredentialManager } from "../core/cliCredentialManager"; import type { MementoManager } from "../core/mementoManager"; import type { OAuthTokenData, SecretsManager } from "../core/secretsManager"; import type { Deployment } from "../deployment/types"; +import type { + AuthLoginPromptTrigger, + AuthTelemetry, + LoginPromptReason, +} from "../instrumentation/auth"; 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 { @@ -44,6 +49,7 @@ export class LoginCoordinator implements vscode.Disposable { private readonly mementoManager: MementoManager, private readonly logger: Logger, private readonly cliCredentialManager: CliCredentialManager, + private readonly authTelemetry: AuthTelemetry, oauthCallback: OAuthCallback, extensionId: string, ) { @@ -79,7 +85,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 +115,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 +126,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 +138,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 +307,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 +320,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 +341,7 @@ export class LoginCoordinator implements vscode.Disposable { return "unauthorized"; } this.showAuthError(err, isAutoLogin); - return { success: false }; + return { success: false, reason: "auth_failed" }; } } @@ -406,7 +423,7 @@ export class LoginCoordinator implements vscode.Disposable { return { success: true, user, token: validatedToken ?? "" }; } - return { success: false }; + return { success: false, reason: "user_dismissed" }; } /** @@ -446,7 +463,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..2357fb0ae7 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.logTokenRefreshDeduped(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..15adbfd9de 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -223,9 +223,8 @@ export class Remote { // 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; @@ -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/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..06b4558968 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 stringifyProps = ( + 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, + stringifyProps(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, + stringifyProps(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, + stringifyProps(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, + stringifyProps(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..06b69ca69e 100644 --- a/src/telemetry/span.ts +++ b/src/telemetry/span.ts @@ -1,4 +1,10 @@ -import type { CallerMeasurements, CallerProperties } from "./event"; +import type { + CallerMeasurements, + CallerProperties, + CallerPropertyValue, +} from "./event"; + +export type SpanResult = "success" | "aborted" | "error"; /** * Parent span handle. Children's `eventName` composes as `${parent.eventName}.${phaseName}`. @@ -17,11 +23,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 +41,7 @@ export const NOOP_SPAN: Span = { return fn(NOOP_SPAN); }, markAborted: () => undefined, + markFailure: () => undefined, setProperty: () => undefined, setMeasurement: () => undefined, }; 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..25c087ecab 100644 --- a/test/unit/deployment/deploymentManager.test.ts +++ b/test/unit/deployment/deploymentManager.test.ts @@ -5,18 +5,19 @@ import { MementoManager } from "@/core/mementoManager"; import { SecretsManager } from "@/core/secretsManager"; import { DeploymentManager } from "@/deployment/deploymentManager"; +import { createTestTelemetryService } from "../../mocks/telemetry"; import { createMockLogger, + createMockServiceContainer, createMockUser, InMemoryMemento, InMemorySecretStorage, MockCoderApi, + MockConfigurationProvider, MockContextManager, MockOAuthSessionManager, } from "../../mocks/testHelpers"; -import type { ServiceContainer } from "@/core/container"; -import type { ContextManager } from "@/core/contextManager"; import type { OAuthSessionManager } from "@/oauth/sessionManager"; import type { WorkspaceProvider } from "@/workspace/workspacesProvider"; @@ -48,6 +49,7 @@ const TEST_HOSTNAME = "coder.example.com"; */ function createTestContext() { vi.resetAllMocks(); + new MockConfigurationProvider(); const mockClient = new MockCoderApi(); // For setDeploymentIfValid, we use a separate mock for validation @@ -66,20 +68,17 @@ function createTestContext() { validationMockClient as unknown as CoderApi, ); - const telemetryService = { - setDeploymentUrl: vi.fn(), - }; - - const container = { - getSecretsManager: () => secretsManager, - getMementoManager: () => mementoManager, - getContextManager: () => contextManager as unknown as ContextManager, - getLogger: () => logger, - getTelemetryService: () => telemetryService, - }; + const telemetryService = createTestTelemetryService(); + const setDeploymentUrlSpy = vi.spyOn(telemetryService, "setDeploymentUrl"); const manager = DeploymentManager.create( - container as unknown as ServiceContainer, + createMockServiceContainer({ + telemetry: telemetryService, + logger, + secretsManager, + mementoManager, + contextManager, + }), mockClient as unknown as CoderApi, mockOAuthSessionManager as unknown as OAuthSessionManager, [mockWorkspaceProvider as unknown as WorkspaceProvider], @@ -93,6 +92,7 @@ function createTestContext() { mockOAuthSessionManager, mockWorkspaceProvider, telemetryService, + setDeploymentUrlSpy, manager, }; } @@ -165,7 +165,7 @@ describe("DeploymentManager", () => { }); it("notifies telemetry of the deployment URL", async () => { - const { telemetryService, manager } = createTestContext(); + const { setDeploymentUrlSpy, manager } = createTestContext(); await manager.setDeployment({ url: TEST_URL, @@ -174,7 +174,7 @@ describe("DeploymentManager", () => { user: createMockUser(), }); - expect(telemetryService.setDeploymentUrl).toHaveBeenCalledWith(TEST_URL); + expect(setDeploymentUrlSpy).toHaveBeenCalledWith(TEST_URL); }); it("sets isOwner context when user has owner role", async () => { @@ -405,7 +405,7 @@ describe("DeploymentManager", () => { }); it("resets the telemetry deployment URL on clearDeployment", async () => { - const { telemetryService, manager } = createTestContext(); + const { setDeploymentUrlSpy, manager } = createTestContext(); await manager.setDeployment({ url: TEST_URL, @@ -415,7 +415,7 @@ describe("DeploymentManager", () => { }); await manager.clearDeployment(); - expect(telemetryService.setDeploymentUrl).toHaveBeenLastCalledWith(""); + expect(setDeploymentUrlSpy).toHaveBeenLastCalledWith(""); }); }); 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..92d99c1a4a 100644 --- a/test/unit/login/loginCoordinator.test.ts +++ b/test/unit/login/loginCoordinator.test.ts @@ -5,10 +5,12 @@ import * as vscode from "vscode"; import { MementoManager } from "@/core/mementoManager"; import { SecretsManager } from "@/core/secretsManager"; import { getHeaders } from "@/headers"; +import { AuthTelemetry } from "@/instrumentation/auth"; 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, @@ -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; @@ -120,11 +124,15 @@ function createTestContext() { const mementoManager = new MementoManager(memento); const mockCredentialManager = createMockCliCredentialManager(); + const authTelemetry = new AuthTelemetry( + telemetry ?? createTestTelemetryService(), + ); const coordinator = new LoginCoordinator( secretsManager, mementoManager, logger, mockCredentialManager, + authTelemetry, oauthCallback, "coder.coder-remote", ); @@ -153,6 +161,7 @@ function createTestContext() { mockGetAuthenticatedUser, mockConfig, userInteraction, + logger, secretsManager, oauthCallback, mementoManager, @@ -306,26 +315,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 +346,7 @@ describe("LoginCoordinator", () => { const result = await coordinator.ensureLoggedInWithDialog({ url: TEST_URL, safeHostname: TEST_HOSTNAME, + trigger: "auth_required", }); expect(result.success).toBe(false); @@ -544,4 +538,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/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[] = [];