diff --git a/CHANGELOG.md b/CHANGELOG.md index 6dda93f906..b1c4b35055 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,23 @@ from published versions since it shows up in the VS Code extension changelog tab and is confusing to users. Add it back between releases if needed. --> +## Unreleased + +### Added + +- Add `coder.connectionLogBuffer.size` to keep recent below-level Coder output + channel entries in memory and replay them into the channel when a connection + fails terminally or you collect a support bundle, so Support can diagnose + connection failures without asking you to reproduce with debug logging on. Set + to `0` to disable. + +### Fixed + +- Stop retrying after an unrecoverable WebSocket close (`1002`/`1003`) and + replay the buffered connection logs instead. Close codes never reached the + reconnect logic, so these closes retried forever. Server-initiated normal + closes (`1000`/`1001`) keep reconnecting. + ## [v1.16.3](https://github.com/coder/vscode-coder/releases/tag/v1.16.3) 2026-09-14 ### Changed diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 5f5d53fa9a..8c3cc7b3d1 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -132,6 +132,32 @@ next to the code: **[`src/instrumentation/CONVENTIONS.md`](src/instrumentation/CONVENTIONS.md)** +## Logging + +The extension logs to the "Coder" output channel, a `LogOutputChannel` that gates +messages by the level chosen in its gear menu. To help Support diagnose +connection failures without asking users to reproduce with debug logging enabled, +a `BufferingLogger` ([`src/logging/logBuffer.ts`](src/logging/logBuffer.ts)) +wraps the channel and keeps a bounded, in-memory ring of the entries that sit +**below** the current level, which the channel would otherwise drop. + +When a WebSocket fails terminally, a remote session closes after a failed or +canceled open, or you collect a support bundle, the extension replays the ring +into the channel. The first physical line of each replayed entry carries a +`[buffered]` marker with its original timestamp and level, and any continuation +lines carry the bare marker. +Capture is best-effort: the channel writes on its own schedule, so a bundle may +miss the most recent lines, but a later failure flush still replays them. +Transient reconnects and intentional teardown never flush, and neither does a +handshake `401` (a 401 explains itself, and with OAuth a refresh reconnects the +same socket). Nothing is recorded or flushed while the channel is at `Off`. + +The buffer size is set by `coder.connectionLogBuffer.size` (number of entries; +`0` disables it) and lives in memory, so a hard kill or out-of-memory event +loses it. Extension SSH debug logs that pass through the shared logger are +buffered; the CLI `ProxyCommand` file logs under `coder.proxyLogDirectory` are +not, since support bundles already collect them from disk. + ## Testing There are a few ways you can test the "Open in VS Code" flow: diff --git a/package.json b/package.json index 982ec1a0f9..5e6b4c890e 100644 --- a/package.json +++ b/package.json @@ -215,6 +215,13 @@ "minimum": 0, "default": 250 }, + "coder.connectionLogBuffer.size": { + "markdownDescription": "Maximum number of log entries below the Coder output channel's log level to keep in memory. When a connection fails terminally or you collect a support bundle, the extension replays them into the channel so a bundle can carry the detail leading up to the failure without debug logging enabled beforehand. Capture is best-effort, since the channel writes on its own schedule. Set to `0` to disable.", + "type": "number", + "minimum": 0, + "maximum": 10000, + "default": 1000 + }, "coder.httpClientLogLevel": { "markdownDescription": "Controls the verbosity of HTTP client logging. This affects what details are logged for each HTTP request and response.", "type": "string", diff --git a/src/api/coderApi.ts b/src/api/coderApi.ts index c401cb9e46..d47888517b 100644 --- a/src/api/coderApi.ts +++ b/src/api/coderApi.ts @@ -26,12 +26,13 @@ import { } from "../logging/httpLogger"; import { HttpRequestsTelemetry } from "../logging/httpRequestsTelemetry"; import { - HttpClientLogLevel, type RequestConfigWithMeta, + type HttpClientLogLevel, } from "../logging/types"; import { sizeOf } from "../logging/utils"; import { AuthConfigTracker } from "../settings/authConfig"; import { getHeaderCommand } from "../settings/headers"; +import { readHttpClientLogLevel } from "../settings/logger"; import { NOOP_TELEMETRY_REPORTER, type TelemetryReporter, @@ -48,6 +49,7 @@ import { type SocketFactory, } from "../websocket/reconnectingWebSocket"; import { SseConnection } from "../websocket/sseConnection"; +import { handshakeStatus } from "../websocket/utils"; import { getRefreshCommand, refreshCertificates } from "./certificateRefresh"; import { @@ -69,6 +71,7 @@ import type { } from "coder/site/src/api/typesGenerated"; import type { ClientOptions } from "ws"; +import type { ConnectionStateReason } from "../instrumentation/websocket"; import type { Logger } from "../logging/logger"; import type { CloseEvent, @@ -125,6 +128,10 @@ export class CoderApi extends Api implements vscode.Disposable { private readonly telemetry: TelemetryReporter, private readonly httpRequestsTelemetry: HttpRequestsTelemetry, private readonly authConfigTracker: AuthConfigTracker, + private readonly onConnectionFailure?: ( + reason: ConnectionStateReason, + route: string, + ) => void, ) { super(); wrapWithValidation(this); @@ -145,6 +152,10 @@ export class CoderApi extends Api implements vscode.Disposable { token: string | undefined, output: Logger, telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, + onConnectionFailure?: ( + reason: ConnectionStateReason, + route: string, + ) => void, ): CoderApi { const httpRequestsTelemetry = new HttpRequestsTelemetry(telemetry); const authConfigTracker = new AuthConfigTracker(); @@ -153,6 +164,7 @@ export class CoderApi extends Api implements vscode.Disposable { telemetry, httpRequestsTelemetry, authConfigTracker, + onConnectionFailure, ); client.getAxiosInstance().defaults.timeout = DEFAULT_REQUEST_TIMEOUT_MS; client.getAxiosInstance().defaults.headers.common[BAGGAGE_HEADER] = @@ -282,9 +294,10 @@ export class CoderApi extends Api implements vscode.Disposable { watchTargets: string[], options?: ClientOptions, ) => { - return this.createReconnectingSocket(() => + const apiRoute = "/api/v2/notifications/inbox/watch"; + return this.createReconnectingSocket(apiRoute, () => this.createOneWayWebSocket({ - apiRoute: "/api/v2/notifications/inbox/watch", + apiRoute, searchParams: { format: "plaintext", templates: watchTemplates.join(","), @@ -296,9 +309,10 @@ export class CoderApi extends Api implements vscode.Disposable { }; watchWorkspace = async (workspace: Workspace, options?: ClientOptions) => { - return this.createReconnectingSocket(() => + const apiRoute = `/api/v2/workspaces/${workspace.id}/watch-ws`; + return this.createReconnectingSocket(apiRoute, () => this.createStreamWithSseFallback({ - apiRoute: `/api/v2/workspaces/${workspace.id}/watch-ws`, + apiRoute, fallbackApiRoute: `/api/v2/workspaces/${workspace.id}/watch`, options, }), @@ -309,9 +323,10 @@ export class CoderApi extends Api implements vscode.Disposable { agentId: WorkspaceAgent["id"], options?: ClientOptions, ) => { - return this.createReconnectingSocket(() => + const apiRoute = `/api/v2/workspaceagents/${agentId}/watch-metadata-ws`; + return this.createReconnectingSocket(apiRoute, () => this.createStreamWithSseFallback({ - apiRoute: `/api/v2/workspaceagents/${agentId}/watch-metadata-ws`, + apiRoute, fallbackApiRoute: `/api/v2/workspaceagents/${agentId}/watch-metadata`, options, }), @@ -530,17 +545,18 @@ export class CoderApi extends Api implements vscode.Disposable { * Check if an error is a 404 Not Found error. */ private is404Error(error: unknown): boolean { - const msg = error instanceof Error ? error.message : String(error); - return msg.includes(String(HttpStatusCode.NOT_FOUND)); + return handshakeStatus(error) === HttpStatusCode.NOT_FOUND; } /** * Create a ReconnectingWebSocket and track it for lifecycle management. */ private async createReconnectingSocket( + apiRoute: string, socketFactory: SocketFactory, ): Promise> { const options: ReconnectingWebSocketOptions = { + route: apiRoute, onCertificateRefreshNeeded: async () => { const refreshCommand = getRefreshCommand(); if (!refreshCommand) { @@ -548,6 +564,7 @@ export class CoderApi extends Api implements vscode.Disposable { } return refreshCertificates(refreshCommand, this.output); }, + onConnectionFailure: this.onConnectionFailure, telemetry: this.telemetry, }; @@ -814,12 +831,5 @@ function getSize(headers: AxiosHeaders, data: unknown): number | undefined { } function getLogLevel(): HttpClientLogLevel { - const logLevelStr = vscode.workspace - .getConfiguration() - .get( - "coder.httpClientLogLevel", - HttpClientLogLevel[HttpClientLogLevel.BASIC], - ) - .toUpperCase(); - return HttpClientLogLevel[logLevelStr as keyof typeof HttpClientLogLevel]; + return readHttpClientLogLevel(vscode.workspace.getConfiguration()); } diff --git a/src/commands.ts b/src/commands.ts index 3ce889b52e..9a337f7eb3 100644 --- a/src/commands.ts +++ b/src/commands.ts @@ -84,6 +84,7 @@ import type { MementoManager } from "./core/mementoManager"; import type { PathResolver } from "./core/pathResolver"; import type { SecretsManager, SessionAuth } from "./core/secretsManager"; import type { DeploymentManager } from "./deployment/deploymentManager"; +import type { ConnectionLogBuffer } from "./logging/logBuffer"; import type { Logger } from "./logging/logger"; import type { LoginCoordinator, LoginMethod } from "./login/loginCoordinator"; import type { TelemetryService } from "./telemetry/service"; @@ -168,6 +169,7 @@ export class Commands { private readonly authTelemetry: AuthTelemetry; private readonly diagnosticTelemetry: DiagnosticTelemetry; private readonly workspaceOpenTelemetry: WorkspaceOpenTelemetry; + private readonly connectionLogBuffer: ConnectionLogBuffer; // These will only be populated when actively connected to a workspace and are // used in commands. Because commands can be executed by the user, it is not @@ -193,6 +195,7 @@ export class Commands { this.telemetryService, ); this.logger = serviceContainer.getLogger(); + this.connectionLogBuffer = serviceContainer.getConnectionLogBuffer(); this.pathResolver = serviceContainer.getPathResolver(); this.mementoManager = serviceContainer.getMementoManager(); this.secretsManager = serviceContainer.getSecretsManager(); @@ -486,6 +489,11 @@ export class Commands { : []; progress.report({ message: "Collecting diagnostics..." }); + // Flush buffered below-level connection logs before the CLI runs so + // the channel has time to write them to disk; retain the ring so a + // later failure flush still replays them. Best-effort: the channel + // writes on its own schedule, so the tail may not land in this bundle. + this.connectionLogBuffer.flush("support_bundle", { retain: true }); await cliExec.supportBundle(env, workspaceId, { outputPath: outputUri.fsPath, agentName, diff --git a/src/core/container.ts b/src/core/container.ts index 56cd0edf83..a39e26503b 100644 --- a/src/core/container.ts +++ b/src/core/container.ts @@ -1,10 +1,19 @@ import * as vscode from "vscode"; +import { watchConfigurationChanges } from "../configWatcher"; import { AuthTelemetry } from "../instrumentation/auth"; +import { + BufferingLogger, + type ConnectionLogBuffer, +} from "../logging/logBuffer"; import { prefixLogger } from "../logging/prefixLogger"; import { shortId } from "../logging/utils"; import { LoginCoordinator } from "../login/loginCoordinator"; import { OAuthCallback } from "../oauth/oauthCallback"; +import { + CONNECTION_LOG_BUFFER_SIZE_SETTING, + readConnectionLogBufferSize, +} from "../settings/logger"; import { buildSession, extractExtensionVersion } from "../telemetry/event"; import { TelemetryService } from "../telemetry/service"; import { LocalJsonlSink } from "../telemetry/sinks/localJsonlSink"; @@ -29,7 +38,8 @@ import type { Logger } from "../logging/logger"; */ export class ServiceContainer implements vscode.Disposable { private readonly outputChannel: vscode.LogOutputChannel; - private readonly logger: Logger; + private readonly logger: BufferingLogger; + private readonly connectionLogBufferConfigSubscription: vscode.Disposable; private readonly pathResolver: PathResolver; private readonly mementoManager: MementoManager; private readonly secretsManager: SecretsManager; @@ -48,9 +58,21 @@ export class ServiceContainer implements vscode.Disposable { this.outputChannel = vscode.window.createOutputChannel("Coder", { log: true, }); - this.logger = prefixLogger( + const readSize = () => + readConnectionLogBufferSize(vscode.workspace.getConfiguration()); + this.logger = new BufferingLogger( + prefixLogger(this.outputChannel, `[session ${shortId(sessionId)}]`), this.outputChannel, - `[session ${shortId(sessionId)}]`, + readSize(), + ); + this.connectionLogBufferConfigSubscription = watchConfigurationChanges( + [ + { + setting: CONNECTION_LOG_BUFFER_SIZE_SETTING, + getValue: readSize, + }, + ], + () => this.logger.setCapacity(readSize()), ); this.pathResolver = new PathResolver( context.globalStorageUri.fsPath, @@ -148,6 +170,11 @@ export class ServiceContainer implements vscode.Disposable { return this.logger; } + /** The connection log buffer that replays below-level entries on failure. */ + getConnectionLogBuffer(): ConnectionLogBuffer { + return this.logger; + } + getCliManager(): CliManager { return this.cliManager; } @@ -193,6 +220,7 @@ export class ServiceContainer implements vscode.Disposable { this.commandManager.dispose(); this.contextManager.dispose(); this.loginCoordinator.dispose(); + this.connectionLogBufferConfigSubscription.dispose(); try { await this.telemetryService.dispose(); } finally { diff --git a/src/extension.ts b/src/extension.ts index 8506c097d5..8feb074615 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -141,6 +141,7 @@ async function doActivate( deploymentSessionAuth?.token, output, telemetryService, + serviceContainer.getConnectionLogBuffer().onConnectionFailure, ); ctx.subscriptions.push(client); diff --git a/src/instrumentation/EVENTS.md b/src/instrumentation/EVENTS.md index f42db9b421..9c5c5f42e5 100644 --- a/src/instrumentation/EVENTS.md +++ b/src/instrumentation/EVENTS.md @@ -428,7 +428,7 @@ Emitted by `WebSocketTelemetry`. These events share one value set, **ConnectionStateReason**: `initial_connect`, `manual_reconnect`, `certificate_refresh`, `scheduled_reconnect`, `open`, `disconnect`, `dispose`, `unrecoverable_close`, `unrecoverable_http`, -`certificate_error`, `connection_error`, `normal_close`, `unexpected_close`. +`certificate_error`, `connection_error`, `unexpected_close`. ### Logs @@ -451,11 +451,11 @@ These events share one value set, **ConnectionStateReason**: `initial_connect`, Emitted as an error log (with the `error` block) when a socket error caused the drop. -| Attribute | Values | -| -------------------------------------- | --------------------------------------------------------------------------------------------------------------- | -| `cause` | `manual_disconnect`, `replaced`, `unrecoverable_close`, `normal_close`, `unexpected_close`, `disposed`, `error` | -| `close_code` | WebSocket close code (when known) | -| `connection_duration_ms` (measurement) | time the connection was open | +| Attribute | Values | +| -------------------------------------- | ----------------------------------------------------------------------------------------------- | +| `cause` | `manual_disconnect`, `replaced`, `unrecoverable_close`, `unexpected_close`, `disposed`, `error` | +| `close_code` | WebSocket close code (when known) | +| `connection_duration_ms` (measurement) | time the connection was open | #### `connection.reconnect_resolved` diff --git a/src/instrumentation/websocket.ts b/src/instrumentation/websocket.ts index 4fcd45d062..98c54bab6f 100644 --- a/src/instrumentation/websocket.ts +++ b/src/instrumentation/websocket.ts @@ -16,14 +16,12 @@ export type ConnectionStateReason = | "unrecoverable_http" | "certificate_error" | "connection_error" - | "normal_close" | "unexpected_close"; export type ConnectionDropCause = | "manual_disconnect" | "replaced" | "unrecoverable_close" - | "normal_close" | "unexpected_close" | "disposed" | "error"; diff --git a/src/logging/formatters.ts b/src/logging/formatters.ts index b962b1dec1..331a67b990 100644 --- a/src/logging/formatters.ts +++ b/src/logging/formatters.ts @@ -24,6 +24,7 @@ const SENSITIVE_BODY_FIELDS: ReadonlySet> = new Set([ "id_token", "password", "refresh_token", + "registration_access_token", "token", ]); diff --git a/src/logging/logBuffer.ts b/src/logging/logBuffer.ts new file mode 100644 index 0000000000..31e3679641 --- /dev/null +++ b/src/logging/logBuffer.ts @@ -0,0 +1,175 @@ +import { safeStringify } from "./utils"; + +import type { Logger } from "./logger"; + +/** + * Numeric severities matching `vscode.LogLevel` (Off=0, Trace=1, Debug=2, + * Info=3, Warning=4, Error=5). Kept as plain numbers so this module stays + * free of the VS Code API and easy to test. + */ +const SEVERITY = { + trace: 1, + debug: 2, + info: 3, + warn: 4, + error: 5, +} as const; + +type Level = keyof typeof SEVERITY; + +/** Sink methods that the output channel persists at any non-Off level. */ +type ReplaySink = "info" | "warn" | "error"; + +/** + * Character budget for the buffered text, independent of the entry count. Bounds + * worst-case memory when `httpClientLogLevel: body` makes each entry large. + */ +const MAX_BUFFERED_CHARS = 2_000_000; + +/** Entries replayed per channel call, so a flush is not one RPC per entry. */ +const REPLAY_CHUNK = 100; + +/** Replays buffered below-level log entries on a connection failure. */ +export interface ConnectionLogBuffer { + flush(reason: string, options?: { readonly retain?: boolean }): void; + readonly onConnectionFailure: (reason: string, route: string) => void; +} + +interface LogEntry { + readonly atMs: number; + readonly level: Level; + /** Message and args formatted once at record time; holds no live references. */ + readonly text: string; +} + +/** + * Buffers entries below the current log level and replays them on failure at a + * level the output channel persists. + */ +export class BufferingLogger implements Logger, ConnectionLogBuffer { + private entries: LogEntry[] = []; + private chars = 0; + + public constructor( + private readonly inner: Logger, + private readonly channel: { readonly logLevel: number }, + private capacity: number, + ) {} + + public readonly trace = this.wrap("trace"); + public readonly debug = this.wrap("debug"); + public readonly info = this.wrap("info"); + public readonly warn = this.wrap("warn"); + public readonly error = this.wrap("error"); + + /** + * Flush the buffer on a terminal socket failure, keyed by the + * ` ` string Support greps for. Arrow property so it can be + * passed by value as the socket's failure callback. + */ + public readonly onConnectionFailure = ( + reason: string, + route: string, + ): void => { + this.flush(`${reason} ${route}`); + }; + + public show(): void { + this.inner.show(); + } + + /** Resize the ring, keeping the most recent entries within both budgets. */ + public setCapacity(capacity: number): void { + this.capacity = capacity; + this.trim(); + } + + /** + * Replay buffered entries into the sink. No-op when empty. Clears the ring by + * default, so consecutive failures never replay the same entries twice; pass + * `retain` for a snapshot flush (a support bundle) that must not disturb a + * later failure flush. + */ + public flush( + reason: string, + options: { readonly retain?: boolean } = {}, + ): void { + // The channel writes nothing at Off. Keep the entries for the next flush; + // nothing new is recorded while Off. + if (this.channel.logLevel === 0) { + return; + } + if (this.entries.length === 0) { + return; + } + const entries = this.entries; + if (!options.retain) { + this.entries = []; + this.chars = 0; + } + + const sink = this.replaySink(); + this.inner[sink]( + `[buffered] replaying ${entries.length} buffered entries (${reason})`, + ); + const lines = entries.map((entry) => + `[buffered] ${new Date(entry.atMs).toISOString()} ${entry.level.toUpperCase()} ${entry.text}`.replaceAll( + "\n", + "\n[buffered] ", + ), + ); + for (let i = 0; i < lines.length; i += REPLAY_CHUNK) { + this.inner[sink](lines.slice(i, i + REPLAY_CHUNK).join("\n")); + } + this.inner[sink](`[buffered] end of buffered logs (${reason})`); + } + + /** Pass a call through to the sink and buffer it when below the level. */ + private wrap(level: Level): (message: string, ...args: unknown[]) => void { + return (message, ...args) => { + this.record(level, message, args); + this.inner[level](message, ...args); + }; + } + + /** + * The least-verbose sink method that is still written at the current level, + * so replayed entries are persisted rather than dropped again. + */ + private replaySink(): ReplaySink { + const level = this.channel.logLevel; + if (level >= SEVERITY.error) { + return "error"; + } + if (level >= SEVERITY.warn) { + return "warn"; + } + return "info"; + } + + private record(level: Level, message: string, args: unknown[]): void { + if (this.capacity === 0 || SEVERITY[level] >= this.channel.logLevel) { + return; + } + const text = [message, ...args.map((arg) => safeStringify(arg) ?? "")].join( + " ", + ); + this.entries.push({ atMs: Date.now(), level, text }); + this.chars += text.length; + this.trim(); + } + + /** Evict oldest entries until both the count and character budgets hold. */ + private trim(): void { + while ( + this.entries.length > this.capacity || + this.chars > MAX_BUFFERED_CHARS + ) { + const removed = this.entries.shift(); + if (removed === undefined) { + break; + } + this.chars -= removed.text.length; + } + } +} diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 612da18f57..9c18dad9a9 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -280,6 +280,7 @@ export class Remote { token, this.logger, this.serviceContainer.getTelemetryService(), + this.serviceContainer.getConnectionLogBuffer().onConnectionFailure, ); disposables.push(workspaceClient); @@ -1093,6 +1094,7 @@ export class Remote { // closeRemote ends the current remote session. public async closeRemote() { + this.serviceContainer.getConnectionLogBuffer().flush("remote_closed"); await vscode.commands.executeCommand("workbench.action.remote.close"); } diff --git a/src/settings/logger.ts b/src/settings/logger.ts new file mode 100644 index 0000000000..fef56318c8 --- /dev/null +++ b/src/settings/logger.ts @@ -0,0 +1,50 @@ +import { HttpClientLogLevel } from "../logging/types"; + +import type { WorkspaceConfiguration } from "vscode"; + +export const CONNECTION_LOG_BUFFER_SIZE_SETTING = + "coder.connectionLogBuffer.size"; +export const DEFAULT_CONNECTION_LOG_BUFFER_SIZE = 1000; +/** + * Largest configurable capacity, in entries. + */ +export const MAX_CONNECTION_LOG_BUFFER_SIZE = 10_000; + +const HTTP_CLIENT_LOG_LEVEL_SETTING = "coder.httpClientLogLevel"; + +/** + * Buffer size in entries, clamped to the maximum; invalid values fall back + * to the default. + */ +export function readConnectionLogBufferSize( + cfg: Pick, +): number { + const value = cfg.get( + CONNECTION_LOG_BUFFER_SIZE_SETTING, + DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + ); + if (typeof value !== "number" || !Number.isFinite(value) || value < 0) { + return DEFAULT_CONNECTION_LOG_BUFFER_SIZE; + } + return Math.min(Math.floor(value), MAX_CONNECTION_LOG_BUFFER_SIZE); +} + +/** HTTP client logging verbosity. Falls back to `BASIC` for unknown values. */ +export function readHttpClientLogLevel( + cfg: Pick, +): HttpClientLogLevel { + const value = cfg.get( + HTTP_CLIENT_LOG_LEVEL_SETTING, + HttpClientLogLevel[HttpClientLogLevel.BASIC], + ); + // settings.json can hold a non-string (e.g. 2 or null) despite the schema; + // guard so the axios interceptors never throw on .toUpperCase(). + if (typeof value !== "string") { + return HttpClientLogLevel.BASIC; + } + return ( + HttpClientLogLevel[ + value.toUpperCase() as keyof typeof HttpClientLogLevel + ] ?? HttpClientLogLevel.BASIC + ); +} diff --git a/src/supportBundle/settings.ts b/src/supportBundle/settings.ts index 8517d4f1f4..db68e4eda1 100644 --- a/src/supportBundle/settings.ts +++ b/src/supportBundle/settings.ts @@ -17,6 +17,7 @@ const COLLECTED_SETTINGS: readonly string[] = [ "coder.autologin", "coder.binaryDestination", "coder.binarySource", + "coder.connectionLogBuffer.size", "coder.defaultUrl", "coder.disableNotifications", "coder.disableSignatureVerification", diff --git a/src/websocket/codes.ts b/src/websocket/codes.ts index f3fd95cdb5..1ea808fec0 100644 --- a/src/websocket/codes.ts +++ b/src/websocket/codes.ts @@ -51,9 +51,3 @@ export const UNRECOVERABLE_HTTP_CODES = new Set([ HttpStatusCode.GONE, HttpStatusCode.UPGRADE_REQUIRED, ]); - -/** Close codes indicating intentional closure - do not reconnect */ -export const NORMAL_CLOSURE_CODES = new Set([ - WebSocketCloseCode.NORMAL, - WebSocketCloseCode.GOING_AWAY, -]); diff --git a/src/websocket/oneWayWebSocket.ts b/src/websocket/oneWayWebSocket.ts index c028e593c4..a08b24f046 100644 --- a/src/websocket/oneWayWebSocket.ts +++ b/src/websocket/oneWayWebSocket.ts @@ -80,10 +80,18 @@ export class OneWayWebSocket< this.#socket.on("message", wrapped); this.#messageCallbacks.set(messageCallback, wrapped); - } else { - // For other events, cast and add directly - this.#socket.on(event, callback); + return; } + + // `ws` only exposes `.code`/`.reason` on the DOM-style CloseEvent from + // addEventListener; the `on()` emitter passes them positionally, which + // leaves `event.code` undefined for consumers. TypeScript cannot correlate + // `event` with `callback` across two parameters, so a cast is needed either + // way, and `ws` dispatches on the event name, so one cast covers all three. + this.#socket.addEventListener( + event as "open", + callback as EventHandler, + ); } removeEventListener( @@ -98,9 +106,13 @@ export class OneWayWebSocket< this.#socket.off("message", wrapper); this.#messageCallbacks.delete(messageCallback); } - } else { - this.#socket.off(event, callback); + return; } + + this.#socket.removeEventListener( + event as "open", + callback as EventHandler, + ); } close(code?: number, reason?: string): void { diff --git a/src/websocket/reconnectingWebSocket.ts b/src/websocket/reconnectingWebSocket.ts index a881599378..f67a16d13e 100644 --- a/src/websocket/reconnectingWebSocket.ts +++ b/src/websocket/reconnectingWebSocket.ts @@ -8,10 +8,11 @@ import { import { WebSocketCloseCode, - NORMAL_CLOSURE_CODES, + HttpStatusCode, UNRECOVERABLE_WS_CLOSE_CODES, UNRECOVERABLE_HTTP_CODES, } from "./codes"; +import { handshakeStatus } from "./utils"; import type { WebSocketEventType } from "coder/site/src/utils/OneWayWebSocket"; @@ -110,13 +111,20 @@ function reduceState( export type SocketFactory = () => Promise>; +/** Default failure callback for callers that do not observe connection failures. */ +const NOOP_CONNECTION_FAILURE = (): void => undefined; + export interface ReconnectingWebSocketOptions { initialBackoffMs?: number; maxBackoffMs?: number; jitterFactor?: number; telemetry: TelemetryReporter; + /** API route (pathname) of the socket, used to seed logging before the first connect resolves. */ + route: string; /** Callback invoked when a refreshable certificate error is detected. Returns true if refresh succeeded. */ onCertificateRefreshNeeded: () => Promise; + /** Callback invoked when the connection fails terminally (not a transient drop). */ + onConnectionFailure?: (reason: ConnectionStateReason, route: string) => void; } export class ReconnectingWebSocket< @@ -125,7 +133,9 @@ export class ReconnectingWebSocket< readonly #socketFactory: SocketFactory; readonly #logger: Logger; readonly #telemetry: WebSocketTelemetry; - readonly #options: Required>; + readonly #options: Required< + Omit + >; readonly #eventHandlers: { [K in WebSocketEventType]: Set>; } = { @@ -136,7 +146,10 @@ export class ReconnectingWebSocket< }; #currentSocket: UnidirectionalStream | null = null; - #lastRoute = "unknown"; // Cached route for logging when socket is closed + // Route to log while no socket is connected. Kept because the live URL + // diverges from the seeded route after an SSE fallback and after a redirect + // (followRedirects), so it is not simply the seeded value. + #lastRoute: string; #backoffMs: number; #reconnectTimeoutId: NodeJS.Timeout | null = null; #state: ConnectionState = ConnectionState.IDLE; @@ -178,7 +191,10 @@ export class ReconnectingWebSocket< maxBackoffMs: options.maxBackoffMs ?? 30000, jitterFactor: options.jitterFactor ?? 0.1, onCertificateRefreshNeeded: options.onCertificateRefreshNeeded, + onConnectionFailure: + options.onConnectionFailure ?? NOOP_CONNECTION_FAILURE, }; + this.#lastRoute = options.route; this.#backoffMs = this.#options.initialBackoffMs; this.#onDispose = onDispose; } @@ -282,7 +298,13 @@ export class ReconnectingWebSocket< private disconnectWithReason( reason: ConnectionStateReason, cause: ConnectionDropCause, - options: { code?: number; closeReason?: string; error?: unknown } = {}, + options: { + code?: number; + closeReason?: string; + error?: unknown; + /** Flush the connection log buffer: a genuine, surfaced failure. */ + failure?: boolean; + } = {}, ): void { if (!this.#dispatch({ type: "DISCONNECT" }, reason)) { return; @@ -293,6 +315,9 @@ export class ReconnectingWebSocket< error: options.error, }); this.clearCurrentSocket(options.code, options.closeReason); + if (options.failure) { + this.#options.onConnectionFailure(reason, this.#route); + } } public close(code?: number, reason?: string): void { @@ -396,24 +421,21 @@ export class ReconnectingWebSocket< if (UNRECOVERABLE_WS_CLOSE_CODES.has(event.code)) { this.#logger.error( - `WebSocket connection closed with unrecoverable error code ${event.code}`, + `WebSocket connection closed with unrecoverable error code ${event.code} for ${this.#route}`, ); this.disconnectWithReason("unrecoverable_close", "unrecoverable_close", { code: event.code, closeReason: event.reason, error: toCloseEventError(event), + failure: true, }); return; } - if (NORMAL_CLOSURE_CODES.has(event.code)) { - this.disconnectWithReason("normal_close", "normal_close", { - code: event.code, - closeReason: event.reason, - }); - return; - } - + // Every close that reaches here is server-initiated: intentional + // disconnect()/close() dispatch first and return early above. Normal + // codes such as coderd's liveness 1001 or a shutdown 1000 must reconnect, + // so they fall through to the backoff retry below. this.scheduleReconnect("unexpected_close", "unexpected_close", { code: event.code, error: toCloseEventError(event), @@ -515,12 +537,18 @@ export class ReconnectingWebSocket< return; } - if (this.isUnrecoverableHttpError(error)) { + const unrecoverableStatus = this.unrecoverableHttpStatus(error); + if (unrecoverableStatus !== undefined) { this.#logger.error( - `Unrecoverable HTTP error during connection for ${this.#route}`, + `Unrecoverable HTTP error (${unrecoverableStatus}) during connection for ${this.#route}`, error, ); - this.disconnectWithReason("unrecoverable_http", "error", { error }); + // A 401 explains itself, and with OAuth a refresh reconnects the same + // socket, so it never flushes. + this.disconnectWithReason("unrecoverable_http", "error", { + error, + failure: unrecoverableStatus !== HttpStatusCode.UNAUTHORIZED, + }); return; } @@ -530,7 +558,10 @@ export class ReconnectingWebSocket< if (await this.handleClientCertificateError(certError)) { this.#reconnectInternal("certificate_refresh"); } else { - this.disconnectWithReason("certificate_error", "error", { error }); + this.disconnectWithReason("certificate_error", "error", { + error, + failure: true, + }); } return; } @@ -540,16 +571,15 @@ export class ReconnectingWebSocket< } /** - * Check if an error message contains an unrecoverable HTTP status code. + * Returns the unrecoverable HTTP status carried by a failed handshake, or + * `undefined`. */ - private isUnrecoverableHttpError(error: unknown): boolean { - const message = (error as { message?: string }).message || String(error); - for (const code of UNRECOVERABLE_HTTP_CODES) { - if (message.includes(String(code))) { - return true; - } + private unrecoverableHttpStatus(error: unknown): number | undefined { + const status = handshakeStatus(error); + if (status === undefined) { + return undefined; } - return false; + return UNRECOVERABLE_HTTP_CODES.has(status) ? status : undefined; } private dispose(code?: number, reason?: string): void { diff --git a/src/websocket/utils.ts b/src/websocket/utils.ts index 8fa34c61ac..aa7a15fcbc 100644 --- a/src/websocket/utils.ts +++ b/src/websocket/utils.ts @@ -27,3 +27,21 @@ export function rawDataToString(data: RawData): string { return new TextDecoder().decode(data); } } + +/** + * Parses the HTTP status carried by a failed WebSocket or SSE handshake. + * + * `ws` rejects with `Unexpected server response: ` and `eventsource` + * with `Non-200 status code ()`. Matching the phrase before the digits + * keeps a host/port such as `127.0.0.1:4040` from masquerading as a status + * code. + */ +const HANDSHAKE_STATUS = + /(?:unexpected server response:|non-200 status code \()\s*(\d{3})/i; + +/** HTTP status from a failed `ws` or `eventsource` handshake, or `undefined`. */ +export function handshakeStatus(error: unknown): number | undefined { + const message = (error as { message?: string }).message || String(error); + const match = HANDSHAKE_STATUS.exec(message); + return match ? Number(match[1]) : undefined; +} diff --git a/test/mocks/testHelpers.ts b/test/mocks/testHelpers.ts index 9200a59705..95e8d17d4c 100644 --- a/test/mocks/testHelpers.ts +++ b/test/mocks/testHelpers.ts @@ -46,6 +46,7 @@ import type { PathResolver } from "@/core/pathResolver"; import type { SecretsManager } from "@/core/secretsManager"; import type { DeploymentManager } from "@/deployment/deploymentManager"; import type { Deployment } from "@/deployment/types"; +import type { ConnectionLogBuffer } from "@/logging/logBuffer"; import type { Logger } from "@/logging/logger"; import type { LoginCoordinator } from "@/login/loginCoordinator"; import type { NetworkInfo } from "@/remote/sshProcess"; @@ -644,6 +645,10 @@ export function createMockServiceContainer( return { getTelemetryService: () => telemetry, getLogger: () => logger, + getConnectionLogBuffer: (): ConnectionLogBuffer => ({ + flush: () => {}, + onConnectionFailure: () => {}, + }), getSecretsManager: () => require("secretsManager", overrides.secretsManager), getMementoManager: () => diff --git a/test/unit/api/coderApi.test.ts b/test/unit/api/coderApi.test.ts index b3eca3fc48..a4010c873b 100644 --- a/test/unit/api/coderApi.test.ts +++ b/test/unit/api/coderApi.test.ts @@ -37,6 +37,7 @@ import { NOOP_TELEMETRY_REPORTER, type TelemetryReporter, } from "@/telemetry/reporter"; +import { WebSocketCloseCode } from "@/websocket/codes"; import { ReconnectingWebSocket } from "@/websocket/reconnectingWebSocket"; import { @@ -114,8 +115,15 @@ describe("CoderApi", () => { url = CODER_URL, token = AXIOS_TOKEN, telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, + onConnectionFailure?: (reason: string) => void, ) => { - return CoderApi.create(url, token, mockLogger, telemetry); + return CoderApi.create( + url, + token, + mockLogger, + telemetry, + onConnectionFailure, + ); }; beforeEach(() => { @@ -457,15 +465,8 @@ describe("CoderApi", () => { beforeEach(() => { api = createApi(CODER_URL, AXIOS_TOKEN); - // createOneWayWebSocket waits for open, so we need to fire it - const mockWs = createMockWebSocket(wsUrl, { - on: vi.fn((event, handler) => { - if (event === "open") { - setImmediate(() => handler()); - } - return mockWs as Ws; - }), - }); + // createOneWayWebSocket waits for open, which the mock fires automatically. + const mockWs = createMockWebSocket(wsUrl); setupWebSocketMock(mockWs); }); @@ -574,6 +575,37 @@ describe("CoderApi", () => { }); }); + describe("connection failure callback", () => { + it("invokes onConnectionFailure on a terminal socket failure", async () => { + const onConnectionFailure = vi.fn(); + const failingApi = createApi( + CODER_URL, + AXIOS_TOKEN, + NOOP_TELEMETRY_REPORTER, + onConnectionFailure, + ); + const mockWs = createMockWebSocket( + `wss://${CODER_URL.replace("https://", "")}/api/v2/workspaceagents/${AGENT_ID}/watch-metadata-ws`, + ); + setupWebSocketMock(mockWs); + + const connection = await failingApi.watchAgentMetadata(AGENT_ID); + + // An unrecoverable close code is a terminal failure, not a retry. + mockWs.fireClose({ + code: WebSocketCloseCode.PROTOCOL_ERROR, + reason: "Unrecoverable", + wasClean: false, + }); + + expect(onConnectionFailure).toHaveBeenCalledWith( + "unrecoverable_close", + `/api/v2/workspaceagents/${AGENT_ID}/watch-metadata-ws`, + ); + connection.close(); + }); + }); + describe("SSE Fallback", () => { beforeEach(() => { api = createApi(); @@ -586,14 +618,6 @@ describe("CoderApi", () => { it("uses WebSocket when no errors occur", async () => { const mockWs = createMockWebSocket( `wss://${CODER_URL.replace("https://", "")}/api/v2/workspaceagents/${AGENT_ID}/watch-metadata`, - { - on: vi.fn((event, handler) => { - if (event === "open") { - setImmediate(() => handler()); - } - return mockWs as Ws; - }), - }, ); setupWebSocketMock(mockWs); @@ -620,17 +644,10 @@ describe("CoderApi", () => { const mockWs = createMockWebSocket( `wss://${CODER_URL.replace("https://", "")}/api/v2/test`, { - on: vi.fn((event: string, handler: (e: unknown) => void) => { - if (event === "error") { - setImmediate(() => { - handler({ - error: new Error("404 Not Found"), - message: "404 Not Found", - }); - }); - } - return mockWs as Ws; - }), + connectError: { + error: new Error("Unexpected server response: 404"), + message: "Unexpected server response: 404", + }, }, ); setupWebSocketMock(mockWs); @@ -667,14 +684,9 @@ describe("CoderApi", () => { vi.mocked(Ws).mockImplementation(function () { wsAttempts++; const mockWs = createMockWebSocket("wss://test", { - on: vi.fn((event: string, handler: (e: unknown) => void) => { - if (event === "error") { - setImmediate(() => - handler({ error: new Error("Something 404") }), - ); - } - return mockWs as Ws; - }), + connectError: { + error: new Error("Unexpected server response: 404"), + }, }); return mockWs as Ws; }); @@ -701,22 +713,13 @@ describe("CoderApi", () => { }); const setupAutoOpeningWebSocket = () => { - const sockets: Array> = []; - const handlers: Record void> = {}; + const sockets: MockWebSocket[] = []; vi.mocked(Ws).mockImplementation(function (url: string | URL) { - const mockWs = createMockWebSocket(String(url), { - on: vi.fn((event: string, handler: (...args: unknown[]) => void) => { - handlers[event] = handler; - if (event === "open") { - setImmediate(() => handler()); - } - return mockWs as Ws; - }), - }); + const mockWs = createMockWebSocket(String(url)); sockets.push(mockWs); return mockWs as Ws; }); - return { sockets, handlers }; + return { sockets }; }; describe("Reconnection on Host/Token Changes", () => { @@ -852,14 +855,7 @@ describe("CoderApi", () => { async ({ eventMessage, expectedMessage }) => { api = createApi(); const mockWs = createMockWebSocket("wss://test", { - on: vi.fn((event: string, handler: (e: unknown) => void) => { - if (event === "error") { - setImmediate(() => - handler({ error: undefined, message: eventMessage }), - ); - } - return mockWs as Ws; - }), + connectError: { error: undefined, message: eventMessage }, }); setupWebSocketMock(mockWs); @@ -1050,14 +1046,7 @@ describe("CoderApi", () => { it("disposes all tracked reconnecting sockets", async () => { const sockets: Array> = []; vi.mocked(Ws).mockImplementation(function (url: string | URL) { - const mockWs = createMockWebSocket(String(url), { - on: vi.fn((event, handler) => { - if (event === "open") { - setImmediate(() => handler()); - } - return mockWs as Ws; - }), - }); + const mockWs = createMockWebSocket(String(url)); sockets.push(mockWs); return mockWs as Ws; }); @@ -1123,12 +1112,12 @@ describe("CoderApi", () => { it("does not reconnect sockets in AWAITING_RETRY state when config changes", async () => { mockConfig.set("coder.insecure", false); - const { sockets, handlers } = setupAutoOpeningWebSocket(); + const { sockets } = setupAutoOpeningWebSocket(); api = createApi(CODER_URL, AXIOS_TOKEN); await api.watchAgentMetadata(AGENT_ID); // Trigger close with abnormal code to put socket in AWAITING_RETRY - handlers["close"]?.({ code: 1006, reason: "Abnormal closure" }); + sockets.at(-1)?.fireClose({ code: 1006, reason: "Abnormal closure" }); await tick(); mockConfig.set("coder.insecure", true); @@ -1145,13 +1134,13 @@ describe("CoderApi", () => { "reconnects sockets in DISCONNECTED state when %s changes", async (setting, before, after) => { mockConfig.set(setting, before); - const { sockets, handlers } = setupAutoOpeningWebSocket(); + const { sockets } = setupAutoOpeningWebSocket(); api = createApi(CODER_URL, AXIOS_TOKEN); await api.watchAgentMetadata(AGENT_ID); await tick(); // Trigger close with unrecoverable code to put socket in DISCONNECTED - handlers["close"]?.({ code: 1002, reason: "Protocol error" }); + sockets.at(-1)?.fireClose({ code: 1002, reason: "Protocol error" }); await tick(); mockConfig.set(setting, after); @@ -1178,17 +1167,68 @@ const mockAdapterImpl = vi.hoisted( }, ); +type MockWebSocket = Partial & { + fireClose: (event: { + code: number; + reason: string; + wasClean?: boolean; + }) => void; +}; + +interface MockWebSocketOptions { + /** Fire this error on connect instead of "open" to simulate a handshake failure. */ + connectError?: { error?: Error; message?: string }; +} + function createMockWebSocket( url: string, - overrides?: Partial, -): Partial { - return { + options: MockWebSocketOptions = {}, +): MockWebSocket { + // OneWayWebSocket registers open/close/error via addEventListener and only + // message via on(), mirroring the DOM/ws split in production. A Set per event + // with identity removal matches how production adds and removes each listener. + const listeners: Record void>> = { + open: new Set(), + close: new Set(), + error: new Set(), + message: new Set(), + }; + const mock: MockWebSocket = { url, - on: vi.fn(), - off: vi.fn(), + on: vi.fn((event: string, handler: (e: unknown) => void) => { + if (event === "message") { + listeners.message.add(handler); + } + return mock as Ws; + }), + off: vi.fn((event: string, handler: (e: unknown) => void) => { + if (event === "message") { + listeners.message.delete(handler); + } + return mock as Ws; + }), + addEventListener: vi.fn((event: string, handler: (e: unknown) => void) => { + listeners[event]?.add(handler); + if (event === "open" && !options.connectError) { + setImmediate(() => handler(new Event("open"))); + } + if (event === "error" && options.connectError) { + setImmediate(() => handler(options.connectError)); + } + }), + removeEventListener: vi.fn( + (event: string, handler: (e: unknown) => void) => { + listeners[event]?.delete(handler); + }, + ), close: vi.fn(), - ...overrides, + fireClose: (event) => { + for (const cb of listeners.close) { + cb(event); + } + }, }; + return mock; } type MockEventSource = Partial & { diff --git a/test/unit/command/updateWorkspace.telemetry.test.ts b/test/unit/command/updateWorkspace.telemetry.test.ts index a1776668c9..9747d86c65 100644 --- a/test/unit/command/updateWorkspace.telemetry.test.ts +++ b/test/unit/command/updateWorkspace.telemetry.test.ts @@ -30,6 +30,7 @@ function setup() { getDuplicateWorkspaceIpc: () => ({}), getSpeedtestPanelFactory: () => ({}), getNetcheckPanelFactory: () => ({}), + getConnectionLogBuffer: () => ({ flush: () => {} }), } as unknown as ServiceContainer; const commands = new Commands( container, diff --git a/test/unit/commands.netcheck.test.ts b/test/unit/commands.netcheck.test.ts index 9704f5da00..692d4172c7 100644 --- a/test/unit/commands.netcheck.test.ts +++ b/test/unit/commands.netcheck.test.ts @@ -39,6 +39,7 @@ function setup(options: { extensionBaseUrl?: string } = {}) { getDuplicateWorkspaceIpc: () => ({}), getSpeedtestPanelFactory: () => ({}), getNetcheckPanelFactory: () => ({}) as NetcheckPanelFactory, + getConnectionLogBuffer: () => ({ flush: () => {} }), } as unknown as ServiceContainer; const commands = new Commands( diff --git a/test/unit/commands.supportBundle.test.ts b/test/unit/commands.supportBundle.test.ts index d473b2f764..4f5c3d776e 100644 --- a/test/unit/commands.supportBundle.test.ts +++ b/test/unit/commands.supportBundle.test.ts @@ -79,9 +79,11 @@ function setup(options: { cliVersion?: string } = {}) { vi.mocked(appendVsCodeLogs).mockResolvedValue(undefined); const logger = createMockLogger(); + const connectionLogBufferFlush = vi.fn(); const serviceContainer = { getTelemetryService: () => service, getLogger: () => logger, + getConnectionLogBuffer: () => ({ flush: connectionLogBufferFlush }), getPathResolver: () => ({ getGlobalConfigDir: () => "/cfg", getProxyLogPath: () => "/logs/proxy", @@ -111,7 +113,7 @@ function setup(options: { cliVersion?: string } = {}) { {} as DeploymentManager, ); - return { commands, client, logger, interaction }; + return { commands, client, logger, interaction, connectionLogBufferFlush }; } function setRemoteAuthority(value: string | undefined): void { @@ -136,10 +138,20 @@ function connectToWorkspace( describe("Commands.supportBundle", () => { it("collects the selected agent's bundle with remote log globs", async () => { - const { commands } = setup(); + const { commands, connectionLogBufferFlush } = setup(); await commands.supportBundle(agentItem("dev")); + // The buffered below-level connection logs are replayed for the bundle, + // keeping the ring so a later failure flush still has them, and before the + // CLI runs so the channel has time to write them to disk. + expect(connectionLogBufferFlush).toHaveBeenCalledWith("support_bundle", { + retain: true, + }); + expect(connectionLogBufferFlush.mock.invocationCallOrder[0]).toBeLessThan( + vi.mocked(cliExec.supportBundle).mock.invocationCallOrder[0], + ); + expect(cliExec.supportBundle).toHaveBeenCalledWith( expect.anything(), "owner/ws", diff --git a/test/unit/commands.telemetry.test.ts b/test/unit/commands.telemetry.test.ts index ffb0d1c892..2e1c67c396 100644 --- a/test/unit/commands.telemetry.test.ts +++ b/test/unit/commands.telemetry.test.ts @@ -18,6 +18,7 @@ import type { PathResolver } from "@/core/pathResolver"; import type { SecretsManager, SessionAuth } from "@/core/secretsManager"; import type { DeploymentManager } from "@/deployment/deploymentManager"; import type { Deployment } from "@/deployment/types"; +import type { ConnectionLogBuffer } from "@/logging/logBuffer"; import type { LoginCoordinator, LoginResult } from "@/login/loginCoordinator"; import type { NetcheckPanelFactory } from "@/webviews/netcheck/netcheckPanelFactory"; import type { SpeedtestPanelFactory } from "@/webviews/speedtest/speedtestPanelFactory"; @@ -120,6 +121,10 @@ function setup(options: SetupOptions = {}) { getDuplicateWorkspaceIpc: () => ({}) as DuplicateWorkspaceIpc, getSpeedtestPanelFactory: () => ({}) as SpeedtestPanelFactory, getNetcheckPanelFactory: () => ({}) as NetcheckPanelFactory, + getConnectionLogBuffer: (): ConnectionLogBuffer => ({ + flush: () => {}, + onConnectionFailure: () => {}, + }), } as ServiceContainer; const extensionClient = { diff --git a/test/unit/instrumentation/websocket.test.ts b/test/unit/instrumentation/websocket.test.ts index a44d172013..c461cc4f70 100644 --- a/test/unit/instrumentation/websocket.test.ts +++ b/test/unit/instrumentation/websocket.test.ts @@ -104,7 +104,7 @@ describe("WebSocketTelemetry", () => { const { ws, sink } = setup(); ws.opened("/api/test"); - ws.dropped("normal_close"); + ws.dropped("unexpected_close"); ws.dropped("error"); expect(sink.eventsNamed("connection.dropped")).toHaveLength(1); diff --git a/test/unit/logging/formatters.test.ts b/test/unit/logging/formatters.test.ts index 8eb699dd66..ab0d581b22 100644 --- a/test/unit/logging/formatters.test.ts +++ b/test/unit/logging/formatters.test.ts @@ -143,6 +143,7 @@ describe("Logging formatters", () => { const result = formatBody({ access_token: "secret-access", refresh_token: "secret-refresh", + registration_access_token: "secret-registration", client_secret: "secret-client", code: "secret-code", code_verifier: "secret-verifier", @@ -152,6 +153,7 @@ describe("Logging formatters", () => { token_type: "bearer", }); expect(result).toContain("access_token: ''"); + expect(result).toContain("registration_access_token: ''"); expect(result).toContain("token_type: 'bearer'"); expect(result).not.toContain("secret-"); }); diff --git a/test/unit/logging/logBuffer.test.ts b/test/unit/logging/logBuffer.test.ts new file mode 100644 index 0000000000..323fc2e8a0 --- /dev/null +++ b/test/unit/logging/logBuffer.test.ts @@ -0,0 +1,263 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; + +import { BufferingLogger } from "@/logging/logBuffer"; + +import type { Logger } from "@/logging/logger"; + +// Numeric levels matching vscode.LogLevel. +const OFF = 0; +const DEBUG = 2; +const INFO = 3; +const WARNING = 4; +const ERROR = 5; + +type LogMethod = Exclude; + +interface Call { + level: LogMethod; + message: string; + args: unknown[]; +} + +function setup(level: number, capacity: number) { + const calls: Call[] = []; + const push = + (method: LogMethod) => + (message: string, ...args: unknown[]) => + calls.push({ level: method, message, args }); + const logger: Logger = { + trace: push("trace"), + debug: push("debug"), + info: push("info"), + warn: push("warn"), + error: push("error"), + show: vi.fn(), + }; + const channel = { logLevel: level }; + const buffer = new BufferingLogger(logger, channel, capacity); + // Ignore the pass-through calls, then return only what the flush replayed. + const flush = ( + reason = "r", + options?: { readonly retain?: boolean }, + ): string[] => { + calls.length = 0; + buffer.flush(reason, options); + return calls.map((c) => c.message); + }; + return { buffer, calls, channel, flush }; +} + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe("BufferingLogger", () => { + it("forwards every call to the inner logger", () => { + const { buffer, calls } = setup(INFO, 10); + + buffer.trace("t"); + buffer.debug("d"); + buffer.info("i"); + buffer.warn("w"); + buffer.error("e"); + + expect(calls.map((c) => c.level)).toEqual([ + "trace", + "debug", + "info", + "warn", + "error", + ]); + }); + + interface LevelCase { + level: number; + hidden: LogMethod; + shown: LogMethod; + sink: "info" | "warn" | "error"; + } + + it.each([ + { + level: DEBUG, + hidden: "trace", + shown: "debug", + sink: "info", + }, + { + level: INFO, + hidden: "debug", + shown: "info", + sink: "info", + }, + { + level: WARNING, + hidden: "info", + shown: "warn", + sink: "warn", + }, + { + level: ERROR, + hidden: "warn", + shown: "error", + sink: "error", + }, + ])( + "at level $level buffers below-level entries and replays them via the $sink sink", + ({ level, hidden, shown, sink }) => { + const { buffer, calls, flush } = setup(level, 10); + + buffer[hidden]("hidden line"); + buffer[shown]("shown line"); + const lines = flush(); + + expect(lines.some((l) => l.includes("hidden line"))).toBe(true); + expect(lines.some((l) => l.includes("shown line"))).toBe(false); + expect(calls.every((c) => c.level === sink)).toBe(true); + }, + ); + + it("re-evaluates what is below level when the level changes", () => { + const { buffer, channel, flush } = setup(ERROR, 10); + + buffer.info("info at error level"); // below ERROR -> buffered + channel.logLevel = INFO; + buffer.info("info at info level"); // at INFO -> not buffered + + const lines = flush(); + expect(lines.some((l) => l.includes("info at error level"))).toBe(true); + expect(lines.some((l) => l.includes("info at info level"))).toBe(false); + }); + + interface CapacityCase { + name: string; + capacity: number; + values: string[]; + shrinkTo?: number; + present: string[]; + absent: string[]; + } + + it.each([ + { + name: "evicts the oldest entry when capacity is exceeded", + capacity: 2, + values: ["one", "two", "three"], + present: ["two", "three"], + absent: ["one"], + }, + { + name: "buffers nothing when capacity is zero", + capacity: 0, + values: ["one", "two", "three"], + present: [], + absent: ["one", "two", "three"], + }, + { + name: "keeps the most recent entries when shrunk via setCapacity", + capacity: 10, + values: ["one", "two", "three"], + shrinkTo: 1, + present: ["three"], + absent: ["one", "two"], + }, + { + name: "evicts oldest entries once the character budget is exceeded", + capacity: 100_000, + values: [ + `first ${"x".repeat(1_200_000)}`, + `second ${"x".repeat(1_200_000)}`, + ], + present: ["second "], + absent: ["first "], + }, + ])("$name", ({ capacity, values, shrinkTo, present, absent }) => { + const { buffer, flush } = setup(INFO, capacity); + + for (const value of values) { + buffer.debug(value); + } + if (shrinkTo !== undefined) { + buffer.setCapacity(shrinkTo); + } + + const lines = flush(); + for (const value of present) { + expect(lines.some((l) => l.includes(value))).toBe(true); + } + for (const value of absent) { + expect(lines.some((l) => l.includes(value))).toBe(false); + } + }); + + it("replays each entry with its record time and formatted args, prefixing every physical line", () => { + const recordedAt = Date.parse("2024-01-01T00:00:00.000Z"); + vi.spyOn(Date, "now").mockReturnValueOnce(recordedAt); + const { buffer, calls, flush } = setup(INFO, 10); + const detail = { code: 1006 }; + + buffer.debug("first line\nsecond line", detail); + const lines = flush(); + + expect(lines[0]).toContain("replaying"); + expect(lines[0]).toContain("(r)"); + expect(lines[lines.length - 1]).toContain("end of buffered logs"); + + const replay = calls.find((c) => c.message.includes("first line")); + expect(replay).toBeDefined(); + expect(replay?.message).toContain("2024-01-01T00:00:00.000Z"); + expect(replay?.message).toContain("DEBUG first line"); + // Args are formatted into the text at record time, not passed through. + expect(replay?.message).toContain("1006"); + expect(replay?.args).toEqual([]); + // Every physical line of the joined replay text carries the prefix. + for (const line of replay?.message.split("\n") ?? []) { + expect(line.startsWith("[buffered] ")).toBe(true); + } + }); + + it("clears after flush, no-ops when empty, and preserves entries flushed while Off", () => { + const { buffer, channel, flush } = setup(INFO, 10); + + // Empty flush is a no-op. + expect(flush()).toHaveLength(0); + + // Each failure only replays entries accumulated since the previous one. + buffer.debug("before first"); + expect(flush("first").some((l) => l.includes("before first"))).toBe(true); + buffer.debug("before second"); + const second = flush("second"); + expect(second.some((l) => l.includes("before second"))).toBe(true); + expect(second.some((l) => l.includes("before first"))).toBe(false); + + // Nothing is buffered while the channel itself is at Off. + channel.logLevel = OFF; + buffer.debug("logged while off"); + channel.logLevel = INFO; + expect(flush("after").some((l) => l.includes("logged while off"))).toBe( + false, + ); + + // A flush at Off keeps the context buffered until logging returns. + buffer.debug("buffered before going off"); + channel.logLevel = OFF; + expect(flush("off")).toHaveLength(0); + channel.logLevel = INFO; + expect( + flush("back").some((l) => l.includes("buffered before going off")), + ).toBe(true); + }); + + it("retains the ring on a snapshot flush so a later flush replays it again", () => { + const { buffer, flush } = setup(INFO, 10); + + buffer.debug("snapshot me"); + // A retained flush replays the entry but keeps it buffered. + expect( + flush("bundle", { retain: true }).some((l) => l.includes("snapshot me")), + ).toBe(true); + // A following failure flush still replays the retained entry, then clears it. + expect(flush("failure").some((l) => l.includes("snapshot me"))).toBe(true); + expect(flush("again")).toHaveLength(0); + }); +}); diff --git a/test/unit/settings/logger.test.ts b/test/unit/settings/logger.test.ts new file mode 100644 index 0000000000..d1b20c7382 --- /dev/null +++ b/test/unit/settings/logger.test.ts @@ -0,0 +1,97 @@ +import { describe, expect, it } from "vitest"; + +import { HttpClientLogLevel } from "@/logging/types"; +import { + DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + MAX_CONNECTION_LOG_BUFFER_SIZE, + readConnectionLogBufferSize, + readHttpClientLogLevel, +} from "@/settings/logger"; + +import type { WorkspaceConfiguration } from "vscode"; + +function cfg(value: unknown): Pick { + return { + get: (_key: string, fallback?: unknown) => + value === undefined ? fallback : value, + } as Pick; +} + +describe("readConnectionLogBufferSize", () => { + interface Case { + name: string; + value: unknown; + expected: number; + } + + it.each([ + { + name: "returns the configured value when in range", + value: 250, + expected: 250, + }, + { name: "floors fractional values", value: 250.9, expected: 250 }, + { name: "treats zero as disabled", value: 0, expected: 0 }, + { + name: "clamps values above the maximum", + value: 1_000_000, + expected: MAX_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for a negative value", + value: -1, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for Infinity", + value: Infinity, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for NaN", + value: Number.NaN, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for a numeric string", + value: "2000", + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for null", + value: null, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "falls back to the default for an object", + value: {}, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + { + name: "uses the default when unset", + value: undefined, + expected: DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + }, + ])("$name", ({ value, expected }) => { + expect(readConnectionLogBufferSize(cfg(value))).toBe(expected); + }); +}); + +describe("readHttpClientLogLevel", () => { + it("maps a known level case-insensitively", () => { + expect(readHttpClientLogLevel(cfg("body"))).toBe(HttpClientLogLevel.BODY); + }); + + it("falls back to BASIC for an unknown level", () => { + expect(readHttpClientLogLevel(cfg("nonsense"))).toBe( + HttpClientLogLevel.BASIC, + ); + }); + + it.each([2, null])( + "falls back to BASIC for a non-string value %p", + (value) => { + expect(readHttpClientLogLevel(cfg(value))).toBe(HttpClientLogLevel.BASIC); + }, + ); +}); diff --git a/test/unit/websocket/oneWayWebSocket.test.ts b/test/unit/websocket/oneWayWebSocket.test.ts new file mode 100644 index 0000000000..ec784492e9 --- /dev/null +++ b/test/unit/websocket/oneWayWebSocket.test.ts @@ -0,0 +1,44 @@ +import { type AddressInfo } from "node:net"; +import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import { WebSocketServer } from "ws"; + +import { OneWayWebSocket } from "@/websocket/oneWayWebSocket"; + +describe("OneWayWebSocket", () => { + let server: WebSocketServer; + let host: string; + + beforeEach(async () => { + server = new WebSocketServer({ port: 0 }); + await new Promise((resolve) => server.once("listening", resolve)); + const { port } = server.address() as AddressInfo; + host = `127.0.0.1:${port}`; + }); + + afterEach(async () => { + await new Promise((resolve) => server.close(() => resolve())); + }); + + it("delivers a DOM CloseEvent with code and reason to close listeners", async () => { + server.on("connection", (socket) => { + socket.close(1002, "protocol error"); + }); + + const ws = new OneWayWebSocket({ + location: { protocol: "http:", host }, + apiRoute: "/api/v2/test", + }); + + const event = await new Promise<{ code: number; reason: string }>( + (resolve) => { + ws.addEventListener("close", (e) => { + resolve({ code: e.code, reason: e.reason }); + }); + }, + ); + + expect(event.code).toBe(1002); + expect(event.reason).toBe("protocol error"); + ws.close(); + }); +}); diff --git a/test/unit/websocket/reconnectingWebSocket.test.ts b/test/unit/websocket/reconnectingWebSocket.test.ts index 463490a2ba..7d841ba7c5 100644 --- a/test/unit/websocket/reconnectingWebSocket.test.ts +++ b/test/unit/websocket/reconnectingWebSocket.test.ts @@ -20,6 +20,7 @@ import { createMockLogger } from "../../mocks/testHelpers"; import type { CloseEvent, Event as WsEvent } from "ws"; +import type { ConnectionStateReason } from "@/instrumentation/websocket"; import type { UnidirectionalStream } from "@/websocket/eventStreamConnection"; describe("ReconnectingWebSocket", () => { @@ -34,7 +35,8 @@ describe("ReconnectingWebSocket", () => { describe("Reconnection Logic", () => { it("automatically reconnects on abnormal closure (1006)", async () => { - const { ws, sockets } = await createReconnectingWebSocket(); + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); sockets[0].fireOpen(); expect(ws.state).toBe(ConnectionState.CONNECTED); @@ -50,6 +52,8 @@ describe("ReconnectingWebSocket", () => { sockets[1].fireOpen(); expect(ws.state).toBe(ConnectionState.CONNECTED); + // A transient drop that reconnects is not a terminal failure. + expect(onConnectionFailure).not.toHaveBeenCalled(); ws.close(); }); @@ -57,15 +61,19 @@ describe("ReconnectingWebSocket", () => { { code: WebSocketCloseCode.NORMAL, name: "Normal Closure" }, { code: WebSocketCloseCode.GOING_AWAY, name: "Going Away" }, ])( - "does not reconnect on normal closure: $name ($code)", + "reconnects on a server-initiated normal closure: $name ($code)", async ({ code }) => { - const { ws, sockets } = await createReconnectingWebSocket(); + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); sockets[0].fireOpen(); sockets[0].fireClose({ code, reason: "Normal" }); + expect(ws.state).toBe(ConnectionState.AWAITING_RETRY); - await vi.advanceTimersByTimeAsync(10000); - expect(sockets).toHaveLength(1); + await vi.advanceTimersByTimeAsync(300); + expect(sockets).toHaveLength(2); + // A server-initiated close is not a terminal failure. + expect(onConnectionFailure).not.toHaveBeenCalled(); ws.close(); }, @@ -77,7 +85,8 @@ describe("ReconnectingWebSocket", () => { ])( "does not reconnect on unrecoverable WebSocket close code: %i", async (code) => { - const { ws, sockets } = await createReconnectingWebSocket(); + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); sockets[0].fireOpen(); expect(ws.state).toBe(ConnectionState.CONNECTED); @@ -87,29 +96,34 @@ describe("ReconnectingWebSocket", () => { await vi.advanceTimersByTimeAsync(10000); expect(sockets).toHaveLength(1); + expect(onConnectionFailure).toHaveBeenCalledWith( + "unrecoverable_close", + expect.any(String), + ); ws.close(); }, ); it.each([ - HttpStatusCode.FORBIDDEN, - HttpStatusCode.GONE, - HttpStatusCode.UPGRADE_REQUIRED, + `Unexpected server response: ${HttpStatusCode.FORBIDDEN}`, + `Unexpected server response: ${HttpStatusCode.GONE}`, + `Unexpected server response: ${HttpStatusCode.UPGRADE_REQUIRED}`, + // eventsource (SSE fallback) reports the status this way. + `Non-200 status code (${HttpStatusCode.FORBIDDEN})`, ])( - "does not reconnect on unrecoverable HTTP error during creation: %i", - async (statusCode) => { + "does not reconnect on an unrecoverable handshake failure during creation: %s", + async (message) => { let socketCreationAttempts = 0; const factory = vi.fn(() => { socketCreationAttempts++; - // Simulate HTTP error during WebSocket handshake - return Promise.reject( - new Error(`Unexpected server response: ${statusCode}`), - ); + // Simulate an HTTP error during the handshake. + return Promise.reject(new Error(message)); }); // create() returns a disconnected instance instead of throwing - const ws = await fromFactory(factory); + const onConnectionFailure = vi.fn(); + const ws = await fromFactory(factory, { onConnectionFailure }); // Should be disconnected after unrecoverable HTTP error expect(ws.state).toBe(ConnectionState.DISCONNECTED); @@ -117,6 +131,10 @@ describe("ReconnectingWebSocket", () => { // Should not retry after unrecoverable HTTP error await vi.advanceTimersByTimeAsync(10000); expect(socketCreationAttempts).toBe(1); + expect(onConnectionFailure).toHaveBeenCalledWith( + "unrecoverable_http", + "/api/v2/test", + ); ws.close(); }, @@ -150,6 +168,55 @@ describe("ReconnectingWebSocket", () => { }, ); + it("does not flush on an unrecoverable 401 (a 401 explains itself, and with OAuth a refresh reconnects the same socket)", async () => { + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); + + sockets[0].fireError( + new Error(`Unexpected server response: ${HttpStatusCode.UNAUTHORIZED}`), + ); + + expect(ws.state).toBe(ConnectionState.DISCONNECTED); + expect(onConnectionFailure).not.toHaveBeenCalled(); + ws.close(); + }); + + it.each([ + HttpStatusCode.FORBIDDEN, + HttpStatusCode.GONE, + HttpStatusCode.UPGRADE_REQUIRED, + ])( + "flushes with the route on an unrecoverable HTTP failure: %i", + async (statusCode) => { + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); + + sockets[0].fireError( + new Error(`Unexpected server response: ${statusCode}`), + ); + + expect(onConnectionFailure).toHaveBeenCalledWith( + "unrecoverable_http", + expect.any(String), + ); + ws.close(); + }, + ); + + it("does not read host/port digits as a status code", async () => { + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); + + // A port ending in 404x must not be treated as HTTP 404. + sockets[0].fireError(new Error("connect ECONNREFUSED 127.0.0.1:4040")); + + expect(onConnectionFailure).not.toHaveBeenCalled(); + // Generic connection errors retry rather than terminate. + await vi.advanceTimersByTimeAsync(1000); + expect(sockets.length).toBeGreaterThan(1); + ws.close(); + }); + it("reconnect() connects immediately and cancels pending reconnections", async () => { const { ws, sockets } = await createReconnectingWebSocket(); @@ -648,7 +715,7 @@ describe("ReconnectingWebSocket", () => { ]); }); - it("emits a normal-close drop and disconnects on server-initiated close", async () => { + it("emits an unexpected-close drop and reconnects on a server-initiated close", async () => { const sink = new TestSink(); const telemetry = createTestTelemetryService(sink); const { ws, sockets } = await createReconnectingWebSocket({ telemetry }); @@ -659,18 +726,18 @@ describe("ReconnectingWebSocket", () => { reason: "server restarting", }); - expect(ws.state).toBe(ConnectionState.DISCONNECTED); + expect(ws.state).toBe(ConnectionState.AWAITING_RETRY); const dropped = sink.eventsNamed("connection.dropped"); expect(dropped).toHaveLength(1); expect(dropped[0].properties).toMatchObject({ - cause: "normal_close", + cause: "unexpected_close", close_code: String(WebSocketCloseCode.GOING_AWAY), }); expect( sink .eventsNamed("connection.state_transitioned") .map((e) => e.properties.reason), - ).toContain("normal_close"); + ).toContain("unexpected_close"); ws.close(); }); @@ -706,6 +773,7 @@ describe("ReconnectingWebSocket", () => { const setupRefreshTest = async (onRefresh: () => Promise) => { const sockets: MockSocket[] = []; const refreshCallback = vi.fn().mockImplementation(onRefresh); + const onConnectionFailure = vi.fn(); const factory = vi.fn(() => { const socket = createMockSocket(); sockets.push(socket); @@ -713,9 +781,10 @@ describe("ReconnectingWebSocket", () => { }); const ws = await fromFactory(factory, { onCertificateRefreshNeeded: refreshCallback, + onConnectionFailure, }); sockets[0].fireOpen(); - return { ws, sockets, refreshCallback }; + return { ws, sockets, refreshCallback, onConnectionFailure }; }; it("reconnects after successful refresh", async () => { @@ -733,7 +802,7 @@ describe("ReconnectingWebSocket", () => { }); it("disconnects when refresh fails", async () => { - const { ws, sockets } = await setupRefreshTest(() => + const { ws, sockets, onConnectionFailure } = await setupRefreshTest(() => Promise.resolve(false), ); @@ -743,6 +812,10 @@ describe("ReconnectingWebSocket", () => { ); expect(sockets).toHaveLength(1); + expect(onConnectionFailure).toHaveBeenCalledWith( + "certificate_error", + expect.any(String), + ); ws.close(); }); @@ -794,6 +867,19 @@ describe("ReconnectingWebSocket", () => { ws.close(); }); }); + + describe("Connection failure callback", () => { + it("does not fire onConnectionFailure on a manual disconnect", async () => { + const { ws, sockets, onConnectionFailure } = + await createReconnectingWebSocket(); + + sockets[0].fireOpen(); + ws.disconnect(); + + expect(onConnectionFailure).not.toHaveBeenCalled(); + ws.close(); + }); + }); }); type MockSocket = UnidirectionalStream & { @@ -864,9 +950,15 @@ function createMockSocket(): MockSocket { }; } +type ConnectionFailureSpy = ReturnType< + typeof vi.fn<(reason: ConnectionStateReason, route: string) => void> +>; + interface FactoryOptions { onDispose?: () => void; onCertificateRefreshNeeded?: () => Promise; + onConnectionFailure?: (reason: ConnectionStateReason, route: string) => void; + route?: string; telemetry?: TelemetryReporter; } @@ -875,16 +967,19 @@ async function createReconnectingWebSocket( ): Promise<{ ws: ReconnectingWebSocket; sockets: MockSocket[]; + onConnectionFailure: ConnectionFailureSpy; }> { const sockets: MockSocket[] = []; + const onConnectionFailure = + vi.fn<(reason: ConnectionStateReason, route: string) => void>(); const factory = vi.fn(() => { const socket = createMockSocket(); sockets.push(socket); return Promise.resolve(socket); }); - const ws = await fromFactory(factory, options); + const ws = await fromFactory(factory, { ...options, onConnectionFailure }); expect(sockets).toHaveLength(1); - return { ws, sockets }; + return { ws, sockets, onConnectionFailure }; } async function createReconnectingWebSocketWithErrorControl( @@ -927,8 +1022,10 @@ async function fromFactory( createMockLogger(), { telemetry: options.telemetry ?? NOOP_TELEMETRY_REPORTER, + route: options.route ?? "/api/v2/test", onCertificateRefreshNeeded: options.onCertificateRefreshNeeded ?? (() => Promise.resolve(false)), + onConnectionFailure: options.onConnectionFailure ?? vi.fn(), }, options.onDispose, ); diff --git a/test/unit/websocket/utils.test.ts b/test/unit/websocket/utils.test.ts new file mode 100644 index 0000000000..61d4cd1d4d --- /dev/null +++ b/test/unit/websocket/utils.test.ts @@ -0,0 +1,55 @@ +import { EventSource } from "eventsource"; +import http from "node:http"; +import { type AddressInfo } from "node:net"; +import { afterEach, describe, expect, it } from "vitest"; +import { WebSocket } from "ws"; + +import { handshakeStatus } from "@/websocket/utils"; + +// `handshakeStatus` parses two libraries' internal error text, and neither is a +// contract. Drive real clients against a rejecting server so a library reword +// fails here instead of silently turning every unrecoverable status into a +// retry-forever connection_error. +describe("handshakeStatus", () => { + let server: http.Server; + + const listen = (statusCode: number): Promise => { + server = http.createServer((_req, res) => { + res.statusCode = statusCode; + res.end(); + }); + return new Promise((resolve) => { + server.listen(0, "127.0.0.1", () => { + const { port } = server.address() as AddressInfo; + resolve(`127.0.0.1:${port}`); + }); + }); + }; + + afterEach(async () => { + await new Promise((resolve) => server.close(() => resolve())); + }); + + it("parses the status from a ws upgrade rejection", async () => { + const host = await listen(404); + const ws = new WebSocket(`ws://${host}`); + + const error = await new Promise((resolve) => { + ws.on("error", resolve); + }); + + expect(handshakeStatus(error)).toBe(404); + }); + + it("parses the status from an EventSource handshake rejection", async () => { + const host = await listen(403); + const source = new EventSource(`http://${host}`); + + const error = await new Promise((resolve) => { + source.onerror = (event) => resolve(event); + }); + source.close(); + + expect(handshakeStatus(error)).toBe(403); + }); +});