diff --git a/CHANGELOG.md b/CHANGELOG.md index 4dcc92f1..5a208ebd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,8 @@ - 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. +- Local telemetry now records aggregated `http.requests` rollups for per-route + HTTP health without emitting one event per request. ### Fixed diff --git a/package.json b/package.json index d96accb6..1af0d3c5 100644 --- a/package.json +++ b/package.json @@ -207,7 +207,7 @@ ] }, "coder.telemetry.local": { - "markdownDescription": "Tunables for the local telemetry sink, which writes events as JSON Lines under the extension's global storage. Used when `#coder.telemetry.level#` is `local`. Missing or invalid fields fall back to defaults.", + "markdownDescription": "Advanced tunables for local telemetry collection. The local sink writes events as JSON Lines under the extension's global storage. Used when `#coder.telemetry.level#` is `local`. Missing or invalid fields fall back to defaults.", "type": "object", "additionalProperties": false, "properties": { @@ -246,6 +246,22 @@ "minimum": 4096, "default": 104857600, "markdownDescription": "Cap, in bytes, on the combined size of telemetry files. Oldest files are deleted on activation until the total is under the cap." + }, + "httpRequests": { + "type": "object", + "additionalProperties": false, + "markdownDescription": "Tunables for HTTP request rollup telemetry.", + "properties": { + "windowSeconds": { + "type": "number", + "minimum": 1, + "default": 60, + "markdownDescription": "Tumbling window length, in seconds, for aggregated `http.requests` events." + } + }, + "default": { + "windowSeconds": 60 + } } }, "default": { @@ -254,7 +270,10 @@ "bufferLimit": 500, "maxFileBytes": 5242880, "maxAgeDays": 30, - "maxTotalBytes": 104857600 + "maxTotalBytes": 104857600, + "httpRequests": { + "windowSeconds": 60 + } }, "tags": [ "telemetry" diff --git a/src/api/coderApi.ts b/src/api/coderApi.ts index 57e27117..3c93b4f5 100644 --- a/src/api/coderApi.ts +++ b/src/api/coderApi.ts @@ -1,21 +1,12 @@ import { - type AxiosResponseHeaders, - type AxiosInstance, + isAxiosError, type AxiosHeaders, + type AxiosInstance, + type AxiosResponseHeaders, type AxiosResponseTransformer, - isAxiosError, } from "axios"; import { Api } from "coder/site/src/api/api"; -import { - type ServerSentEvent, - type GetInboxNotificationResponse, - type ProvisionerJobLog, - type Workspace, - type WorkspaceAgent, - type WorkspaceAgentLog, -} from "coder/site/src/api/typesGenerated"; import * as vscode from "vscode"; -import { type ClientOptions } from "ws"; import { watchConfigurationChanges } from "../configWatcher"; import { ClientCertificateError } from "../error/clientCertificateError"; @@ -25,23 +16,31 @@ import { getHeaders } from "../headers"; import { EventStreamLogger } from "../logging/eventStreamLogger"; import { createRequestMeta, - logRequest, logError, + logRequest, logResponse, } from "../logging/httpLogger"; -import { type Logger } from "../logging/logger"; import { - type RequestConfigWithMeta, + HttpRequestsTelemetry, + NOOP_HTTP_REQUESTS_TELEMETRY, + type HttpRequestsTelemetryRecorder, +} from "../logging/httpRequestsTelemetry"; +import { HttpClientLogLevel, + type RequestConfigWithMeta, } from "../logging/types"; import { sizeOf } from "../logging/utils"; import { getHeaderCommand } from "../settings/headers"; -import { HttpStatusCode, WebSocketCloseCode } from "../websocket/codes"; import { - type UnidirectionalStream, - type CloseEvent, - type ErrorEvent, -} from "../websocket/eventStreamConnection"; + LOCAL_TELEMETRY_SETTING, + readHttpRequestsTelemetryConfig, + type HttpRequestsTelemetryConfig, +} from "../settings/telemetry"; +import { + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "../telemetry/reporter"; +import { HttpStatusCode, WebSocketCloseCode } from "../websocket/codes"; import { OneWayWebSocket, type OneWayWebSocketInit, @@ -56,8 +55,29 @@ import { SseConnection } from "../websocket/sseConnection"; import { getRefreshCommand, refreshCertificates } from "./certificateRefresh"; import { createHttpAgent } from "./utils"; +import type { + GetInboxNotificationResponse, + ProvisionerJobLog, + ServerSentEvent, + Workspace, + WorkspaceAgent, + WorkspaceAgentLog, +} from "coder/site/src/api/typesGenerated"; +import type { ClientOptions } from "ws"; + +import type { Logger } from "../logging/logger"; +import type { + CloseEvent, + ErrorEvent, + UnidirectionalStream, +} from "../websocket/eventStreamConnection"; + const coderSessionTokenHeader = "Coder-Session-Token"; +const NOOP_DISPOSABLE: vscode.Disposable = { + dispose: () => undefined, +}; + /** * Configuration settings that affect WebSocket connections. * Changes to these settings will trigger WebSocket reconnection. @@ -85,10 +105,15 @@ export class CoderApi extends Api implements vscode.Disposable { ReconnectingWebSocket >(); private readonly configWatcher: vscode.Disposable; + private readonly httpRequestsConfigWatcher: vscode.Disposable; - private constructor(private readonly output: Logger) { + private constructor( + private readonly output: Logger, + private readonly httpRequestsTelemetry: HttpRequestsTelemetryRecorder, + ) { super(); this.configWatcher = this.watchConfigChanges(); + this.httpRequestsConfigWatcher = this.watchHttpRequestsConfigChanges(); } /** @@ -99,11 +124,13 @@ export class CoderApi extends Api implements vscode.Disposable { baseUrl: string, token: string | undefined, output: Logger, + telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, ): CoderApi { - const client = new CoderApi(output); + const httpRequestsTelemetry = createHttpRequestsTelemetry(telemetry); + const client = new CoderApi(output, httpRequestsTelemetry); client.setCredentials(baseUrl, token); - setupInterceptors(client, output); + setupInterceptors(client, output, httpRequestsTelemetry); return client; } @@ -155,6 +182,8 @@ export class CoderApi extends Api implements vscode.Disposable { */ dispose(): void { this.configWatcher.dispose(); + this.httpRequestsConfigWatcher.dispose(); + this.httpRequestsTelemetry.dispose(); for (const socket of this.reconnectingSockets) { socket.close(); } @@ -187,6 +216,32 @@ export class CoderApi extends Api implements vscode.Disposable { }); } + private watchHttpRequestsConfigChanges(): vscode.Disposable { + if (this.httpRequestsTelemetry === NOOP_HTTP_REQUESTS_TELEMETRY) { + return NOOP_DISPOSABLE; + } + + return watchConfigurationChanges( + [ + { + setting: LOCAL_TELEMETRY_SETTING, + getValue: () => + readHttpRequestsTelemetryConfig( + vscode.workspace.getConfiguration(), + ), + }, + ], + (changes) => { + const config = changes.get(LOCAL_TELEMETRY_SETTING) as + | HttpRequestsTelemetryConfig + | undefined; + if (config) { + this.httpRequestsTelemetry.updateConfig(config); + } + }, + ); + } + watchInboxNotifications = async ( watchTemplates: string[], watchTargets: string[], @@ -473,8 +528,29 @@ export class CoderApi extends Api implements vscode.Disposable { /** * Set up logging and request interceptors for the CoderApi instance. */ -function setupInterceptors(client: CoderApi, output: Logger): void { - addLoggingInterceptors(client.getAxiosInstance(), output); +function createHttpRequestsTelemetry( + telemetry: TelemetryReporter, +): HttpRequestsTelemetryRecorder { + if (telemetry === NOOP_TELEMETRY_REPORTER) { + return NOOP_HTTP_REQUESTS_TELEMETRY; + } + + return new HttpRequestsTelemetry( + telemetry, + readHttpRequestsTelemetryConfig(vscode.workspace.getConfiguration()), + ); +} + +function setupInterceptors( + client: CoderApi, + output: Logger, + httpRequestsTelemetry: HttpRequestsTelemetryRecorder, +): void { + addLoggingInterceptors( + client.getAxiosInstance(), + output, + httpRequestsTelemetry, + ); client.getAxiosInstance().interceptors.request.use(async (config) => { const baseUrl = client.getAxiosInstance().defaults.baseURL; @@ -522,7 +598,11 @@ function setupInterceptors(client: CoderApi, output: Logger): void { ); } -function addLoggingInterceptors(client: AxiosInstance, logger: Logger) { +function addLoggingInterceptors( + client: AxiosInstance, + logger: Logger, + httpRequestsTelemetry: HttpRequestsTelemetryRecorder, +) { client.interceptors.request.use( (config) => { const configWithMeta = config as RequestConfigWithMeta; @@ -555,10 +635,12 @@ function addLoggingInterceptors(client: AxiosInstance, logger: Logger) { client.interceptors.response.use( (response) => { + httpRequestsTelemetry.recordResponse(response); logResponse(logger, response, getLogLevel()); return response; }, (error: unknown) => { + httpRequestsTelemetry.recordError(error); logError(logger, error, getLogLevel()); throw error; }, diff --git a/src/extension.ts b/src/extension.ts index 0ba96aff..2a2b5bf7 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -67,6 +67,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { const secretsManager = serviceContainer.getSecretsManager(); const contextManager = serviceContainer.getContextManager(); const commandManager = serviceContainer.getCommandManager(); + const telemetryService = serviceContainer.getTelemetryService(); // Migrate auth storage from old flat format to new label-based format await migrateAuthStorage(serviceContainer); @@ -114,6 +115,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { (await secretsManager.getSessionAuth(deployment?.safeHostname ?? "")) ?.token, output, + telemetryService, ); ctx.subscriptions.push(client); diff --git a/src/logging/httpRequestsTelemetry.ts b/src/logging/httpRequestsTelemetry.ts new file mode 100644 index 00000000..1471abea --- /dev/null +++ b/src/logging/httpRequestsTelemetry.ts @@ -0,0 +1,353 @@ +import { isAxiosError, type AxiosResponse } from "axios"; + +import { formatMethod } from "./formatters"; + +import type { Disposable } from "vscode"; + +import type { HttpRequestsTelemetryConfig } from "../settings/telemetry"; +import type { TelemetryReporter } from "../telemetry/reporter"; + +import type { RequestConfigWithMeta } from "./types"; + +const EVENT_NAME = "http.requests"; +const UNKNOWN_ROUTE = ""; + +const ID_PLACEHOLDER = "{id}"; +const NAME_PLACEHOLDER = "{name}"; +type Placeholder = typeof ID_PLACEHOLDER | typeof NAME_PLACEHOLDER; +type RouteNormalizationRule = readonly string[]; + +const route = (...segments: RouteNormalizationRule): RouteNormalizationRule => + segments; + +const ID_RESOURCE_ROUTES = [ + "aibridge/sessions", + "files", + "groups", + "licenses", + "oauth2-provider/apps", + "templates", + "templateversions", + "workspaceagents", + "workspacebuilds", + "workspaces", +] as const; + +export const ROUTE_NORMALIZATION_RULES: readonly RouteNormalizationRule[] = [ + route("api", "v2", "users", NAME_PLACEHOLDER, "workspace", NAME_PLACEHOLDER), + route("api", "v2", "users", NAME_PLACEHOLDER, "keys", ID_PLACEHOLDER), + route("api", "v2", "users", NAME_PLACEHOLDER), + route("api", "v2", "tasks", NAME_PLACEHOLDER, ID_PLACEHOLDER), + route("api", "v2", "tasks", NAME_PLACEHOLDER), + route( + "api", + "v2", + "organizations", + ID_PLACEHOLDER, + "templates", + NAME_PLACEHOLDER, + "versions", + NAME_PLACEHOLDER, + ), + route( + "api", + "v2", + "organizations", + ID_PLACEHOLDER, + "templates", + NAME_PLACEHOLDER, + ), + route( + "api", + "v2", + "organizations", + ID_PLACEHOLDER, + "groups", + NAME_PLACEHOLDER, + ), + route("api", "v2", "organizations", ID_PLACEHOLDER), + ...ID_RESOURCE_ROUTES.map((resource) => + route("api", "v2", ...resource.split("/"), ID_PLACEHOLDER), + ), +]; + +const UUID = + /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; +const NUMERIC = /^\d+$/; + +interface HttpRequestTelemetrySample { + readonly method?: string; + readonly url?: string; + readonly baseURL?: string; + readonly statusCode?: number; + readonly networkError?: boolean; + readonly durationMs?: number; +} + +interface HttpRequestBucket { + count2xx: number; + count3xx: number; + count4xx: number; + count5xx: number; + countNetworkError: number; + durationsMs: number[]; +} + +export interface HttpRequestsTelemetryRecorder extends Disposable { + recordResponse(response: AxiosResponse): void; + recordError(error: unknown): void; + updateConfig(config: HttpRequestsTelemetryConfig): void; +} + +export const NOOP_HTTP_REQUESTS_TELEMETRY: HttpRequestsTelemetryRecorder = { + recordResponse: () => undefined, + recordError: () => undefined, + updateConfig: () => undefined, + dispose: () => undefined, +}; + +export class HttpRequestsTelemetry implements HttpRequestsTelemetryRecorder { + readonly #telemetry: TelemetryReporter; + #windowSeconds: number; + #timer: NodeJS.Timeout | null = null; + #disposed = false; + readonly #buckets = new Map(); + + public constructor( + telemetry: TelemetryReporter, + config: HttpRequestsTelemetryConfig, + ) { + this.#telemetry = telemetry; + this.#windowSeconds = config.windowSeconds; + this.#scheduleNextWindow(); + } + + public updateConfig(config: HttpRequestsTelemetryConfig): void { + if (config.windowSeconds === this.#windowSeconds) { + return; + } + this.#flush(); + this.#windowSeconds = config.windowSeconds; + this.#scheduleNextWindow(); + } + + public recordResponse(response: AxiosResponse): void { + this.#record({ + method: response.config.method, + url: response.config.url, + baseURL: response.config.baseURL, + statusCode: response.status, + durationMs: durationFromConfig(response.config), + }); + } + + public recordError(error: unknown): void { + if (!isAxiosError(error)) { + return; + } + + const config = error.config as RequestConfigWithMeta | undefined; + if (!config) { + return; + } + + this.#record({ + method: config.method, + url: config.url, + baseURL: config.baseURL, + statusCode: error.response?.status, + networkError: !error.response, + durationMs: durationFromConfig(config), + }); + } + + #flush(): void { + const buckets = [...this.#buckets.entries()]; + this.#buckets.clear(); + for (const [key, bucket] of buckets) { + const { method, route: normalizedRoute } = parseBucketKey(key); + this.#telemetry.log( + EVENT_NAME, + { method, route: normalizedRoute }, + { + window_seconds: this.#windowSeconds, + count_2xx: bucket.count2xx, + count_3xx: bucket.count3xx, + count_4xx: bucket.count4xx, + count_5xx: bucket.count5xx, + count_network_error: bucket.countNetworkError, + avg_duration_ms: average(bucket.durationsMs), + p95_duration_ms: percentile95(bucket.durationsMs), + }, + ); + } + } + + public dispose(): void { + this.#disposed = true; + if (this.#timer) { + clearTimeout(this.#timer); + this.#timer = null; + } + this.#buckets.clear(); + } + + #record(sample: HttpRequestTelemetrySample): void { + if (this.#disposed) { + return; + } + + const method = formatMethod(sample.method); + const normalizedRoute = normalizeHttpRoute(sample.url, sample.baseURL); + const key = bucketKey(method, normalizedRoute); + const bucket = this.#buckets.get(key) ?? createBucket(); + this.#buckets.set(key, bucket); + + const durationMs = sanitizeDuration(sample.durationMs); + bucket.durationsMs.push(durationMs); + + if (sample.networkError) { + bucket.countNetworkError += 1; + return; + } + + const statusCode = sample.statusCode; + if (statusCode === undefined) { + bucket.countNetworkError += 1; + return; + } + + if (statusCode >= 200 && statusCode < 300) { + bucket.count2xx += 1; + } else if (statusCode >= 300 && statusCode < 400) { + bucket.count3xx += 1; + } else if (statusCode >= 400 && statusCode < 500) { + bucket.count4xx += 1; + } else if (statusCode >= 500 && statusCode < 600) { + bucket.count5xx += 1; + } else { + bucket.countNetworkError += 1; + } + } + + #scheduleNextWindow(): void { + if (this.#timer) { + clearTimeout(this.#timer); + this.#timer = null; + } + if (this.#disposed) { + return; + } + this.#timer = setTimeout(() => { + this.#flush(); + this.#scheduleNextWindow(); + }, this.#windowSeconds * 1000); + } +} + +export function normalizeHttpRoute( + url: string | undefined, + baseURL?: string, +): string { + if (!url) { + return UNKNOWN_ROUTE; + } + + const segments = parsePathSegments(url, baseURL); + if (segments.length === 0) { + return UNKNOWN_ROUTE; + } + + for (const rule of ROUTE_NORMALIZATION_RULES) { + const normalized = normalizeByRule(segments, rule); + if (normalized) { + return normalized; + } + } + return `/${segments.map(normalizeIdSegment).join("/")}`; +} + +function normalizeByRule( + segments: readonly string[], + rule: RouteNormalizationRule, +): string | undefined { + if (segments.length < rule.length) { + return undefined; + } + + const normalized: string[] = []; + for (const [index, ruleSegment] of rule.entries()) { + if (isPlaceholder(ruleSegment)) { + normalized.push(ruleSegment); + continue; + } + if (segments[index] !== ruleSegment) { + return undefined; + } + normalized.push(segments[index]); + } + + return `/${[ + ...normalized, + ...segments.slice(rule.length).map(normalizeIdSegment), + ].join("/")}`; +} + +function parsePathSegments(url: string, baseURL?: string): string[] { + try { + return new URL(url, baseURL ?? "http://coder.invalid").pathname + .split("/") + .filter(Boolean); + } catch { + return []; + } +} + +function isPlaceholder(segment: string): segment is Placeholder { + return segment === ID_PLACEHOLDER || segment === NAME_PLACEHOLDER; +} + +function normalizeIdSegment(segment: string): string { + return UUID.test(segment) || NUMERIC.test(segment) ? ID_PLACEHOLDER : segment; +} + +function durationFromConfig(config: RequestConfigWithMeta | undefined): number { + const startedAt = config?.metadata?.startedAt; + return typeof startedAt === "number" ? Date.now() - startedAt : 0; +} + +function sanitizeDuration(durationMs: number | undefined): number { + return typeof durationMs === "number" && Number.isFinite(durationMs) + ? Math.max(0, durationMs) + : 0; +} + +function createBucket(): HttpRequestBucket { + return { + count2xx: 0, + count3xx: 0, + count4xx: 0, + count5xx: 0, + countNetworkError: 0, + durationsMs: [], + }; +} + +function average(values: readonly number[]): number { + return values.reduce((sum, value) => sum + value, 0) / values.length; +} + +function percentile95(values: readonly number[]): number { + const sorted = [...values].sort((a, b) => a - b); + const index = Math.ceil(sorted.length * 0.95) - 1; + return sorted[Math.max(0, index)]; +} + +function bucketKey(method: string, route: string): string { + return `${method}\n${route}`; +} + +function parseBucketKey(key: string): { method: string; route: string } { + const [method, route] = key.split("\n", 2); + return { method, route }; +} diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 0f8714d5..f0f0f9c4 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -190,7 +190,12 @@ export class Remote { // break this connection. We could force close the remote session or // disallow logging out/in altogether, but for now just use a separate // client to remain unaffected by whatever the plugin is doing. - const workspaceClient = CoderApi.create(baseUrlRaw, token, this.logger); + const workspaceClient = CoderApi.create( + baseUrlRaw, + token, + this.logger, + this.serviceContainer.getTelemetryService(), + ); disposables.push(workspaceClient); // Create 401 interceptor - handles auth failures with re-login dialog diff --git a/src/settings/telemetry.ts b/src/settings/telemetry.ts index e082c615..8f1417c1 100644 --- a/src/settings/telemetry.ts +++ b/src/settings/telemetry.ts @@ -3,7 +3,8 @@ import type { WorkspaceConfiguration } from "vscode"; import type { TelemetryLevel } from "../telemetry/event"; export const TELEMETRY_LEVEL_SETTING = "coder.telemetry.level"; -export const LOCAL_SINK_SETTING = "coder.telemetry.local"; +export const LOCAL_TELEMETRY_SETTING = "coder.telemetry.local"; +export const LOCAL_SINK_SETTING = LOCAL_TELEMETRY_SETTING; /** Telemetry level. Falls back to `local` for unknown or invalid values. */ export function readTelemetryLevel( @@ -22,6 +23,10 @@ export interface LocalSinkConfig { readonly maxTotalBytes: number; } +export interface HttpRequestsTelemetryConfig { + readonly windowSeconds: number; +} + export const LOCAL_SINK_DEFAULTS: LocalSinkConfig = { flushIntervalMs: 15_000, flushBatchSize: 100, @@ -31,6 +36,10 @@ export const LOCAL_SINK_DEFAULTS: LocalSinkConfig = { maxTotalBytes: 100 * 1024 * 1024, }; +export const HTTP_REQUESTS_TELEMETRY_DEFAULTS: HttpRequestsTelemetryConfig = { + windowSeconds: 60, +}; + // Defense in depth: VS Code does not enforce JSON schema at runtime, so users // can drop in any value via settings.json. Mirrors the minimums in package.json. const LOCAL_SINK_MINIMUMS: LocalSinkConfig = { @@ -42,21 +51,17 @@ const LOCAL_SINK_MINIMUMS: LocalSinkConfig = { maxTotalBytes: 4096, }; +const HTTP_REQUESTS_TELEMETRY_MINIMUMS: HttpRequestsTelemetryConfig = { + windowSeconds: 1, +}; + /** Per-field: missing, non-numeric, or below-minimum values fall back to defaults. */ export function readLocalSinkConfig( cfg: Pick, ): LocalSinkConfig { - const raw = cfg.get(LOCAL_SINK_SETTING); - const obj = - raw && typeof raw === "object" && !Array.isArray(raw) - ? (raw as Record) - : {}; - const read = (key: keyof LocalSinkConfig): number => { - const value = obj[key]; - return typeof value === "number" && value >= LOCAL_SINK_MINIMUMS[key] - ? value - : LOCAL_SINK_DEFAULTS[key]; - }; + const obj = readLocalTelemetryObject(cfg); + const read = (key: keyof LocalSinkConfig): number => + readNumber(obj, key, LOCAL_SINK_DEFAULTS[key], LOCAL_SINK_MINIMUMS[key]); return { flushIntervalMs: read("flushIntervalMs"), flushBatchSize: read("flushBatchSize"), @@ -66,3 +71,41 @@ export function readLocalSinkConfig( maxTotalBytes: read("maxTotalBytes"), }; } + +export function readHttpRequestsTelemetryConfig( + cfg: Pick, +): HttpRequestsTelemetryConfig { + const httpRequests = readObject(readLocalTelemetryObject(cfg).httpRequests); + return { + windowSeconds: readNumber( + httpRequests, + "windowSeconds", + HTTP_REQUESTS_TELEMETRY_DEFAULTS.windowSeconds, + HTTP_REQUESTS_TELEMETRY_MINIMUMS.windowSeconds, + ), + }; +} + +function readLocalTelemetryObject( + cfg: Pick, +): Record { + return readObject(cfg.get(LOCAL_TELEMETRY_SETTING)); +} + +function readObject(value: unknown): Record { + return value && typeof value === "object" && !Array.isArray(value) + ? (value as Record) + : {}; +} + +function readNumber( + obj: Record, + key: string, + defaultValue: number, + minimum: number, +): number { + const value = obj[key]; + return typeof value === "number" && Number.isFinite(value) && value >= minimum + ? value + : defaultValue; +} diff --git a/src/telemetry/reporter.ts b/src/telemetry/reporter.ts new file mode 100644 index 00000000..e46811b4 --- /dev/null +++ b/src/telemetry/reporter.ts @@ -0,0 +1,29 @@ +import { NOOP_SPAN, type Span } from "./span"; + +import type { CallerMeasurements, CallerProperties } from "./event"; + +export interface TelemetryReporter { + log( + eventName: string, + properties?: CallerProperties, + measurements?: CallerMeasurements, + ): void; + logError( + eventName: string, + error: unknown, + properties?: CallerProperties, + measurements?: CallerMeasurements, + ): void; + trace( + eventName: string, + fn: (span: Span) => Promise, + properties?: CallerProperties, + measurements?: CallerMeasurements, + ): Promise; +} + +export const NOOP_TELEMETRY_REPORTER: TelemetryReporter = { + log: () => undefined, + logError: () => undefined, + trace: (_eventName, fn) => fn(NOOP_SPAN), +}; diff --git a/src/telemetry/service.ts b/src/telemetry/service.ts index 9ada725d..724614c2 100644 --- a/src/telemetry/service.ts +++ b/src/telemetry/service.ts @@ -19,6 +19,8 @@ import { import { newSpanId, newTraceId } from "./ids"; import { NOOP_SPAN, type Span } from "./span"; +import type { TelemetryReporter } from "./reporter"; + const LEVEL_ORDER: Readonly> = { off: 0, local: 1, @@ -44,7 +46,7 @@ interface EmitOptions extends Partial { * by `minLevel` and may self-gate. `dispose` flushes are best-effort since * VS Code does not await deactivation. */ -export class TelemetryService implements vscode.Disposable { +export class TelemetryService implements vscode.Disposable, TelemetryReporter { #level: TelemetryLevel; #nextSequence = 0; #deploymentUrl = ""; diff --git a/test/unit/api/coderApi.test.ts b/test/unit/api/coderApi.test.ts index b6eab26b..cb07bcd0 100644 --- a/test/unit/api/coderApi.test.ts +++ b/test/unit/api/coderApi.test.ts @@ -4,7 +4,6 @@ import axios, { type CreateAxiosDefaults, type InternalAxiosRequestConfig, } from "axios"; -import { type ProvisionerJobLog } from "coder/site/src/api/typesGenerated"; import { EventSource } from "eventsource"; import { ProxyAgent } from "proxy-agent"; import { @@ -27,7 +26,11 @@ import { createHttpAgent } from "@/api/utils"; import { ClientCertificateError } from "@/error/clientCertificateError"; import { ServerCertificateError } from "@/error/serverCertificateError"; import { getHeaders } from "@/headers"; -import { type RequestConfigWithMeta } from "@/logging/types"; +import { LOCAL_TELEMETRY_SETTING } from "@/settings/telemetry"; +import { + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "@/telemetry/reporter"; import { ReconnectingWebSocket } from "@/websocket/reconnectingWebSocket"; import { @@ -35,6 +38,10 @@ import { MockConfigurationProvider, } from "../../mocks/testHelpers"; +import type { ProvisionerJobLog } from "coder/site/src/api/typesGenerated"; + +import type { RequestConfigWithMeta } from "@/logging/types"; + const CODER_URL = "https://coder.example.com"; const AXIOS_TOKEN = "passed-token"; const BUILD_ID = "build-123"; @@ -93,8 +100,12 @@ describe("CoderApi", () => { >; let api: CoderApi; - const createApi = (url = CODER_URL, token = AXIOS_TOKEN) => { - return CoderApi.create(url, token, mockLogger); + const createApi = ( + url = CODER_URL, + token = AXIOS_TOKEN, + telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, + ) => { + return CoderApi.create(url, token, mockLogger, telemetry); }; beforeEach(() => { @@ -117,6 +128,7 @@ describe("CoderApi", () => { afterEach(() => { // Dispose any api created during the test to clean up config watchers api?.dispose(); + vi.useRealTimers(); }); describe("HTTP Interceptors", () => { @@ -229,6 +241,54 @@ describe("CoderApi", () => { ); }); + it("rolls HTTP responses into telemetry when telemetry is provided", async () => { + vi.useFakeTimers(); + mockConfig.set(LOCAL_TELEMETRY_SETTING, { + httpRequests: { windowSeconds: 1 }, + }); + const log = vi.fn(); + api = createApi(CODER_URL, AXIOS_TOKEN, { + ...NOOP_TELEMETRY_REPORTER, + log, + }); + + await api.getAxiosInstance().get("/api/v2/workspaces/abc-123"); + await vi.advanceTimersByTimeAsync(1000); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + window_seconds: 1, + count_2xx: 1, + }), + ); + }); + + it("updates HTTP telemetry window from configuration changes", async () => { + vi.useFakeTimers(); + mockConfig.set(LOCAL_TELEMETRY_SETTING, { + httpRequests: { windowSeconds: 10 }, + }); + const log = vi.fn(); + api = createApi(CODER_URL, AXIOS_TOKEN, { + ...NOOP_TELEMETRY_REPORTER, + log, + }); + + mockConfig.set(LOCAL_TELEMETRY_SETTING, { + httpRequests: { windowSeconds: 1 }, + }); + await api.getAxiosInstance().get("/api/v2/workspaces/abc-123"); + await vi.advanceTimersByTimeAsync(1000); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ window_seconds: 1 }), + ); + }); + describe("certificate refresh and retry", () => { const rejectWithCertError = ( config: InternalAxiosRequestConfig, diff --git a/test/unit/logging/httpRequestsTelemetry.test.ts b/test/unit/logging/httpRequestsTelemetry.test.ts new file mode 100644 index 00000000..7a0508a9 --- /dev/null +++ b/test/unit/logging/httpRequestsTelemetry.test.ts @@ -0,0 +1,235 @@ +import { AxiosError, AxiosHeaders, type AxiosResponse } from "axios"; +import { afterEach, describe, expect, it, vi } from "vitest"; + +import { + HttpRequestsTelemetry, + normalizeHttpRoute, +} from "@/logging/httpRequestsTelemetry"; +import { + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "@/telemetry/reporter"; + +import type { RequestConfigWithMeta } from "@/logging/types"; + +interface Harness { + rollup: HttpRequestsTelemetry; + log: ReturnType; +} + +interface RequestOptions { + readonly method?: string; + readonly url: string; + readonly status?: number; + readonly durationMs?: number; +} + +describe("HttpRequestsTelemetry", () => { + afterEach(() => vi.useRealTimers()); + + it("emits one event per active method and route at the window boundary", async () => { + const { rollup, log } = createHarness(2); + try { + recordResponse(rollup, { + method: "get", + url: "/api/v2/workspaces/abc-123?owner=danny", + status: 200, + durationMs: 100, + }); + recordResponse(rollup, { + method: "GET", + url: "/api/v2/workspaces/abc-123?owner=someone-else", + status: 204, + durationMs: 200, + }); + recordResponse(rollup, { + method: "POST", + url: "/api/v2/workspaces/abc-123", + status: 201, + durationMs: 300, + }); + + await vi.advanceTimersByTimeAsync(2000); + + expect(log).toHaveBeenCalledTimes(2); + expect(log).toHaveBeenNthCalledWith( + 1, + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + { + window_seconds: 2, + count_2xx: 2, + count_3xx: 0, + count_4xx: 0, + count_5xx: 0, + count_network_error: 0, + avg_duration_ms: 150, + p95_duration_ms: 200, + }, + ); + expect(log).toHaveBeenNthCalledWith( + 2, + "http.requests", + { method: "POST", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + window_seconds: 2, + count_2xx: 1, + }), + ); + } finally { + rollup.dispose(); + } + }); + + it("counts status code classes and network errors", async () => { + const { rollup, log } = createHarness(1); + try { + const route = "/api/v2/users/danny/workspaces"; + recordResponse(rollup, { method: "POST", url: route, status: 201 }); + recordResponse(rollup, { method: "POST", url: route, status: 302 }); + recordAxiosError(rollup, { method: "POST", url: route, status: 404 }); + recordAxiosError(rollup, { method: "POST", url: route, status: 500 }); + recordAxiosError(rollup, { method: "POST", url: route }); + + await vi.advanceTimersByTimeAsync(1000); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "POST", route: "/api/v2/users/{name}/workspaces" }, + expect.objectContaining({ + count_2xx: 1, + count_3xx: 1, + count_4xx: 1, + count_5xx: 1, + count_network_error: 1, + }), + ); + } finally { + rollup.dispose(); + } + }); + + it("emits nothing for empty windows", async () => { + const { rollup, log } = createHarness(1); + try { + await vi.advanceTimersByTimeAsync(2000); + + expect(log).not.toHaveBeenCalled(); + } finally { + rollup.dispose(); + } + }); + + it("calculates nearest-rank p95", async () => { + const { rollup, log } = createHarness(1); + try { + for (const durationMs of [ + 10, 20, 30, 40, 50, 60, 70, 80, 90, 100, 110, 120, 130, 140, 150, 160, + 170, 180, 190, 200, + ]) { + recordResponse(rollup, { + method: "GET", + url: "/api/v2/workspaces/ws-id", + status: 200, + durationMs, + }); + } + + await vi.advanceTimersByTimeAsync(1000); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + avg_duration_ms: 105, + p95_duration_ms: 190, + }), + ); + } finally { + rollup.dispose(); + } + }); + + it.each([ + ["/api/v2/workspaces/abc-123?foo=bar", "/api/v2/workspaces/{id}"], + [ + "/api/v2/users/danny/workspace/my-workspace?foo=bar", + "/api/v2/users/{name}/workspace/{name}", + ], + ["/api/v2/users/danny/keys/123", "/api/v2/users/{name}/keys/{id}"], + ["/api/v2/tasks/danny/task-123", "/api/v2/tasks/{name}/{id}"], + [ + "/api/v2/organizations/9f0f7f37-dfb7-4f4b-bcb8-c7062c7550fc/templates/base/versions/v1", + "/api/v2/organizations/{id}/templates/{name}/versions/{name}", + ], + [ + "/api/v2/workspaceagents/9f0f7f37-dfb7-4f4b-bcb8-c7062c7550fc/logs", + "/api/v2/workspaceagents/{id}/logs", + ], + [ + "/api/v2/workspaces/123/builds/456", + "/api/v2/workspaces/{id}/builds/{id}", + ], + ["http://%", ""], + ])("normalizes %s", (url, expected) => { + expect(normalizeHttpRoute(url)).toBe(expected); + }); +}); + +function createHarness(windowSeconds = 60): Harness { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2025-01-01T00:00:00.000Z")); + + const log = vi.fn(); + const reporter: TelemetryReporter = { + ...NOOP_TELEMETRY_REPORTER, + log, + }; + return { + rollup: new HttpRequestsTelemetry(reporter, { windowSeconds }), + log, + }; +} + +function recordResponse( + rollup: HttpRequestsTelemetry, + options: RequestOptions, +): void { + rollup.recordResponse(makeResponse(options)); +} + +function recordAxiosError( + rollup: HttpRequestsTelemetry, + options: RequestOptions, +): void { + const config = makeRequestConfig(options); + const response = options.status + ? makeResponse({ ...options, status: options.status }) + : undefined; + rollup.recordError( + new AxiosError("Request failed", undefined, config, {}, response), + ); +} + +function makeResponse(options: RequestOptions): AxiosResponse { + const status = options.status ?? 200; + return { + data: {}, + status, + statusText: String(status), + headers: {}, + config: makeRequestConfig(options), + }; +} + +function makeRequestConfig(options: RequestOptions): RequestConfigWithMeta { + return { + headers: new AxiosHeaders(), + method: options.method, + url: options.url, + metadata: { + requestId: "test-request", + startedAt: Date.now() - (options.durationMs ?? 0), + }, + } as RequestConfigWithMeta; +} diff --git a/test/unit/settings/telemetry.test.ts b/test/unit/settings/telemetry.test.ts index cfc7f2c6..df4f7d96 100644 --- a/test/unit/settings/telemetry.test.ts +++ b/test/unit/settings/telemetry.test.ts @@ -1,9 +1,11 @@ import { beforeEach, describe, expect, it } from "vitest"; import { + HTTP_REQUESTS_TELEMETRY_DEFAULTS, LOCAL_SINK_DEFAULTS, - LOCAL_SINK_SETTING, + LOCAL_TELEMETRY_SETTING, TELEMETRY_LEVEL_SETTING, + readHttpRequestsTelemetryConfig, readLocalSinkConfig, readTelemetryLevel, } from "@/settings/telemetry"; @@ -44,7 +46,7 @@ describe("telemetry settings", () => { ["null", null], ["an array", [1, 2]], ])("returns defaults when the raw value is %s", (_, raw) => { - config.set(LOCAL_SINK_SETTING, raw); + config.set(LOCAL_TELEMETRY_SETTING, raw); expect(readLocalSinkConfig(config)).toEqual(LOCAL_SINK_DEFAULTS); }); @@ -57,7 +59,7 @@ describe("telemetry settings", () => { maxAgeDays: 7, maxTotalBytes: 8192, }; - config.set(LOCAL_SINK_SETTING, custom); + config.set(LOCAL_TELEMETRY_SETTING, custom); expect(readLocalSinkConfig(config)).toEqual(custom); }); @@ -68,14 +70,14 @@ describe("telemetry settings", () => { ["a numeric string", "100"], ["a boolean", true], ])("falls back per-field when a value is %s", (_, bad) => { - config.set(LOCAL_SINK_SETTING, { flushIntervalMs: bad }); + config.set(LOCAL_TELEMETRY_SETTING, { flushIntervalMs: bad }); expect(readLocalSinkConfig(config).flushIntervalMs).toBe( LOCAL_SINK_DEFAULTS.flushIntervalMs, ); }); it("merges valid fields with defaults for invalid ones", () => { - config.set(LOCAL_SINK_SETTING, { + config.set(LOCAL_TELEMETRY_SETTING, { flushIntervalMs: 5_000, flushBatchSize: -1, }); @@ -86,7 +88,7 @@ describe("telemetry settings", () => { }); it("returns bufferLimit and flushBatchSize as written, without clamping", () => { - config.set(LOCAL_SINK_SETTING, { + config.set(LOCAL_TELEMETRY_SETTING, { flushBatchSize: 200, bufferLimit: 50, }); @@ -96,4 +98,55 @@ describe("telemetry settings", () => { }); }); }); + + describe("readHttpRequestsTelemetryConfig", () => { + it("returns defaults when unset", () => { + expect(readHttpRequestsTelemetryConfig(config)).toEqual( + HTTP_REQUESTS_TELEMETRY_DEFAULTS, + ); + }); + + it.each([ + ["a string", "nope"], + ["a boolean", true], + ["null", null], + ["an array", [1, 2]], + ])("returns defaults when the raw value is %s", (_, raw) => { + config.set(LOCAL_TELEMETRY_SETTING, raw); + expect(readHttpRequestsTelemetryConfig(config)).toEqual( + HTTP_REQUESTS_TELEMETRY_DEFAULTS, + ); + }); + + it("accepts a fully-specified object", () => { + config.set(LOCAL_TELEMETRY_SETTING, { + httpRequests: { windowSeconds: 10 }, + }); + expect(readHttpRequestsTelemetryConfig(config)).toEqual({ + windowSeconds: 10, + }); + }); + + it.each([ + ["zero", 0], + ["a negative", -1], + ["NaN", Number.NaN], + ["a numeric string", "100"], + ["a boolean", true], + ])("falls back per-field when a value is %s", (_, bad) => { + config.set(LOCAL_TELEMETRY_SETTING, { + httpRequests: { windowSeconds: bad }, + }); + expect(readHttpRequestsTelemetryConfig(config).windowSeconds).toBe( + HTTP_REQUESTS_TELEMETRY_DEFAULTS.windowSeconds, + ); + }); + + it("ignores invalid httpRequests values", () => { + config.set(LOCAL_TELEMETRY_SETTING, { httpRequests: "nope" }); + expect(readHttpRequestsTelemetryConfig(config)).toEqual( + HTTP_REQUESTS_TELEMETRY_DEFAULTS, + ); + }); + }); });