diff --git a/CHANGELOG.md b/CHANGELOG.md index 32e8e137..0c556163 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,8 @@ 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 `http.requests` rollups for per-route HTTP + health without emitting one event per request. ### Fixed diff --git a/package.json b/package.json index 1066eb9e..1e652166 100644 --- a/package.json +++ b/package.json @@ -31,7 +31,7 @@ "package:prerelease": "pnpm build:production && vsce package --pre-release --no-dependencies", "storybook": "storybook dev -p 6006 --config-dir .storybook", "storybook:build": "storybook build --config-dir .storybook", - "storybook:ci": "storybook build --test --config-dir .storybook", + "storybook:ci": "storybook build --test --config-dir .storybook", "test": "cross-env CI=true ELECTRON_RUN_AS_NODE=1 electron node_modules/vitest/vitest.mjs", "test:extension": "cross-env ELECTRON_RUN_AS_NODE=1 electron node_modules/vitest/vitest.mjs --project extension", "test:integration": "pnpm compile-tests:integration && node esbuild.mjs && vscode-test", @@ -211,7 +211,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": { diff --git a/src/api/coderApi.ts b/src/api/coderApi.ts index 57e27117..751256f2 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,22 @@ 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 { HttpRequestsTelemetry } from "../logging/httpRequestsTelemetry"; import { - type RequestConfigWithMeta, 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"; + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "../telemetry/reporter"; +import { HttpStatusCode, WebSocketCloseCode } from "../websocket/codes"; import { OneWayWebSocket, type OneWayWebSocketInit, @@ -56,6 +46,23 @@ 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"; /** @@ -86,24 +93,30 @@ export class CoderApi extends Api implements vscode.Disposable { >(); private readonly configWatcher: vscode.Disposable; - private constructor(private readonly output: Logger) { + private constructor( + private readonly output: Logger, + private readonly httpRequestsTelemetry: HttpRequestsTelemetry, + ) { super(); this.configWatcher = this.watchConfigChanges(); } /** * Create a new CoderApi instance with the provided configuration. - * Automatically sets up logging interceptors and certificate handling. + * Automatically sets up logging interceptors, certificate handling, + * and HTTP request telemetry that emits via the given reporter. */ static create( baseUrl: string, token: string | undefined, output: Logger, + telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, ): CoderApi { - const client = new CoderApi(output); + const httpRequestsTelemetry = new HttpRequestsTelemetry(telemetry); + const client = new CoderApi(output, httpRequestsTelemetry); client.setCredentials(baseUrl, token); - setupInterceptors(client, output); + setupInterceptors(client, output, httpRequestsTelemetry); return client; } @@ -155,6 +168,7 @@ export class CoderApi extends Api implements vscode.Disposable { */ dispose(): void { this.configWatcher.dispose(); + this.httpRequestsTelemetry.dispose(); for (const socket of this.reconnectingSockets) { socket.close(); } @@ -470,11 +484,16 @@ 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 setupInterceptors( + client: CoderApi, + output: Logger, + httpRequestsTelemetry: HttpRequestsTelemetry, +): void { + addRequestInterceptors( + client.getAxiosInstance(), + output, + httpRequestsTelemetry, + ); client.getAxiosInstance().interceptors.request.use(async (config) => { const baseUrl = client.getAxiosInstance().defaults.baseURL; @@ -499,7 +518,7 @@ function setupInterceptors(client: CoderApi, output: Logger): void { return config; }); - // Wrap certificate errors and handle client certificate errors with refresh. + // Cert-refresh retries re-enter the chain, so each attempt is recorded. client.getAxiosInstance().interceptors.response.use( (r) => r, async (err: unknown) => { @@ -522,7 +541,11 @@ function setupInterceptors(client: CoderApi, output: Logger): void { ); } -function addLoggingInterceptors(client: AxiosInstance, logger: Logger) { +function addRequestInterceptors( + client: AxiosInstance, + logger: Logger, + httpRequestsTelemetry: HttpRequestsTelemetry, +) { client.interceptors.request.use( (config) => { const configWithMeta = config as RequestConfigWithMeta; @@ -555,10 +578,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 cf310bce..3067014c 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -84,6 +84,7 @@ async function doActivate( 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); @@ -137,6 +138,7 @@ async function doActivate( deployment?.url || "", deploymentSessionAuth?.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..dd95b94c --- /dev/null +++ b/src/logging/httpRequestsTelemetry.ts @@ -0,0 +1,281 @@ +import { isAxiosError, type AxiosResponse } from "axios"; + +import { + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "../telemetry/reporter"; + +import { formatMethod } from "./formatters"; + +import type { Disposable } from "vscode"; + +import type { RequestConfigWithMeta } from "./types"; + +const EVENT_NAME = "http.requests"; +const UNKNOWN_ROUTE = ""; +const WINDOW_SECONDS = 60; + +const ID_PLACEHOLDER = "{id}"; +const NAME_PLACEHOLDER = "{name}"; + +const ROUTE_NORMALIZATION_RULES: ReadonlyArray = [ + "api/v2/users/{name}/workspace/{name}", + "api/v2/users/{name}/keys/{id}", + "api/v2/users/{name}", + "api/v2/tasks/{name}/{id}", + "api/v2/tasks/{name}", + "api/v2/organizations/{id}/templates/{name}/versions/{name}", + "api/v2/organizations/{id}/templates/{name}", + "api/v2/organizations/{id}/groups/{name}", + "api/v2/organizations/{id}/members/{name}", + "api/v2/organizations/{id}", + "api/v2/aibridge/sessions/{id}", + "api/v2/files/{id}", + "api/v2/groups/{id}", + "api/v2/licenses/{id}", + "api/v2/oauth2-provider/apps/{id}", + "api/v2/templates/{id}", + "api/v2/templateversions/{id}", + "api/v2/workspaceagents/{id}", + "api/v2/workspacebuilds/{id}", + "api/v2/workspaces/{id}/builds/{id}", + "api/v2/workspaces/{id}", +].map((rule) => rule.split("/")); + +interface HttpRequestBucket { + count1xx: number; + count2xx: number; + count3xx: number; + count4xx: number; + count5xx: number; + countNetworkError: number; + durationsMs: number[]; +} + +/** + * Rolls up HTTP request counts and latencies into "http.requests" events + * every 60 seconds. Construct with NOOP_TELEMETRY_REPORTER to skip the + * timer so throwaway clients don't leak it. + */ +export class HttpRequestsTelemetry implements Disposable { + readonly #telemetry: TelemetryReporter; + #timer: NodeJS.Timeout | null = null; + #disposed = false; + #windowStartedAt = Date.now(); + readonly #buckets = new Map>(); + + public constructor(telemetry: TelemetryReporter) { + this.#telemetry = telemetry; + if (telemetry !== NOOP_TELEMETRY_REPORTER) { + this.#scheduleNextWindow(); + } + } + + public recordResponse(response: AxiosResponse): void { + this.#record( + response.config as RequestConfigWithMeta, + response.status, + false, + ); + } + + public recordError(error: unknown): void { + if (!isAxiosError(error) || !error.config) { + return; + } + this.#record( + error.config as RequestConfigWithMeta, + error.response?.status, + !error.response, + ); + } + + public dispose(): void { + if (this.#disposed) { + return; + } + try { + this.#flush(); + } finally { + this.#disposed = true; + if (this.#timer) { + clearTimeout(this.#timer); + this.#timer = null; + } + } + } + + #record( + config: RequestConfigWithMeta, + statusCode: number | undefined, + networkError: boolean, + ): void { + if (this.#disposed) { + return; + } + + const method = formatMethod(config.method); + const route = normalizeHttpRoute(config.url, config.baseURL); + const bucket = this.#getOrCreateBucket(method, route); + + const durationMs = elapsedMs(config); + if (durationMs !== undefined) { + bucket.durationsMs.push(durationMs); + } + + if (networkError || statusCode === undefined) { + bucket.countNetworkError += 1; + } else if (statusCode >= 100 && statusCode < 200) { + bucket.count1xx += 1; + } else 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; + } + } + + #getOrCreateBucket(method: string, route: string): HttpRequestBucket { + let byRoute = this.#buckets.get(method); + if (!byRoute) { + byRoute = new Map(); + this.#buckets.set(method, byRoute); + } + let bucket = byRoute.get(route); + if (!bucket) { + bucket = { + count1xx: 0, + count2xx: 0, + count3xx: 0, + count4xx: 0, + count5xx: 0, + countNetworkError: 0, + durationsMs: [], + }; + byRoute.set(route, bucket); + } + return bucket; + } + + #flush(): void { + const elapsedSeconds = Math.max( + 1, + Math.round((Date.now() - this.#windowStartedAt) / 1000), + ); + for (const [method, byRoute] of this.#buckets) { + for (const [route, bucket] of byRoute) { + const sortedDurations = bucket.durationsMs.toSorted((a, b) => a - b); + this.#telemetry.log( + EVENT_NAME, + { method, route }, + { + window_seconds: elapsedSeconds, + count_1xx: bucket.count1xx, + count_2xx: bucket.count2xx, + count_3xx: bucket.count3xx, + count_4xx: bucket.count4xx, + count_5xx: bucket.count5xx, + count_network_error: bucket.countNetworkError, + p50_duration_ms: percentile(sortedDurations, 0.5), + p95_duration_ms: percentile(sortedDurations, 0.95), + p99_duration_ms: percentile(sortedDurations, 0.99), + }, + ); + } + } + this.#buckets.clear(); + this.#windowStartedAt = Date.now(); + } + + #scheduleNextWindow(): void { + if (this.#disposed) { + return; + } + this.#timer = setTimeout(() => { + try { + this.#flush(); + } finally { + this.#scheduleNextWindow(); + } + }, WINDOW_SECONDS * 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; + } + } + // No matching rule. Pass through; add a rule above if cardinality grows. + return `/${segments.join("/")}`; +} + +function normalizeByRule( + segments: readonly string[], + rule: readonly string[], +): string | undefined { + if (segments.length < rule.length) { + return undefined; + } + + const normalized: string[] = []; + for (const [index, ruleSegment] of rule.entries()) { + if (ruleSegment === ID_PLACEHOLDER || ruleSegment === NAME_PLACEHOLDER) { + normalized.push(ruleSegment); + continue; + } + if (segments[index] !== ruleSegment) { + return undefined; + } + normalized.push(segments[index]); + } + + // Trailing segments pass through. If a tail can hold an ID, add a rule. + return `/${[...normalized, ...segments.slice(rule.length)].join("/")}`; +} + +function parsePathSegments(url: string, baseURL?: string): string[] { + try { + return new URL(url, baseURL ?? "http://coder.invalid").pathname + .split("/") + .filter(Boolean); + } catch { + return []; + } +} + +function elapsedMs( + config: RequestConfigWithMeta | undefined, +): number | undefined { + const startedAt = config?.metadata?.startedAt; + return typeof startedAt === "number" + ? Math.max(0, Date.now() - startedAt) + : undefined; +} + +function percentile(sortedValues: readonly number[], p: number): number { + if (sortedValues.length === 0) { + return 0; + } + const index = Math.ceil(sortedValues.length * p) - 1; + return sortedValues[Math.max(0, index)]; +} diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 0a63973c..69fdd006 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -212,7 +212,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(baseUrl, token, this.logger); + const workspaceClient = CoderApi.create( + baseUrl, + 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..b700ccef 100644 --- a/src/settings/telemetry.ts +++ b/src/settings/telemetry.ts @@ -3,7 +3,7 @@ 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"; /** Telemetry level. Falls back to `local` for unknown or invalid values. */ export function readTelemetryLevel( @@ -46,17 +46,9 @@ const LOCAL_SINK_MINIMUMS: LocalSinkConfig = { 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 = readObject(cfg.get(LOCAL_TELEMETRY_SETTING)); + 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 +58,21 @@ export function readLocalSinkConfig( maxTotalBytes: read("maxTotalBytes"), }; } + +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..d721670d --- /dev/null +++ b/src/telemetry/reporter.ts @@ -0,0 +1,33 @@ +import { NOOP_SPAN, type Span } from "./span"; + +import type { CallerMeasurements, CallerProperties } from "./event"; + +/** + * Narrow reporting surface so callers don't have to depend on the full + * TelemetryService. Pass NOOP_TELEMETRY_REPORTER to opt out. + */ +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 a3dd0a45..05ac1482 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/src/telemetry/sinks/localJsonlSink.ts b/src/telemetry/sinks/localJsonlSink.ts index 3cfe94ad..5ac7fbb3 100644 --- a/src/telemetry/sinks/localJsonlSink.ts +++ b/src/telemetry/sinks/localJsonlSink.ts @@ -4,7 +4,7 @@ import * as vscode from "vscode"; import { watchConfigurationChanges } from "../../configWatcher"; import { - LOCAL_SINK_SETTING, + LOCAL_TELEMETRY_SETTING, readLocalSinkConfig, type LocalSinkConfig, } from "../../settings/telemetry"; @@ -148,13 +148,13 @@ export class LocalJsonlSink implements TelemetrySink, vscode.Disposable { return watchConfigurationChanges( [ { - setting: LOCAL_SINK_SETTING, + setting: LOCAL_TELEMETRY_SETTING, getValue: () => readLocalSinkConfig(vscode.workspace.getConfiguration()), }, ], (changes) => { - const next = changes.get(LOCAL_SINK_SETTING) as + const next = changes.get(LOCAL_TELEMETRY_SETTING) as | LocalSinkConfig | undefined; if (!next) { diff --git a/test/unit/api/coderApi.test.ts b/test/unit/api/coderApi.test.ts index b6eab26b..c132fb47 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,10 @@ 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 { + NOOP_TELEMETRY_REPORTER, + type TelemetryReporter, +} from "@/telemetry/reporter"; import { ReconnectingWebSocket } from "@/websocket/reconnectingWebSocket"; import { @@ -35,6 +37,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 +99,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(() => { @@ -115,8 +125,8 @@ describe("CoderApi", () => { }); afterEach(() => { - // Dispose any api created during the test to clean up config watchers api?.dispose(); + vi.useRealTimers(); }); describe("HTTP Interceptors", () => { @@ -229,6 +239,33 @@ describe("CoderApi", () => { ); }); + it("rolls HTTP responses into telemetry", async () => { + vi.useFakeTimers(); + const log = vi.fn(); + api = createApi(CODER_URL, AXIOS_TOKEN, { + ...NOOP_TELEMETRY_REPORTER, + log, + }); + + await api.getAxiosInstance().get("/api/v2/workspaces/abc-123"); + // WINDOW_SECONDS is 60 in the implementation. + await vi.advanceTimersByTimeAsync(60_000); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + window_seconds: 60, + count_1xx: 0, + count_2xx: 1, + count_3xx: 0, + count_4xx: 0, + count_5xx: 0, + count_network_error: 0, + }), + ); + }); + 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..fce97c26 --- /dev/null +++ b/test/unit/logging/httpRequestsTelemetry.test.ts @@ -0,0 +1,304 @@ +import { AxiosError, AxiosHeaders, type AxiosResponse } from "axios"; +import { + afterEach, + beforeEach, + describe, + expect, + it, + type Mock, + 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 RequestOptions { + readonly method?: string; + readonly url: string; + readonly status?: number; + readonly durationMs?: number; +} + +// Mirrors WINDOW_SECONDS in src/logging/httpRequestsTelemetry.ts. +const WINDOW_SECONDS = 60; + +describe("HttpRequestsTelemetry", () => { + let log: Mock; + let rollup: HttpRequestsTelemetry; + + const start = () => { + const reporter: TelemetryReporter = { ...NOOP_TELEMETRY_REPORTER, log }; + rollup = new HttpRequestsTelemetry(reporter); + return rollup; + }; + + beforeEach(() => { + vi.useFakeTimers(); + log = vi.fn(); + }); + + afterEach(() => { + rollup?.dispose(); + vi.useRealTimers(); + }); + + it("emits one event per active method and route at the window boundary", async () => { + start(); + 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 advanceOneWindow(); + + expect(log).toHaveBeenCalledTimes(2); + expect(log).toHaveBeenNthCalledWith( + 1, + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + { + window_seconds: WINDOW_SECONDS, + count_1xx: 0, + count_2xx: 2, + count_3xx: 0, + count_4xx: 0, + count_5xx: 0, + count_network_error: 0, + p50_duration_ms: 100, + p95_duration_ms: 200, + p99_duration_ms: 200, + }, + ); + expect(log).toHaveBeenNthCalledWith( + 2, + "http.requests", + { method: "POST", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ count_2xx: 1 }), + ); + }); + + it("counts status code classes and network errors", async () => { + start(); + const route = "/api/v2/users/danny/workspaces"; + recordResponse(rollup, { method: "POST", url: route, status: 101 }); + 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 advanceOneWindow(); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "POST", route: "/api/v2/users/{name}/workspaces" }, + expect.objectContaining({ + count_1xx: 1, + count_2xx: 1, + count_3xx: 1, + count_4xx: 1, + count_5xx: 1, + count_network_error: 1, + }), + ); + }); + + it("emits nothing for empty windows", async () => { + start(); + await advanceOneWindow(); + expect(log).not.toHaveBeenCalled(); + }); + + it("is inert when constructed with the NOOP reporter", async () => { + // Throwaway clients pass NOOP and may never dispose, so no timer. + rollup = new HttpRequestsTelemetry(NOOP_TELEMETRY_REPORTER); + recordResponse(rollup, { + method: "GET", + url: "/api/v2/workspaces/abc", + status: 200, + }); + await vi.advanceTimersByTimeAsync(WINDOW_SECONDS * 10 * 1000); + expect(vi.getTimerCount()).toBe(0); + }); + + it("calculates nearest-rank p50, p95, p99", async () => { + start(); + for (let durationMs = 10; durationMs <= 200; durationMs += 10) { + recordResponse(rollup, { + method: "GET", + url: "/api/v2/workspaces/ws-id", + status: 200, + durationMs, + }); + } + + await advanceOneWindow(); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + p50_duration_ms: 100, + p95_duration_ms: 190, + p99_duration_ms: 200, + }), + ); + }); + + it("skips duration when request metadata is missing", async () => { + start(); + rollup.recordResponse({ + data: {}, + status: 200, + statusText: "OK", + headers: {}, + config: { + headers: new AxiosHeaders(), + method: "GET", + url: "/api/v2/workspaces/abc", + }, + } as AxiosResponse); + + await advanceOneWindow(); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ + count_2xx: 1, + p50_duration_ms: 0, + p95_duration_ms: 0, + p99_duration_ms: 0, + }), + ); + }); + + it("flushes any pending bucket on dispose", () => { + start(); + recordResponse(rollup, { + method: "GET", + url: "/api/v2/workspaces/abc", + status: 200, + }); + + rollup.dispose(); + + expect(log).toHaveBeenCalledWith( + "http.requests", + { method: "GET", route: "/api/v2/workspaces/{id}" }, + expect.objectContaining({ count_2xx: 1 }), + ); + }); + + it("ignores non-axios errors", async () => { + start(); + rollup.recordError(new Error("not an axios error")); + rollup.recordError("string error"); + + await advanceOneWindow(); + expect(log).not.toHaveBeenCalled(); + }); + + 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/organizations/9f0f7f37-dfb7-4f4b-bcb8-c7062c7550fc/members/danny", + "/api/v2/organizations/{id}/members/{name}", + ], + [ + "/api/v2/workspaceagents/9f0f7f37-dfb7-4f4b-bcb8-c7062c7550fc/logs", + "/api/v2/workspaceagents/{id}/logs", + ], + [ + "/api/v2/workspaces/0196ac60-0cf9-7c6b-ba8e-925c3e83bb9f/builds/42", + "/api/v2/workspaces/{id}/builds/{id}", + ], + // No rule match: route is passed through verbatim. + ["/api/v2/buildinfo", "/api/v2/buildinfo"], + [undefined, ""], + ["", ""], + ["http://%", ""], + ])("normalizes %s", (url, expected) => { + expect(normalizeHttpRoute(url)).toBe(expected); + }); +}); + +async function advanceOneWindow(): Promise { + await vi.advanceTimersByTimeAsync(WINDOW_SECONDS * 1000); +} + +function recordResponse( + rollup: HttpRequestsTelemetry, + options: RequestOptions, +): void { + rollup.recordResponse({ + data: {}, + status: options.status ?? 200, + statusText: "", + headers: {}, + config: makeRequestConfig(options), + } as AxiosResponse); +} + +function recordAxiosError( + rollup: HttpRequestsTelemetry, + options: RequestOptions, +): void { + const config = makeRequestConfig(options); + const response = options.status + ? ({ + data: {}, + status: options.status, + statusText: "", + headers: {}, + config, + } as AxiosResponse) + : undefined; + rollup.recordError( + new AxiosError("Request failed", undefined, config, {}, response), + ); +} + +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..a585613a 100644 --- a/test/unit/settings/telemetry.test.ts +++ b/test/unit/settings/telemetry.test.ts @@ -2,7 +2,7 @@ import { beforeEach, describe, expect, it } from "vitest"; import { LOCAL_SINK_DEFAULTS, - LOCAL_SINK_SETTING, + LOCAL_TELEMETRY_SETTING, TELEMETRY_LEVEL_SETTING, readLocalSinkConfig, readTelemetryLevel, @@ -44,7 +44,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 +57,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 +68,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 +86,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, }); diff --git a/test/unit/telemetry/sinks/localJsonlSink.test.ts b/test/unit/telemetry/sinks/localJsonlSink.test.ts index 55da1ddf..745bac6c 100644 --- a/test/unit/telemetry/sinks/localJsonlSink.test.ts +++ b/test/unit/telemetry/sinks/localJsonlSink.test.ts @@ -2,7 +2,10 @@ import { vol } from "memfs"; import * as fsPromises from "node:fs/promises"; import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; -import { LOCAL_SINK_SETTING, type LocalSinkConfig } from "@/settings/telemetry"; +import { + LOCAL_TELEMETRY_SETTING, + type LocalSinkConfig, +} from "@/settings/telemetry"; import { LocalJsonlSink } from "@/telemetry/sinks/localJsonlSink"; import { @@ -67,7 +70,7 @@ describe("LocalJsonlSink", () => { config: Partial = {}, sessionId = SESSION_ID, ) { - provider.set(LOCAL_SINK_SETTING, { + provider.set(LOCAL_TELEMETRY_SETTING, { flushIntervalMs: 1_000_000, ...config, }); @@ -420,7 +423,7 @@ describe("LocalJsonlSink", () => { sink.write(makeEvent()); expect(vol.existsSync(todaysFile())).toBe(false); - provider.set(LOCAL_SINK_SETTING, { + provider.set(LOCAL_TELEMETRY_SETTING, { flushIntervalMs: 1_000_000, flushBatchSize: 3, });