diff --git a/src/configWatcher.ts b/src/configWatcher.ts index ee63f4489f..cc026c9087 100644 --- a/src/configWatcher.ts +++ b/src/configWatcher.ts @@ -8,16 +8,18 @@ export interface WatchedSetting { /** * Watch for configuration changes and invoke a callback when values change. + * The callback receives a map of changed settings to their new values, so + * consumers can act on the new value without re-reading the configuration. * Only fires when actual values change, not just when settings are touched. */ export function watchConfigurationChanges( settings: WatchedSetting[], - onChange: (changedSettings: string[]) => void, + onChange: (changes: ReadonlyMap) => void, ): vscode.Disposable { const appliedValues = new Map(settings.map((s) => [s.setting, s.getValue()])); return vscode.workspace.onDidChangeConfiguration((e) => { - const changedSettings: string[] = []; + const changes = new Map(); for (const { setting, getValue } of settings) { if (!e.affectsConfiguration(setting)) { @@ -27,13 +29,13 @@ export function watchConfigurationChanges( const newValue = getValue(); if (!configValuesEqual(newValue, appliedValues.get(setting))) { - changedSettings.push(setting); + changes.set(setting, newValue); appliedValues.set(setting, newValue); } } - if (changedSettings.length > 0) { - onChange(changedSettings); + if (changes.size > 0) { + onChange(changes); } }); } diff --git a/src/core/container.ts b/src/core/container.ts index 330ad8969f..8593460521 100644 --- a/src/core/container.ts +++ b/src/core/container.ts @@ -3,6 +3,7 @@ import * as vscode from "vscode"; import { CoderApi } from "../api/coderApi"; import { LoginCoordinator } from "../login/loginCoordinator"; import { OAuthCallback } from "../oauth/oauthCallback"; +import { TelemetryService } from "../telemetry/service"; import { SpeedtestPanelFactory } from "../webviews/speedtest/speedtestPanelFactory"; import { DuplicateWorkspaceIpc } from "../workspace/duplicateWorkspaceIpc"; @@ -31,6 +32,7 @@ export class ServiceContainer implements vscode.Disposable { private readonly duplicateWorkspaceIpc: DuplicateWorkspaceIpc; private readonly oauthCallback: OAuthCallback; private readonly speedtestPanelFactory: SpeedtestPanelFactory; + private readonly telemetryService: TelemetryService; constructor(context: vscode.ExtensionContext) { this.logger = vscode.window.createOutputChannel("Coder", { log: true }); @@ -88,6 +90,7 @@ export class ServiceContainer implements vscode.Disposable { context.extensionUri, this.logger, ); + this.telemetryService = new TelemetryService(context, [], this.logger); } getPathResolver(): PathResolver { @@ -134,12 +137,18 @@ export class ServiceContainer implements vscode.Disposable { return this.speedtestPanelFactory; } - /** - * Dispose of all services and clean up resources. - */ - dispose(): void { + getTelemetryService(): TelemetryService { + return this.telemetryService; + } + + /** Dispose logger last so telemetry teardown warnings still reach it. */ + async dispose(): Promise { this.contextManager.dispose(); - this.logger.dispose(); this.loginCoordinator.dispose(); + try { + await this.telemetryService.dispose(); + } finally { + this.logger.dispose(); + } } } diff --git a/src/deployment/deploymentManager.ts b/src/deployment/deploymentManager.ts index 9eaf2ccf35..adb732a0fc 100644 --- a/src/deployment/deploymentManager.ts +++ b/src/deployment/deploymentManager.ts @@ -5,6 +5,7 @@ import { type MementoManager } from "../core/mementoManager"; import { type SecretsManager } from "../core/secretsManager"; import { type Logger } from "../logging/logger"; import { type OAuthSessionManager } from "../oauth/sessionManager"; +import { type TelemetryService } from "../telemetry/service"; import { type WorkspaceProvider } from "../workspace/workspacesProvider"; import { @@ -33,6 +34,7 @@ export class DeploymentManager implements vscode.Disposable { private readonly mementoManager: MementoManager; private readonly contextManager: ContextManager; private readonly logger: Logger; + private readonly telemetryService: TelemetryService; #deployment: Deployment | null = null; #authListenerDisposable: vscode.Disposable | undefined; @@ -48,6 +50,7 @@ export class DeploymentManager implements vscode.Disposable { this.mementoManager = serviceContainer.getMementoManager(); this.contextManager = serviceContainer.getContextManager(); this.logger = serviceContainer.getLogger(); + this.telemetryService = serviceContainer.getTelemetryService(); } public static create( @@ -124,6 +127,7 @@ export class DeploymentManager implements vscode.Disposable { user: deployment.user.username, }); this.#deployment = { ...deployment }; + this.telemetryService.setDeploymentUrl(deployment.url); // Updates client credentials if (deployment.token === undefined) { @@ -155,6 +159,7 @@ export class DeploymentManager implements vscode.Disposable { this.#authListenerDisposable?.dispose(); this.#authListenerDisposable = undefined; this.#deployment = null; + this.telemetryService.setDeploymentUrl(""); await this.secretsManager.setCurrentDeployment(undefined); } diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 240afe65f3..0f8714d5b5 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -861,8 +861,8 @@ export class Remote { ): vscode.Disposable { const titleMap = new Map(settings.map((s) => [s.setting, s.title])); - return watchConfigurationChanges(settings, (changedSettings) => { - const changedTitles = changedSettings + return watchConfigurationChanges(settings, (changes) => { + const changedTitles = [...changes.keys()] .map((s) => titleMap.get(s)) .filter((t) => t !== undefined); diff --git a/src/telemetry/event.ts b/src/telemetry/event.ts new file mode 100644 index 0000000000..068b6c0148 --- /dev/null +++ b/src/telemetry/event.ts @@ -0,0 +1,107 @@ +import * as os from "node:os"; +import * as vscode from "vscode"; + +import { toError } from "../error/errorUtils"; + +/** Telemetry level, mirrors `coder.telemetry.level`. Ordered: off < local. */ +export type TelemetryLevel = "off" | "local"; + +/** Caller properties. `result` is framework-managed on traced events. */ +export type CallerProperties = Record & { result?: never }; + +/** Caller measurements. `durationMs` is framework-managed on traced events. */ +export type CallerMeasurements = Record & { + durationMs?: never; +}; + +/** Session-stable resource attributes. Field names are inspired by OTel + * resource attributes; they are camelCase TypeScript and not a 1:1 mapping. */ +export interface SessionContext { + readonly extensionVersion: string; + readonly machineId: string; + readonly sessionId: string; + readonly osType: string; + readonly osVersion: string; + readonly hostArch: string; + readonly platformName: string; + readonly platformVersion: string; +} + +/** Per-event context: session attributes plus the current deployment URL. */ +export interface TelemetryContext extends SessionContext { + readonly deploymentUrl: string; +} + +export interface TelemetryEvent { + readonly eventId: string; + readonly eventName: string; + readonly timestamp: string; + readonly eventSequence: number; + + readonly context: TelemetryContext; + + readonly properties: Readonly>; + readonly measurements: Readonly>; + + /** Shared by all events in a trace. Maps to OTel `trace_id`. */ + readonly traceId?: string; + /** Set on phase children only. Equals the parent event's `eventId`. Maps to OTel `parent_span_id`. */ + readonly parentEventId?: string; + + readonly error?: Readonly<{ + message: string; + type?: string; + code?: string; + }>; +} + +/** + * Sink for telemetry events. `write` is sync and must buffer in memory; I/O + * happens in `flush`/`dispose`. The service filters by `minLevel`; sinks can + * still self-gate on other signals (e.g. deployment URL). + */ +export interface TelemetrySink { + readonly name: string; + readonly minLevel: TelemetryLevel; + write(event: TelemetryEvent): void; + flush(): Promise; + dispose(): Promise; +} + +/** Build session attributes. `extensionVersion` falls back to `"unknown"`. */ +export function buildSession(ctx: vscode.ExtensionContext): SessionContext { + // "unknown" only for malformed package.json or test fixtures missing `version`. + const packageJson = ctx.extension.packageJSON as { version?: unknown }; + const extensionVersion = + typeof packageJson.version === "string" ? packageJson.version : "unknown"; + + return { + extensionVersion, + machineId: vscode.env.machineId, + sessionId: vscode.env.sessionId, + osType: detectOsType(), + osVersion: os.release(), + hostArch: process.arch, + platformName: vscode.env.appName, + platformVersion: vscode.version, + }; +} + +/** Normalize a thrown value into the event's `error` block. */ +export function buildErrorBlock( + value: unknown, +): NonNullable { + const err = toError(value); + const rawCode = (value as { code?: unknown } | null | undefined)?.code; + const hasCode = typeof rawCode === "string" || typeof rawCode === "number"; + return { + message: err.message, + ...(err.name && err.name !== "Error" && { type: err.name }), + ...(hasCode && { code: String(rawCode) }), + }; +} + +// Node uses "win32" on Windows; OTel's os.type is "windows". +function detectOsType(): string { + return process.platform === "win32" ? "windows" : process.platform; +} diff --git a/src/telemetry/service.ts b/src/telemetry/service.ts new file mode 100644 index 0000000000..78803668fb --- /dev/null +++ b/src/telemetry/service.ts @@ -0,0 +1,290 @@ +import * as vscode from "vscode"; + +import { watchConfigurationChanges } from "../configWatcher"; +import { type Logger } from "../logging/logger"; + +import { + buildSession, + buildErrorBlock, + type CallerMeasurements, + type CallerProperties, + type SessionContext, + type TelemetryEvent, + type TelemetryLevel, + type TelemetrySink, +} from "./event"; +import { NOOP_SPAN, type Span } from "./span"; + +const TELEMETRY_LEVEL_SETTING = "coder.telemetry.level"; + +const LEVEL_ORDER: Readonly> = { + off: 0, + local: 1, +}; + +/** Trace context shared by all events in one trace. */ +interface SpanOptions { + traceId: string; + parentEventId?: string; + /** Level frozen at trace start so a mid-trace toggle does not orphan events. */ + traceLevel: TelemetryLevel; +} + +interface EmitOptions extends Partial { + error?: unknown; +} + +/** + * Emits structured telemetry events to a fan-out of sinks. Sinks are filtered + * by `minLevel` and may self-gate. `dispose` flushes are best-effort since + * VS Code does not await deactivation. + */ +export class TelemetryService implements vscode.Disposable { + #level: TelemetryLevel; + #nextSequence = 0; + #deploymentUrl = ""; + readonly #session: SessionContext; + readonly #configWatcher: vscode.Disposable; + + public constructor( + ctx: vscode.ExtensionContext, + private readonly sinks: readonly TelemetrySink[], + private readonly logger: Logger, + ) { + this.#session = buildSession(ctx); + this.#level = readLevel(); + this.#configWatcher = watchConfigurationChanges( + [{ setting: TELEMETRY_LEVEL_SETTING, getValue: readLevel }], + (changes) => { + const raw = changes.get(TELEMETRY_LEVEL_SETTING); + if (!isTelemetryLevel(raw)) { + return; + } + this.#applyLevelChange(raw).catch((err) => { + this.logger.warn("Telemetry level change failed", err); + }); + }, + ); + } + + public setDeploymentUrl(url: string): void { + this.#deploymentUrl = url; + } + + public log( + eventName: string, + properties: CallerProperties = {}, + measurements: CallerMeasurements = {}, + ): void { + if (this.#level === "off") { + return; + } + this.#safeEmit(crypto.randomUUID(), eventName, properties, measurements); + } + + public logError( + eventName: string, + error: unknown, + properties: CallerProperties = {}, + measurements: CallerMeasurements = {}, + ): void { + if (this.#level === "off") { + return; + } + this.#safeEmit(crypto.randomUUID(), eventName, properties, measurements, { + error, + }); + } + + /** + * Run a timed operation. The emitted event carries `durationMs` and a + * `result` of `success` or `error`. All events from one call share a + * `traceId`; phase children carry `parentEventId`. + */ + public trace( + eventName: string, + fn: (span: Span) => Promise, + properties: CallerProperties = {}, + measurements: CallerMeasurements = {}, + ): Promise { + if (this.#level === "off") { + return fn(NOOP_SPAN); + } + return this.#startSpan(eventName, fn, properties, measurements, { + traceId: crypto.randomUUID(), + traceLevel: this.#level, + }); + } + + public async dispose(): Promise { + this.#configWatcher.dispose(); + await Promise.allSettled( + this.sinks.map(async (sink) => { + await this.#safeCall(sink, "flush"); + await this.#safeCall(sink, "dispose"); + }), + ); + } + + #startSpan( + eventName: string, + fn: (span: Span) => Promise, + properties: Record, + measurements: Record, + spanOpts: SpanOptions, + ): Promise { + const eventId = crypto.randomUUID(); + const { traceId, traceLevel } = spanOpts; + const span: Span = { + traceId, + eventId, + eventName, + phase: ( + phaseName: string, + phaseFn: (childSpan: Span) => Promise, + phaseProps: Record = {}, + phaseMeasurements: Record = {}, + ): Promise => { + const safeName = this.#sanitizePhaseName(phaseName); + return this.#startSpan( + `${eventName}.${safeName}`, + phaseFn, + phaseProps, + phaseMeasurements, + { traceId, parentEventId: eventId, traceLevel }, + ); + }, + }; + return this.#emitTimed( + eventId, + eventName, + () => fn(span), + properties, + measurements, + spanOpts, + ); + } + + #sanitizePhaseName(name: string): string { + if (!name.includes(".")) { + return name; + } + const sanitized = name.replaceAll(".", "_"); + this.logger.warn( + `Telemetry phase name '${name}' contains '.', sanitized to '${sanitized}'`, + ); + return sanitized; + } + + async #emitTimed( + eventId: string, + eventName: string, + fn: () => Promise, + properties: Record, + measurements: Record, + spanOpts: SpanOptions, + ): Promise { + const start = performance.now(); + const send = (result: "success" | "error", error?: unknown): void => + this.#safeEmit( + eventId, + eventName, + { ...properties, result }, + { ...measurements, durationMs: performance.now() - start }, + { ...spanOpts, error }, + ); + try { + const value = await fn(); + send("success"); + return value; + } catch (err) { + send("error", err); + throw err; + } + } + + /** Catch-all wrapper around `#emit`: telemetry failures never reach callers. */ + #safeEmit( + eventId: string, + eventName: string, + properties: Record, + measurements: Record, + options: EmitOptions = {}, + ): void { + try { + this.#emit(eventId, eventName, properties, measurements, options); + } catch (err) { + this.logger.warn("Telemetry emit failed", err); + } + } + + #emit( + eventId: string, + eventName: string, + properties: Record, + measurements: Record, + options: EmitOptions = {}, + ): void { + const { traceId, parentEventId, error, traceLevel } = options; + const event: TelemetryEvent = { + eventId, + eventName, + timestamp: new Date().toISOString(), + eventSequence: this.#nextSequence++, + context: { ...this.#session, deploymentUrl: this.#deploymentUrl }, + properties: { ...properties }, + measurements: { ...measurements }, + ...(traceId !== undefined && { traceId }), + ...(parentEventId !== undefined && { parentEventId }), + ...(error !== undefined && { error: buildErrorBlock(error) }), + }; + + const currentOrder = LEVEL_ORDER[traceLevel ?? this.#level]; + for (const sink of this.sinks) { + if (currentOrder < LEVEL_ORDER[sink.minLevel]) { + continue; + } + try { + sink.write(event); + } catch (err) { + this.logger.warn(`Telemetry sink '${sink.name}' write failed`, err); + } + } + + this.logger.trace(`[telemetry] ${eventName}`, event); + } + + async #applyLevelChange(newLevel: TelemetryLevel): Promise { + if (newLevel === this.#level) { + return; + } + this.#level = newLevel; + if (newLevel === "off") { + await Promise.allSettled( + this.sinks.map((sink) => this.#safeCall(sink, "flush")), + ); + } + } + + async #safeCall( + sink: TelemetrySink, + action: "flush" | "dispose", + ): Promise { + try { + await sink[action](); + } catch (err) { + this.logger.warn(`Telemetry sink '${sink.name}' ${action} failed`, err); + } + } +} + +function readLevel(): TelemetryLevel { + const value = vscode.workspace + .getConfiguration() + .get(TELEMETRY_LEVEL_SETTING); + return isTelemetryLevel(value) ? value : "local"; +} + +function isTelemetryLevel(value: unknown): value is TelemetryLevel { + return value === "off" || value === "local"; +} diff --git a/src/telemetry/span.ts b/src/telemetry/span.ts new file mode 100644 index 0000000000..626c4bb450 --- /dev/null +++ b/src/telemetry/span.ts @@ -0,0 +1,34 @@ +import { type CallerProperties } from "./event"; + +/** + * Parent span handle. Children's `eventName` composes as `${parent.eventName}.${phaseName}`. + * Phase names should not contain `.`; if they do, dots are replaced with `_` and a warning is logged. + * Recurse via `phase` for grandchildren. + */ +export interface Span { + readonly traceId: string; + readonly eventId: string; + readonly eventName: string; + /** Emit a child phase event. Framework sets `result` and `durationMs`. */ + phase( + phaseName: string, + fn: (span: Span) => Promise, + properties?: CallerProperties, + measurements?: Record, + ): Promise; +} + +/** No-op `Span` used when telemetry is off. Runs phase fns but emits nothing. */ +export const NOOP_SPAN: Span = { + traceId: "", + eventId: "", + eventName: "", + phase( + _phaseName: string, + fn: (span: Span) => Promise, + _properties?: CallerProperties, + _measurements?: Record, + ): Promise { + return fn(NOOP_SPAN); + }, +}; diff --git a/test/mocks/telemetry.ts b/test/mocks/telemetry.ts new file mode 100644 index 0000000000..4a9c188683 --- /dev/null +++ b/test/mocks/telemetry.ts @@ -0,0 +1,28 @@ +import { vi } from "vitest"; + +import type { + TelemetryEvent, + TelemetryLevel, + TelemetrySink, +} from "@/telemetry/event"; + +/** + * In-memory `TelemetrySink` for tests. Captures every written event and + * exposes `flush`/`dispose` as `vi.fn()` mocks for assertions. + */ +export class TestSink implements TelemetrySink { + readonly name: string; + readonly minLevel: TelemetryLevel; + readonly events: TelemetryEvent[] = []; + readonly flush = vi.fn(() => Promise.resolve()); + readonly dispose = vi.fn(() => Promise.resolve()); + + constructor(name = "test", minLevel: TelemetryLevel = "local") { + this.name = name; + this.minLevel = minLevel; + } + + write(event: TelemetryEvent): void { + this.events.push(event); + } +} diff --git a/test/mocks/vscode.runtime.ts b/test/mocks/vscode.runtime.ts index c4bdd20bc7..8def001eb6 100644 --- a/test/mocks/vscode.runtime.ts +++ b/test/mocks/vscode.runtime.ts @@ -185,6 +185,8 @@ export const extensions = { all: [] as unknown[], }; +export const version = "1.106.0-test"; + const vscode = { ProgressLocation, ViewColumn, @@ -204,6 +206,7 @@ const vscode = { workspace, env, extensions, + version, }; export default vscode; diff --git a/test/unit/configWatcher.test.ts b/test/unit/configWatcher.test.ts index 2327b2dfb5..7d552b8d47 100644 --- a/test/unit/configWatcher.test.ts +++ b/test/unit/configWatcher.test.ts @@ -10,25 +10,24 @@ import { MockConfigurationProvider } from "../mocks/testHelpers"; describe("watchConfigurationChanges", () => { const createWatcher = (...keys: string[]) => { - const changes: string[][] = []; + const changes: Array> = []; const settings: WatchedSetting[] = keys.map((key) => ({ setting: key, getValue: () => vscode.workspace.getConfiguration().get(key), })); - const watcher = watchConfigurationChanges(settings, (changed) => - changes.push(changed), - ); + const watcher = watchConfigurationChanges(settings, (c) => changes.push(c)); return { changes, dispose: () => watcher.dispose() }; }; - it("fires callback when watched setting value changes", () => { + it("fires callback with the new value when a watched setting changes", () => { const config = new MockConfigurationProvider(); config.set("test.setting", "initial"); const { changes, dispose } = createWatcher("test.setting"); config.set("test.setting", "changed"); - expect(changes).toEqual([["test.setting"]]); + expect(changes).toHaveLength(1); + expect(changes[0].get("test.setting")).toBe("changed"); dispose(); }); @@ -64,10 +63,10 @@ describe("watchConfigurationChanges", () => { config.set("test.setting", "changed2"); // same value - no callback config.set("test.setting", "changed1"); // back to changed1 - should fire - expect(changes).toEqual([ - ["test.setting"], - ["test.setting"], - ["test.setting"], + expect(changes.map((c) => c.get("test.setting"))).toEqual([ + "changed1", + "changed2", + "changed1", ]); dispose(); }); @@ -91,7 +90,8 @@ describe("watchConfigurationChanges", () => { config.set("test.setting", { key: "value" }); // deep equal - no callback config.set("test.setting", { key: "different" }); - expect(changes).toEqual([["test.setting"]]); + expect(changes).toHaveLength(1); + expect(changes[0].get("test.setting")).toEqual({ key: "different" }); dispose(); }); @@ -131,7 +131,8 @@ describe("watchConfigurationChanges", () => { config.set("test.setting", to); - expect(changes).toEqual([["test.setting"]]); + expect(changes).toHaveLength(1); + expect(changes[0].has("test.setting")).toBe(true); dispose(); }); }); diff --git a/test/unit/deployment/deploymentManager.test.ts b/test/unit/deployment/deploymentManager.test.ts index 2756b64717..87b4872e2e 100644 --- a/test/unit/deployment/deploymentManager.test.ts +++ b/test/unit/deployment/deploymentManager.test.ts @@ -66,11 +66,16 @@ 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 manager = DeploymentManager.create( @@ -87,6 +92,7 @@ function createTestContext() { contextManager, mockOAuthSessionManager, mockWorkspaceProvider, + telemetryService, manager, }; } @@ -158,6 +164,19 @@ describe("DeploymentManager", () => { expect(persisted?.url).toBe(TEST_URL); }); + it("notifies telemetry of the deployment URL", async () => { + const { telemetryService, manager } = createTestContext(); + + await manager.setDeployment({ + url: TEST_URL, + safeHostname: TEST_HOSTNAME, + token: "test-token", + user: createMockUser(), + }); + + expect(telemetryService.setDeploymentUrl).toHaveBeenCalledWith(TEST_URL); + }); + it("sets isOwner context when user has owner role", async () => { const { contextManager, manager } = createTestContext(); const ownerUser = createMockUser({ @@ -384,6 +403,20 @@ describe("DeploymentManager", () => { expect(contextManager.get("coder.authenticated")).toBe(false); expect(contextManager.get("coder.isOwner")).toBe(false); }); + + it("resets the telemetry deployment URL on clearDeployment", async () => { + const { telemetryService, manager } = createTestContext(); + + await manager.setDeployment({ + url: TEST_URL, + safeHostname: TEST_HOSTNAME, + token: "test-token", + user: createMockUser(), + }); + await manager.clearDeployment(); + + expect(telemetryService.setDeploymentUrl).toHaveBeenLastCalledWith(""); + }); }); describe("suspendSession", () => { diff --git a/test/unit/telemetry/event.test.ts b/test/unit/telemetry/event.test.ts new file mode 100644 index 0000000000..1ad5d455af --- /dev/null +++ b/test/unit/telemetry/event.test.ts @@ -0,0 +1,72 @@ +import { describe, expect, it } from "vitest"; + +import { buildErrorBlock, buildSession } from "@/telemetry/event"; + +import type * as vscode from "vscode"; + +function fakeContext(version: unknown = "1.2.3-test"): vscode.ExtensionContext { + return { + extension: { packageJSON: { version } }, + } as unknown as vscode.ExtensionContext; +} + +describe("buildSession", () => { + it("populates session-stable fields from the extension context, vscode env, and host", () => { + const session = buildSession(fakeContext()); + + expect(session).toMatchObject({ + extensionVersion: "1.2.3-test", + machineId: "test-machine-id", + sessionId: "test-session-id", + platformName: "Visual Studio Code", + platformVersion: "1.106.0-test", + hostArch: process.arch, + }); + expect(session.osType).toBe( + process.platform === "win32" ? "windows" : process.platform, + ); + expect(session.osVersion).toBeTruthy(); + }); + + it("uses the 'unknown' sentinel when packageJSON.version is missing or non-string", () => { + const noVersion = { + extension: { packageJSON: {} }, + } as unknown as vscode.ExtensionContext; + expect(buildSession(noVersion).extensionVersion).toBe("unknown"); + expect(buildSession(fakeContext(123)).extensionVersion).toBe("unknown"); + }); +}); + +describe("buildErrorBlock", () => { + it.each([ + [ + "Error instance", + new TypeError("nope"), + { message: "nope", type: "TypeError" }, + ], + ["string", "boom", { message: "boom" }], + [ + "plain object with message + name", + { message: "hi", name: "Custom" }, + { message: "hi", type: "Custom" }, + ], + ["null", null, { message: "Unknown error" }], + ])("normalizes %s", (_label, input, expected) => { + expect(buildErrorBlock(input)).toEqual(expected); + }); + + it("captures Node-style and HTTP-style codes as strings", () => { + expect( + buildErrorBlock( + Object.assign(new Error("connect failed"), { code: "ECONNREFUSED" }), + ).code, + ).toBe("ECONNREFUSED"); + expect( + buildErrorBlock(Object.assign(new Error("bad"), { code: 401 })).code, + ).toBe("401"); + }); + + it("omits type for generic Error instances", () => { + expect(buildErrorBlock(new Error("plain"))).toEqual({ message: "plain" }); + }); +}); diff --git a/test/unit/telemetry/service.test.ts b/test/unit/telemetry/service.test.ts new file mode 100644 index 0000000000..8bcafae25f --- /dev/null +++ b/test/unit/telemetry/service.test.ts @@ -0,0 +1,488 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +import { TelemetryService } from "@/telemetry/service"; + +import { TestSink } from "../../mocks/telemetry"; +import { + createMockLogger, + MockConfigurationProvider, +} from "../../mocks/testHelpers"; + +import type * as vscode from "vscode"; + +import type { TelemetrySink } from "@/telemetry/event"; + +function fakeContext(): vscode.ExtensionContext { + return { + extension: { packageJSON: { version: "1.2.3-test" } }, + } as unknown as vscode.ExtensionContext; +} + +interface Harness { + service: TelemetryService; + sink: TestSink; + config: MockConfigurationProvider; +} + +function makeHarness(level: "off" | "local" = "local"): Harness { + const config = new MockConfigurationProvider(); + config.set("coder.telemetry.level", level); + const sink = new TestSink(); + const service = new TelemetryService( + fakeContext(), + [sink], + createMockLogger(), + ); + return { service, sink, config }; +} + +function makeService(sinks: TelemetrySink[]): TelemetryService { + new MockConfigurationProvider().set("coder.telemetry.level", "local"); + return new TelemetryService(fakeContext(), sinks, createMockLogger()); +} + +describe("TelemetryService", () => { + let h: Harness; + beforeEach(() => { + h = makeHarness(); + }); + afterEach(() => { + vi.useRealTimers(); + }); + + describe("log", () => { + it("emits an event with auto-injected context, properties, and measurements", () => { + h.service.log("activation", { outcome: "success" }, { latencyMs: 12 }); + + const [event] = h.sink.events; + expect(event).toMatchObject({ + eventName: "activation", + eventSequence: 0, + properties: { outcome: "success" }, + measurements: { latencyMs: 12 }, + context: { + extensionVersion: "1.2.3-test", + machineId: "test-machine-id", + sessionId: "test-session-id", + deploymentUrl: "", + }, + }); + expect(event.eventId).toMatch( + /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/, + ); + expect(event.timestamp).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + + it("emits unique eventIds and monotonic eventSequence", () => { + h.service.log("a"); + h.service.log("b"); + h.service.log("c"); + + expect(new Set(h.sink.events.map((e) => e.eventId)).size).toBe(3); + expect(h.sink.events.map((e) => e.eventSequence)).toEqual([0, 1, 2]); + }); + }); + + describe("logError", () => { + it("attaches the normalized error block to the event", () => { + h.service.logError("activation", new TypeError("nope"), { + phase: "init", + }); + + expect(h.sink.events[0]).toMatchObject({ + properties: { phase: "init" }, + error: { message: "nope", type: "TypeError" }, + }); + }); + }); + + describe("trace", () => { + it("returns the wrapped value and records durationMs on success", async () => { + vi.useFakeTimers(); + const promise = h.service.trace( + "activation", + async () => { + await new Promise((r) => setTimeout(r, 250)); + return 42; + }, + { phase: "init" }, + ); + await vi.advanceTimersByTimeAsync(250); + + expect(await promise).toBe(42); + expect(h.sink.events[0]).toMatchObject({ + properties: { phase: "init", result: "success" }, + }); + expect(h.sink.events[0].measurements.durationMs).toBeCloseTo(250, 0); + }); + + it("emits an error event with the cause and rethrows on failure", async () => { + const err = new Error("boom"); + await expect( + h.service.trace("activation", () => Promise.reject(err)), + ).rejects.toBe(err); + + expect(h.sink.events[0]).toMatchObject({ + properties: { result: "error" }, + error: { message: "boom" }, + }); + }); + + it("forwards caller measurements alongside the framework-set durationMs", async () => { + await h.service.trace( + "auth.token_refresh", + () => Promise.resolve(), + {}, + { attempts: 2 }, + ); + + const [event] = h.sink.events; + expect(event.measurements.attempts).toBe(2); + expect(event.measurements.durationMs).toBeGreaterThanOrEqual(0); + }); + + it("flat traces (no phases) emit a single event with a fresh traceId", async () => { + await h.service.trace("a", () => Promise.resolve(1)); + await h.service.trace("b", () => Promise.resolve(2)); + + const [a, b] = h.sink.events; + expect(a.traceId).toBeDefined(); + expect(b.traceId).toBeDefined(); + expect(a.traceId).not.toBe(b.traceId); + expect(a.parentEventId).toBeUndefined(); + expect(b.parentEventId).toBeUndefined(); + }); + + it("parent and child phase events share one traceId on success", async () => { + const result = await h.service.trace("remote.setup", async (span) => { + await span.phase("workspace_lookup", () => Promise.resolve("ws")); + await span.phase("ssh_config", () => Promise.resolve("cfg")); + return "done"; + }); + + expect(result).toBe("done"); + const [phase1, phase2, parent] = h.sink.events; + expect(phase1.eventName).toBe("remote.setup.workspace_lookup"); + expect(phase2.eventName).toBe("remote.setup.ssh_config"); + expect(parent).toMatchObject({ + eventName: "remote.setup", + properties: { result: "success" }, + }); + expect(parent.traceId).toBeDefined(); + expect(phase1.traceId).toBe(parent.traceId); + expect(phase2.traceId).toBe(parent.traceId); + }); + + it("phase children carry parentEventId pointing at the parent's eventId; logs do not", async () => { + h.service.log("plain"); + await h.service.trace("op", async (span) => { + await span.phase("p1", () => Promise.resolve()); + await span.phase("p2", () => Promise.resolve()); + }); + + const [plain, p1, p2, parent] = h.sink.events; + // log/logError/time events have no parentEventId field. + expect(plain.parentEventId).toBeUndefined(); + // Parent (root) has no parentEventId either. + expect(parent.parentEventId).toBeUndefined(); + // Phase children point at the parent's eventId. + expect(p1.parentEventId).toBe(parent.eventId); + expect(p2.parentEventId).toBe(parent.eventId); + // All eventIds are still globally unique. + expect( + new Set([plain.eventId, p1.eventId, p2.eventId, parent.eventId]).size, + ).toBe(4); + }); + + it("phase eventName composes as '.' and records durationMs", async () => { + await h.service.trace("remote.setup", async (span) => { + await span.phase("workspace_lookup", () => Promise.resolve("ws")); + }); + + const [phase] = h.sink.events; + expect(phase.eventName).toBe("remote.setup.workspace_lookup"); + expect(phase.measurements.durationMs).toBeGreaterThanOrEqual(0); + }); + + it("supports grandchildren via the child span's phase method", async () => { + await h.service.trace("remote.setup", async (span) => { + await span.phase("workspace_lookup", async (childSpan) => { + await childSpan.phase("dns_resolve", () => Promise.resolve()); + }); + }); + + const [grandchild, child, parent] = h.sink.events; + expect(parent.eventName).toBe("remote.setup"); + expect(child.eventName).toBe("remote.setup.workspace_lookup"); + expect(grandchild.eventName).toBe( + "remote.setup.workspace_lookup.dns_resolve", + ); + // All three share one traceId. + expect(child.traceId).toBe(parent.traceId); + expect(grandchild.traceId).toBe(parent.traceId); + // Hierarchy via parentEventId. + expect(parent.parentEventId).toBeUndefined(); + expect(child.parentEventId).toBe(parent.eventId); + expect(grandchild.parentEventId).toBe(child.eventId); + }); + + it("phase forwards caller properties unchanged except for the framework-set result", async () => { + await h.service.trace("op", async (span) => { + await span.phase("p", () => Promise.resolve(0), { extra: "yes" }); + }); + + const [phase] = h.sink.events; + expect(phase.properties).toEqual({ + extra: "yes", + result: "success", + }); + }); + + it("phase emits error event with cause and rethrows on failure", async () => { + const boom = new Error("nope"); + await expect( + h.service.trace("op", async (span) => { + await span.phase("p", () => Promise.reject(boom)); + }), + ).rejects.toBe(boom); + + const [phase] = h.sink.events; + expect(phase).toMatchObject({ + eventName: "op.p", + properties: { result: "error" }, + error: { message: "nope" }, + }); + }); + + it("phase with a name containing '.' is sanitized and the call succeeds", async () => { + await h.service.trace("op", async (span) => { + await span.phase("bad.name", () => Promise.resolve()); + }); + + const [phase] = h.sink.events; + expect(phase.eventName).toBe("op.bad_name"); + }); + + 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"); + + await expect( + h.service.trace("remote.setup", async (span) => { + await span.phase("ok_phase", () => Promise.resolve("ok")); + await span.phase("bad_phase", () => Promise.reject(boom)); + await span.phase("never_runs", () => Promise.resolve("x")); + }), + ).rejects.toBe(boom); + + expect(h.sink.events).toHaveLength(3); + const [okPhase, badPhase, parent] = h.sink.events; + expect(okPhase.eventName).toBe("remote.setup.ok_phase"); + expect(okPhase.properties).toMatchObject({ result: "success" }); + expect(badPhase.eventName).toBe("remote.setup.bad_phase"); + expect(badPhase.properties).toMatchObject({ result: "error" }); + expect(parent).toMatchObject({ + eventName: "remote.setup", + properties: { result: "error" }, + error: { message: "phase-2-broke" }, + }); + expect( + [okPhase, badPhase, parent].every((e) => e.traceId === parent.traceId), + ).toBe(true); + }); + }); + + describe("setDeploymentUrl", () => { + it("propagates to subsequent events and can be reset", () => { + h.service.log("a"); + h.service.setDeploymentUrl("https://coder.example.com"); + h.service.log("b"); + h.service.setDeploymentUrl(""); + h.service.log("c"); + + expect(h.sink.events.map((e) => e.context.deploymentUrl)).toEqual([ + "", + "https://coder.example.com", + "", + ]); + }); + + it("captures the URL as of the moment each event in a trace is emitted", async () => { + await h.service.trace("op", async (span) => { + await span.phase("first", () => Promise.resolve("")); + h.service.setDeploymentUrl("https://coder.example.com"); + await span.phase("second", () => Promise.resolve("")); + }); + + const [first, second, parent] = h.sink.events; + expect(first.context.deploymentUrl).toBe(""); + expect(second.context.deploymentUrl).toBe("https://coder.example.com"); + expect(parent.context.deploymentUrl).toBe("https://coder.example.com"); + }); + }); + + describe("level off", () => { + beforeEach(() => { + h = makeHarness("off"); + }); + + it("suppresses emissions but still runs wrapped fns for trace", async () => { + h.service.log("a"); + h.service.logError("b", new Error("ignored")); + + expect(await h.service.trace("c", () => Promise.resolve(42))).toBe(42); + + const traceResult = await h.service.trace("d", async (span) => { + const phaseValue = await span.phase("p", () => + Promise.resolve("inner"), + ); + expect(phaseValue).toBe("inner"); + return "outer"; + }); + expect(traceResult).toBe("outer"); + + expect(h.sink.events).toHaveLength(0); + }); + }); + + describe("reactive level", () => { + it("local → off flushes sinks and suppresses; off → local resumes", () => { + h.service.log("first"); + expect(h.sink.events).toHaveLength(1); + + h.config.set("coder.telemetry.level", "off"); + expect(h.sink.flush).toHaveBeenCalledTimes(1); + + h.service.log("second"); + expect(h.sink.events).toHaveLength(1); + + h.config.set("coder.telemetry.level", "local"); + h.service.log("third"); + expect(h.sink.events).toHaveLength(2); + }); + + it("a mid-trace level → off does not orphan child phases or drop the parent", async () => { + let toggled = false; + await h.service.trace("op", async (span) => { + await span.phase("p1", () => Promise.resolve()); + if (!toggled) { + h.config.set("coder.telemetry.level", "off"); + toggled = true; + } + await span.phase("p2", () => Promise.resolve()); + }); + + expect(h.sink.events).toHaveLength(3); + const [p1, p2, parent] = h.sink.events; + expect(p1.eventName).toBe("op.p1"); + expect(p2.eventName).toBe("op.p2"); + expect(parent.eventName).toBe("op"); + expect(p1.traceId).toBe(parent.traceId); + expect(p2.traceId).toBe(parent.traceId); + }); + + it("treats unknown values (e.g. future deployment) as local", () => { + h = makeHarness("off"); + h.config.set("coder.telemetry.level", "deployment"); + h.service.log("evt"); + expect(h.sink.events).toHaveLength(1); + }); + }); + + describe("multiple sinks", () => { + it("a throwing sink does not block other sinks from receiving events", () => { + const bad: TelemetrySink = { + name: "bad", + minLevel: "local", + write: () => { + throw new Error("boom"); + }, + flush: () => Promise.resolve(), + dispose: () => Promise.resolve(), + }; + const good = new TestSink("good"); + const service = makeService([bad, good]); + + service.log("activation"); + expect(good.events).toHaveLength(1); + }); + }); + + describe("errors never propagate to the caller", () => { + const throwingSink: TelemetrySink = { + name: "throws", + minLevel: "local", + write: () => { + throw new Error("sink write failed"); + }, + flush: () => Promise.resolve(), + dispose: () => Promise.resolve(), + }; + + it("log/logError do not throw when the only sink throws", () => { + const service = makeService([throwingSink]); + expect(() => service.log("a")).not.toThrow(); + expect(() => + service.logError("b", new Error("user-error")), + ).not.toThrow(); + }); + + it("trace returns the user fn's value when the sink throws", async () => { + const service = makeService([throwingSink]); + await expect( + service.trace("op", () => Promise.resolve(42)), + ).resolves.toBe(42); + }); + + it("trace rethrows the user fn's error (not any telemetry error)", async () => { + const service = makeService([throwingSink]); + const userErr = new Error("user-error"); + await expect( + service.trace("op", () => Promise.reject(userErr)), + ).rejects.toBe(userErr); + }); + + it("trace and span.phase complete normally when the sink throws", async () => { + const service = makeService([throwingSink]); + const result = await service.trace("op", async (span) => { + const phaseValue = await span.phase("p", () => + Promise.resolve("phase"), + ); + expect(phaseValue).toBe("phase"); + return "trace"; + }); + expect(result).toBe("trace"); + }); + }); + + describe("dispose", () => { + it("flushes and disposes every sink", async () => { + await h.service.dispose(); + expect(h.sink.flush).toHaveBeenCalledTimes(1); + expect(h.sink.dispose).toHaveBeenCalledTimes(1); + }); + + it("unsubscribes the config watcher so later level changes are ignored", async () => { + await h.service.dispose(); + h.sink.flush.mockClear(); + + h.config.set("coder.telemetry.level", "off"); + expect(h.sink.flush).not.toHaveBeenCalled(); + }); + + it("resolves even when sinks reject in flush or dispose", async () => { + const bad: TelemetrySink = { + name: "bad", + minLevel: "local", + write: () => {}, + flush: () => Promise.reject(new Error("flush fail")), + dispose: () => Promise.reject(new Error("dispose fail")), + }; + const good = new TestSink("good"); + const service = makeService([bad, good]); + + await expect(service.dispose()).resolves.toBeUndefined(); + expect(good.flush).toHaveBeenCalled(); + expect(good.dispose).toHaveBeenCalled(); + }); + }); +});