diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 5f5d53fa9a..ba42487418 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -132,6 +132,38 @@ 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 log lines that sit +**below** the current level — the ones the channel would otherwise drop. + +On a genuine connection failure the buffer is flushed: the captured lines are +re-emitted into the output channel (each marked `[buffered]` with its original +timestamp and level) so they land on disk and in a support bundle. Only +below-level lines are buffered, so nothing already written is duplicated. + +Flush happens only on genuine failures, never on transient drops or intentional +teardown: + +- a reconnecting WebSocket terminal failure (`unrecoverable_close`, + `unrecoverable_http`, `certificate_error`); +- a `WorkspaceMonitor` socket error; +- an agent reported as `disconnected` during connection. + +A short suppression window coalesces the burst of signals a single outage often +triggers into one flush. + +The buffer size is set by `coder.connectionLogBuffer.size` (number of lines; +`0` disables it). It 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` writes its own file logs under +`coder.proxyLogDirectory`, which support bundles already collect from disk, so +those are not buffered here. + ## Testing There are a few ways you can test the "Open in VS Code" flow: diff --git a/package.json b/package.json index 203b9b23d9..6673e19fc3 100644 --- a/package.json +++ b/package.json @@ -215,6 +215,12 @@ "minimum": 0, "default": 250 }, + "coder.connectionLogBuffer.size": { + "markdownDescription": "Number of connection debug log lines to keep in memory below the current log level. On a connection failure they are written out so a support bundle captures the detail leading up to it, without debug logging enabled beforehand. Set to `0` to disable. The buffer is lost on a hard kill or out-of-memory event.", + "type": "number", + "minimum": 0, + "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..249b24d2db 100644 --- a/src/api/coderApi.ts +++ b/src/api/coderApi.ts @@ -69,6 +69,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 +126,9 @@ 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, + ) => void, ) { super(); wrapWithValidation(this); @@ -145,6 +149,7 @@ export class CoderApi extends Api implements vscode.Disposable { token: string | undefined, output: Logger, telemetry: TelemetryReporter = NOOP_TELEMETRY_REPORTER, + onConnectionFailure?: (reason: ConnectionStateReason) => void, ): CoderApi { const httpRequestsTelemetry = new HttpRequestsTelemetry(telemetry); const authConfigTracker = new AuthConfigTracker(); @@ -153,6 +158,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] = @@ -548,6 +554,7 @@ export class CoderApi extends Api implements vscode.Disposable { } return refreshCertificates(refreshCommand, this.output); }, + onConnectionFailure: this.onConnectionFailure, telemetry: this.telemetry, }; diff --git a/src/core/container.ts b/src/core/container.ts index 56cd0edf83..7df2b74568 100644 --- a/src/core/container.ts +++ b/src/core/container.ts @@ -1,6 +1,10 @@ import * as vscode from "vscode"; 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"; @@ -30,6 +34,8 @@ import type { Logger } from "../logging/logger"; export class ServiceContainer implements vscode.Disposable { private readonly outputChannel: vscode.LogOutputChannel; private readonly logger: Logger; + private readonly connectionLogBuffer: BufferingLogger; + private readonly disposables: vscode.Disposable[] = []; private readonly pathResolver: PathResolver; private readonly mementoManager: MementoManager; private readonly secretsManager: SecretsManager; @@ -48,9 +54,23 @@ export class ServiceContainer implements vscode.Disposable { this.outputChannel = vscode.window.createOutputChannel("Coder", { log: true, }); - this.logger = prefixLogger( - this.outputChannel, - `[session ${shortId(sessionId)}]`, + this.connectionLogBuffer = new BufferingLogger( + prefixLogger(this.outputChannel, `[session ${shortId(sessionId)}]`), + { + getLogLevel: () => this.outputChannel.logLevel, + onDidChangeLogLevel: (listener) => + this.outputChannel.onDidChangeLogLevel(listener), + }, + readConnectionLogBufferSize(), + ); + this.logger = this.connectionLogBuffer; + this.disposables.push( + this.connectionLogBuffer, + vscode.workspace.onDidChangeConfiguration((event) => { + if (event.affectsConfiguration(CONNECTION_LOG_BUFFER_SIZE_KEY)) { + this.connectionLogBuffer.setCapacity(readConnectionLogBufferSize()); + } + }), ); this.pathResolver = new PathResolver( context.globalStorageUri.fsPath, @@ -148,6 +168,11 @@ export class ServiceContainer implements vscode.Disposable { return this.logger; } + /** The below-level connection log buffer; flush it on a connection failure. */ + getConnectionLogBuffer(): ConnectionLogBuffer { + return this.connectionLogBuffer; + } + getCliManager(): CliManager { return this.cliManager; } @@ -193,6 +218,9 @@ export class ServiceContainer implements vscode.Disposable { this.commandManager.dispose(); this.contextManager.dispose(); this.loginCoordinator.dispose(); + for (const disposable of this.disposables) { + disposable.dispose(); + } try { await this.telemetryService.dispose(); } finally { @@ -200,3 +228,15 @@ export class ServiceContainer implements vscode.Disposable { } } } + +const CONNECTION_LOG_BUFFER_SIZE_KEY = "coder.connectionLogBuffer.size"; +const DEFAULT_CONNECTION_LOG_BUFFER_SIZE = 1000; + +function readConnectionLogBufferSize(): number { + return vscode.workspace + .getConfiguration() + .get( + CONNECTION_LOG_BUFFER_SIZE_KEY, + DEFAULT_CONNECTION_LOG_BUFFER_SIZE, + ); +} diff --git a/src/extension.ts b/src/extension.ts index e5733b0bb2..6d6294e3d9 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -143,6 +143,7 @@ async function doActivate( deploymentSessionAuth?.token, output, telemetryService, + (reason) => serviceContainer.getConnectionLogBuffer().flush(reason), ); ctx.subscriptions.push(client); diff --git a/src/logging/logBuffer.ts b/src/logging/logBuffer.ts new file mode 100644 index 0000000000..0c1a149b70 --- /dev/null +++ b/src/logging/logBuffer.ts @@ -0,0 +1,177 @@ +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; + +const LEVEL_LABEL: Record = { + trace: "TRACE", + debug: "DEBUG", + info: "INFO", + warn: "WARN", + error: "ERROR", +}; + +/** Reads the sink's effective log level (numeric, matching `vscode.LogLevel`). */ +export interface LogLevelSource { + getLogLevel(): number; + onDidChangeLogLevel(listener: (level: number) => void): { dispose(): void }; +} + +/** The failure-time surface used by connection-failure call sites. */ +export interface ConnectionLogBuffer { + flush(reason: string): void; +} + +interface BufferedEntry { + readonly atMs: number; + readonly level: Level; + readonly message: string; + readonly args: unknown[]; +} + +function normalizeCapacity(capacity: number): number { + return Number.isFinite(capacity) && capacity > 0 ? Math.floor(capacity) : 0; +} + +/** + * Wraps a {@link Logger} and keeps a bounded, in-memory ring of entries whose + * level is **below the sink's current level** — the ones the sink would + * otherwise drop. On a connection failure, {@link flush} replays those entries + * into the sink so they persist to disk (and any support bundle), giving Support + * the debug detail leading up to the failure without the user having enabled + * debug logging beforehand. + * + * Only below-level entries are buffered, so nothing that the sink already writes + * is ever duplicated. Replay is emitted at the least-verbose level the sink + * still writes, so the flush lands regardless of the configured level. + */ +export class BufferingLogger implements Logger, ConnectionLogBuffer { + private entries: BufferedEntry[] = []; + private capacity: number; + private currentLevel: number; + private lastFlushMs = Number.NEGATIVE_INFINITY; + private readonly levelSubscription: { dispose(): void }; + + public constructor( + private readonly inner: Logger, + private readonly levelSource: LogLevelSource, + capacity: number, + private readonly flushSuppressionMs = 5_000, + private readonly now: () => number = Date.now, + ) { + this.capacity = normalizeCapacity(capacity); + this.currentLevel = levelSource.getLogLevel(); + this.levelSubscription = levelSource.onDidChangeLogLevel((level) => { + this.currentLevel = level; + }); + } + + public trace(message: string, ...args: unknown[]): void { + this.record("trace", message, args); + this.inner.trace(message, ...args); + } + + public debug(message: string, ...args: unknown[]): void { + this.record("debug", message, args); + this.inner.debug(message, ...args); + } + + public info(message: string, ...args: unknown[]): void { + this.record("info", message, args); + this.inner.info(message, ...args); + } + + public warn(message: string, ...args: unknown[]): void { + this.record("warn", message, args); + this.inner.warn(message, ...args); + } + + public error(message: string, ...args: unknown[]): void { + this.record("error", message, args); + this.inner.error(message, ...args); + } + + public show(): void { + this.inner.show(); + } + + /** Resize the ring, keeping the most recent entries. */ + public setCapacity(capacity: number): void { + this.capacity = normalizeCapacity(capacity); + if (this.entries.length > this.capacity) { + this.entries.splice(0, this.entries.length - this.capacity); + } + } + + /** + * Replay buffered entries into the sink and clear them. No-op when empty or + * when called again within the suppression window (one outage often trips + * several failure signals at once). + */ + public flush(reason: string): void { + const now = this.now(); + if (now - this.lastFlushMs < this.flushSuppressionMs) { + return; + } + if (this.entries.length === 0) { + return; + } + this.lastFlushMs = now; + const entries = this.entries; + this.entries = []; + + const emit = this.replayEmitter(); + emit( + `[buffered] connection failure (${reason}): replaying ${entries.length} buffered log line(s)`, + ); + for (const entry of entries) { + emit( + `[buffered] ${new Date(entry.atMs).toISOString()} ${LEVEL_LABEL[entry.level]} ${entry.message}`, + ...entry.args, + ); + } + emit(`[buffered] end of buffered logs (${reason})`); + } + + public dispose(): void { + this.levelSubscription.dispose(); + } + + /** + * The least-verbose sink method that is still written at the current level, + * so a flush is captured whatever the user's log level (except Off, where the + * sink writes nothing). + */ + private replayEmitter(): (message: string, ...args: unknown[]) => void { + const level = this.levelSource.getLogLevel(); + if (level >= SEVERITY.error) { + return (message, ...args) => this.inner.error(message, ...args); + } + if (level >= SEVERITY.warn) { + return (message, ...args) => this.inner.warn(message, ...args); + } + return (message, ...args) => this.inner.info(message, ...args); + } + + private record(level: Level, message: string, args: unknown[]): void { + if (this.capacity === 0 || SEVERITY[level] >= this.currentLevel) { + return; + } + this.entries.push({ atMs: this.now(), level, message, args }); + if (this.entries.length > this.capacity) { + this.entries.shift(); + } + } +} diff --git a/src/remote/workspaceStateMachine.ts b/src/remote/workspaceStateMachine.ts index fc4242d967..0e44f9fa93 100644 --- a/src/remote/workspaceStateMachine.ts +++ b/src/remote/workspaceStateMachine.ts @@ -32,6 +32,7 @@ import type { CoderApi } from "../api/coderApi"; import type { ServiceContainer } from "../core/container"; import type { StartupMode } from "../core/mementoManager"; import type { FeatureSet } from "../featureSet"; +import type { ConnectionLogBuffer } from "../logging/logBuffer"; import type { Logger } from "../logging/logger"; import type { CliAuth } from "../settings/cli"; import type { AuthorityParts } from "../util/authority"; @@ -50,6 +51,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { private workspace: Workspace | undefined; private readonly logger: Logger; + private readonly connectionLogBuffer: ConnectionLogBuffer; constructor( private readonly parts: AuthorityParts, @@ -61,6 +63,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { container: ServiceContainer, ) { this.logger = container.getLogger(); + this.connectionLogBuffer = container.getConnectionLogBuffer(); this.terminal = new TerminalOutputChannel("Coder: Workspace Build"); const telemetry = container.getTelemetryService(); const workspaceName = `${parts.username}/${parts.workspace}`; @@ -189,6 +192,7 @@ export class WorkspaceStateMachine implements vscode.Disposable { return false; case "disconnected": + this.connectionLogBuffer.flush("agent_disconnected"); throw new Error(`Agent ${workspaceName}/${agent.name} disconnected`); case "timeout": diff --git a/src/websocket/reconnectingWebSocket.ts b/src/websocket/reconnectingWebSocket.ts index a881599378..80e1d6aeb1 100644 --- a/src/websocket/reconnectingWebSocket.ts +++ b/src/websocket/reconnectingWebSocket.ts @@ -28,6 +28,22 @@ function toCloseEventError(event: CloseEvent): Error { return new Error(`WebSocket closed with code ${event.code}: ${event.reason}`); } +/** + * Terminal-failure reasons: the socket has given up and surfaced an error, + * rather than dropping transiently and auto-reconnecting. These are the moments + * worth flushing the connection log buffer. + */ +const CONNECTION_FAILURE_REASONS: ReadonlySet = new Set([ + "unrecoverable_close", + "unrecoverable_http", + "certificate_error", +]); + +/** Whether a state-transition reason represents a genuine connection failure. */ +export function isConnectionFailure(reason: ConnectionStateReason): boolean { + return CONNECTION_FAILURE_REASONS.has(reason); +} + /** * Connection states for the ReconnectingWebSocket state machine. */ @@ -117,6 +133,8 @@ export interface ReconnectingWebSocketOptions { telemetry: TelemetryReporter; /** 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) => void; } export class ReconnectingWebSocket< @@ -125,7 +143,10 @@ export class ReconnectingWebSocket< readonly #socketFactory: SocketFactory; readonly #logger: Logger; readonly #telemetry: WebSocketTelemetry; - readonly #options: Required>; + readonly #options: Required< + Omit + >; + readonly #onConnectionFailure?: (reason: ConnectionStateReason) => void; readonly #eventHandlers: { [K in WebSocketEventType]: Set>; } = { @@ -179,6 +200,7 @@ export class ReconnectingWebSocket< jitterFactor: options.jitterFactor ?? 0.1, onCertificateRefreshNeeded: options.onCertificateRefreshNeeded, }; + this.#onConnectionFailure = options.onConnectionFailure; this.#backoffMs = this.#options.initialBackoffMs; this.#onDispose = onDispose; } @@ -293,6 +315,9 @@ export class ReconnectingWebSocket< error: options.error, }); this.clearCurrentSocket(options.code, options.closeReason); + if (isConnectionFailure(reason)) { + this.#onConnectionFailure?.(reason); + } } public close(code?: number, reason?: string): void { diff --git a/src/workspace/workspaceMonitor.ts b/src/workspace/workspaceMonitor.ts index debcf6c545..20cf6a0168 100644 --- a/src/workspace/workspaceMonitor.ts +++ b/src/workspace/workspaceMonitor.ts @@ -26,6 +26,7 @@ import { import type { CoderApi } from "../api/coderApi"; import type { ServiceContainer } from "../core/container"; import type { ContextManager } from "../core/contextManager"; +import type { ConnectionLogBuffer } from "../logging/logBuffer"; import type { Logger } from "../logging/logger"; import type { TelemetryReporter } from "../telemetry/reporter"; import type { UnidirectionalStream } from "../websocket/eventStreamConnection"; @@ -63,6 +64,7 @@ export class WorkspaceMonitor implements vscode.Disposable { private readonly agentObserver = new WorkspaceAgentObserver(); private readonly logger: Logger; private readonly contextManager: ContextManager; + private readonly connectionLogBuffer: ConnectionLogBuffer; private latestWorkspace: Workspace; @@ -73,6 +75,7 @@ export class WorkspaceMonitor implements vscode.Disposable { ) { this.logger = container.getLogger(); this.contextManager = container.getContextManager(); + this.connectionLogBuffer = container.getConnectionLogBuffer(); this.name = createWorkspaceIdentifier(workspace); this.telemetry = container.getTelemetryService(); this.latestWorkspace = workspace; @@ -312,6 +315,7 @@ export class WorkspaceMonitor implements vscode.Disposable { "Got empty error while monitoring workspace", ); this.logger.error(message); + this.connectionLogBuffer.flush("workspace_monitor_error"); } private updateContext(workspace: Workspace) { diff --git a/test/mocks/testHelpers.ts b/test/mocks/testHelpers.ts index 708440cbb0..b3d07a83a8 100644 --- a/test/mocks/testHelpers.ts +++ b/test/mocks/testHelpers.ts @@ -42,6 +42,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"; @@ -625,10 +626,14 @@ export function createMockServiceContainer( pathResolver?: PathResolver; contextManager?: ContextManagerLike; loginCoordinator?: LoginCoordinatorLike; + connectionLogBuffer?: ConnectionLogBuffer; } = {}, ): ServiceContainer { const telemetry = overrides.telemetry ?? createTestTelemetryService(); const logger = overrides.logger ?? createMockLogger(); + const connectionLogBuffer = overrides.connectionLogBuffer ?? { + flush: () => {}, + }; const require = (name: string, value: T | undefined): T => { if (value === undefined) { throw new Error(`createMockServiceContainer: '${name}' was not provided`); @@ -638,6 +643,7 @@ export function createMockServiceContainer( return { getTelemetryService: () => telemetry, getLogger: () => logger, + getConnectionLogBuffer: () => connectionLogBuffer, getSecretsManager: () => require("secretsManager", overrides.secretsManager), getMementoManager: () => diff --git a/test/unit/logging/logBuffer.test.ts b/test/unit/logging/logBuffer.test.ts new file mode 100644 index 0000000000..8a3f0a7cce --- /dev/null +++ b/test/unit/logging/logBuffer.test.ts @@ -0,0 +1,309 @@ +import { describe, expect, it, vi } from "vitest"; + +import { BufferingLogger, type LogLevelSource } 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; + +interface Call { + level: keyof Logger; + message: string; + args: unknown[]; +} + +function recordingLogger(): { logger: Logger; calls: Call[] } { + const calls: Call[] = []; + const push = + (level: keyof Logger) => + (message: string, ...args: unknown[]) => + calls.push({ level, message, args }); + return { + calls, + logger: { + trace: push("trace"), + debug: push("debug"), + info: push("info"), + warn: push("warn"), + error: push("error"), + show: vi.fn(), + }, + }; +} + +function fakeLevelSource(initial: number): LogLevelSource & { + set(level: number): void; +} { + let level = initial; + const listeners = new Set<(level: number) => void>(); + return { + getLogLevel: () => level, + onDidChangeLogLevel: (listener) => { + listeners.add(listener); + return { dispose: () => listeners.delete(listener) }; + }, + set(next: number) { + level = next; + for (const listener of listeners) { + listener(next); + } + }, + }; +} + +function clock(start = 1_000): { + now: () => number; + advance(ms: number): void; +} { + let t = start; + return { now: () => t, advance: (ms) => (t += ms) }; +} + +describe("BufferingLogger", () => { + it("forwards every call to the inner logger", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(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", + ]); + }); + + it("buffers only entries below the current level and replays them on flush", () => { + const { logger, calls } = recordingLogger(); + const time = clock(); + const buffer = new BufferingLogger( + logger, + fakeLevelSource(INFO), + 10, + 5_000, + time.now, + ); + + buffer.debug("hidden debug"); + buffer.info("visible info"); + + calls.length = 0; // ignore the pass-through calls + buffer.flush("test_reason"); + + const replayed = calls.filter((c) => c.message.includes("[buffered]")); + // header + one debug line + footer; the info line was at level and not buffered. + expect(replayed).toHaveLength(3); + expect(replayed[0].message).toContain("connection failure (test_reason)"); + expect(replayed[1].message).toContain("DEBUG hidden debug"); + expect(replayed[2].message).toContain("end of buffered logs"); + }); + + it("does not buffer entries at or above the current level", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 10); + + buffer.info("i"); + buffer.warn("w"); + buffer.error("e"); + + calls.length = 0; + buffer.flush("r"); + + expect(calls).toHaveLength(0); + }); + + it("evicts the oldest entry when capacity is exceeded", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 2); + + buffer.debug("one"); + buffer.debug("two"); + buffer.debug("three"); + + calls.length = 0; + buffer.flush("r"); + + const lines = calls.map((c) => c.message); + expect(lines.some((l) => l.includes("one"))).toBe(false); + expect(lines.some((l) => l.includes("two"))).toBe(true); + expect(lines.some((l) => l.includes("three"))).toBe(true); + }); + + it("clears the buffer after a flush", () => { + const { logger, calls } = recordingLogger(); + const time = clock(); + const buffer = new BufferingLogger( + logger, + fakeLevelSource(INFO), + 10, + 5_000, + time.now, + ); + + buffer.debug("d"); + buffer.flush("first"); + time.advance(10_000); // past the suppression window + + calls.length = 0; + buffer.flush("second"); + + expect(calls).toHaveLength(0); + }); + + it("is a no-op when the buffer is empty", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 10); + + buffer.flush("r"); + + expect(calls).toHaveLength(0); + }); + + it("suppresses a second flush within the suppression window", () => { + const { logger, calls } = recordingLogger(); + const time = clock(); + const buffer = new BufferingLogger( + logger, + fakeLevelSource(INFO), + 10, + 5_000, + time.now, + ); + + buffer.debug("a"); + buffer.flush("first"); + + time.advance(1_000); // within the window + buffer.debug("b"); + calls.length = 0; + buffer.flush("second"); + + expect(calls).toHaveLength(0); + }); + + it("re-evaluates what is below level when the level changes", () => { + const { logger, calls } = recordingLogger(); + const level = fakeLevelSource(ERROR); + const buffer = new BufferingLogger(logger, level, 10); + + buffer.info("info at error level"); // below ERROR -> buffered + level.set(INFO); + buffer.info("info at info level"); // at INFO -> not buffered + + calls.length = 0; + buffer.flush("r"); + + const lines = calls.map((c) => c.message); + expect(lines.some((l) => l.includes("info at error level"))).toBe(true); + expect(lines.some((l) => l.includes("info at info level"))).toBe(false); + }); + + it("buffers nothing when capacity is zero", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 0); + + buffer.debug("d"); + calls.length = 0; + buffer.flush("r"); + + expect(calls).toHaveLength(0); + }); + + it("keeps the most recent entries when shrunk via setCapacity", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 10); + + buffer.debug("one"); + buffer.debug("two"); + buffer.debug("three"); + buffer.setCapacity(1); + + calls.length = 0; + buffer.flush("r"); + + const lines = calls.map((c) => c.message); + expect(lines.some((l) => l.includes("three"))).toBe(true); + expect(lines.some((l) => l.includes("one"))).toBe(false); + expect(lines.some((l) => l.includes("two"))).toBe(false); + }); + + it.each([ + { level: INFO, expected: "info" as const }, + { level: WARNING, expected: "warn" as const }, + { level: ERROR, expected: "error" as const }, + ])( + "replays at $expected so the flush is written at level $level", + ({ level, expected }) => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(level), 10); + + // Always below the current level so it is buffered. + buffer.trace("below"); + calls.length = 0; + buffer.flush("r"); + + expect(calls.length).toBeGreaterThan(0); + expect(calls.every((c) => c.level === expected)).toBe(true); + }, + ); + + it("preserves extra args on replay", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(INFO), 10); + const detail = { code: 1006 }; + + buffer.debug("dropped", detail); + calls.length = 0; + buffer.flush("r"); + + const line = calls.find((c) => c.message.includes("dropped")); + expect(line?.args).toEqual([detail]); + }); + + it("stops buffering after dispose unsubscribes from level changes", () => { + const { logger } = recordingLogger(); + const level = fakeLevelSource(INFO); + const buffer = new BufferingLogger(logger, level, 10); + + buffer.dispose(); + // Changing the level must not throw or affect the disposed buffer. + expect(() => level.set(ERROR)).not.toThrow(); + }); + + it("does not buffer at the Off level", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(OFF), 10); + + buffer.trace("t"); + buffer.debug("d"); + calls.length = 0; + buffer.flush("r"); + + expect(calls).toHaveLength(0); + }); + + it("buffers trace but not debug at the Debug level", () => { + const { logger, calls } = recordingLogger(); + const buffer = new BufferingLogger(logger, fakeLevelSource(DEBUG), 10); + + buffer.trace("trace line"); + buffer.debug("debug line"); + calls.length = 0; + buffer.flush("r"); + + const lines = calls.map((c) => c.message); + expect(lines.some((l) => l.includes("trace line"))).toBe(true); + expect(lines.some((l) => l.includes("debug line"))).toBe(false); + }); +}); diff --git a/test/unit/remote/workspaceStateMachine.test.ts b/test/unit/remote/workspaceStateMachine.test.ts index e437b67467..ee50360fd1 100644 --- a/test/unit/remote/workspaceStateMachine.test.ts +++ b/test/unit/remote/workspaceStateMachine.test.ts @@ -103,6 +103,7 @@ function setup( enableLocalTelemetry(); const progress = new MockProgress<{ message?: string }>(); const userInteraction = new MockUserInteraction(); + const connectionLogBuffer = { flush: vi.fn() }; const sm = new WorkspaceStateMachine( DEFAULT_PARTS, {} as CoderApi, @@ -110,9 +111,13 @@ function setup( "/usr/bin/coder", {} as FeatureSet, { mode: "url", url: "https://test.coder.com" }, - createMockServiceContainer({ telemetry, logger: createMockLogger() }), + createMockServiceContainer({ + telemetry, + logger: createMockLogger(), + connectionLogBuffer, + }), ); - return { sm, progress, userInteraction }; + return { sm, progress, userInteraction, connectionLogBuffer }; } describe("WorkspaceStateMachine", () => { @@ -148,11 +153,14 @@ describe("WorkspaceStateMachine", () => { }); it("throws when agent is disconnected", async () => { - const { sm, progress } = setup(); + const { sm, progress, connectionLogBuffer } = setup(); const ws = runningWorkspace({ status: "disconnected" }); await expect(sm.processWorkspace(ws, progress)).rejects.toThrow( "disconnected", ); + expect(connectionLogBuffer.flush).toHaveBeenCalledWith( + "agent_disconnected", + ); }); it("triggers update and falls through to agent check", async () => { diff --git a/test/unit/websocket/reconnectingWebSocket.test.ts b/test/unit/websocket/reconnectingWebSocket.test.ts index 463490a2ba..0f703a12ea 100644 --- a/test/unit/websocket/reconnectingWebSocket.test.ts +++ b/test/unit/websocket/reconnectingWebSocket.test.ts @@ -8,6 +8,7 @@ import { WebSocketCloseCode, HttpStatusCode } from "@/websocket/codes"; import { ConnectionState, ReconnectingWebSocket, + isConnectionFailure, type SocketFactory, } from "@/websocket/reconnectingWebSocket"; @@ -20,6 +21,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", () => { @@ -794,6 +796,91 @@ describe("ReconnectingWebSocket", () => { ws.close(); }); }); + + describe("Connection failure callback", () => { + it.each([ + "unrecoverable_close", + "unrecoverable_http", + "certificate_error", + ] as const)("treats %s as a connection failure", (reason) => { + expect(isConnectionFailure(reason)).toBe(true); + }); + + it.each([ + "initial_connect", + "manual_reconnect", + "scheduled_reconnect", + "open", + "disconnect", + "dispose", + "connection_error", + "normal_close", + "unexpected_close", + ] as const)("does not treat %s as a connection failure", (reason) => { + expect(isConnectionFailure(reason)).toBe(false); + }); + + it("fires onConnectionFailure on an unrecoverable close code", async () => { + const onConnectionFailure = vi.fn(); + const { ws, sockets } = await createReconnectingWebSocket({ + onConnectionFailure, + }); + + sockets[0].fireOpen(); + sockets[0].fireClose({ + code: WebSocketCloseCode.PROTOCOL_ERROR, + reason: "Unrecoverable", + }); + + expect(onConnectionFailure).toHaveBeenCalledWith("unrecoverable_close"); + ws.close(); + }); + + it("does not fire onConnectionFailure on a normal close", async () => { + const onConnectionFailure = vi.fn(); + const { ws, sockets } = await createReconnectingWebSocket({ + onConnectionFailure, + }); + + sockets[0].fireOpen(); + sockets[0].fireClose({ + code: WebSocketCloseCode.NORMAL, + reason: "Normal", + }); + + expect(onConnectionFailure).not.toHaveBeenCalled(); + ws.close(); + }); + + it("does not fire onConnectionFailure on a manual disconnect", async () => { + const onConnectionFailure = vi.fn(); + const { ws, sockets } = await createReconnectingWebSocket({ + onConnectionFailure, + }); + + sockets[0].fireOpen(); + ws.disconnect(); + + expect(onConnectionFailure).not.toHaveBeenCalled(); + ws.close(); + }); + + it("does not fire onConnectionFailure on a transient reconnecting drop", async () => { + const onConnectionFailure = vi.fn(); + const { ws, sockets } = await createReconnectingWebSocket({ + onConnectionFailure, + }); + + sockets[0].fireOpen(); + sockets[0].fireClose({ + code: WebSocketCloseCode.ABNORMAL, + reason: "Network error", + }); + + expect(onConnectionFailure).not.toHaveBeenCalled(); + ws.close(); + }); + }); }); type MockSocket = UnidirectionalStream & { @@ -867,6 +954,7 @@ function createMockSocket(): MockSocket { interface FactoryOptions { onDispose?: () => void; onCertificateRefreshNeeded?: () => Promise; + onConnectionFailure?: (reason: ConnectionStateReason) => void; telemetry?: TelemetryReporter; } @@ -929,6 +1017,7 @@ async function fromFactory( telemetry: options.telemetry ?? NOOP_TELEMETRY_REPORTER, onCertificateRefreshNeeded: options.onCertificateRefreshNeeded ?? (() => Promise.resolve(false)), + onConnectionFailure: options.onConnectionFailure, }, options.onDispose, ); diff --git a/test/unit/workspace/workspaceMonitor.test.ts b/test/unit/workspace/workspaceMonitor.test.ts index 29fd685848..f6d7ac90c0 100644 --- a/test/unit/workspace/workspaceMonitor.test.ts +++ b/test/unit/workspace/workspaceMonitor.test.ts @@ -55,6 +55,7 @@ describe("WorkspaceMonitor", () => { const statusBar = new MockStatusBarItem(); const contextManager = new MockContextManager(); const logger = createMockLogger(); + const connectionLogBuffer = { flush: vi.fn() }; const client = { watchWorkspace: vi.fn().mockResolvedValue(stream), getTemplate: vi.fn().mockResolvedValue({ @@ -71,6 +72,7 @@ describe("WorkspaceMonitor", () => { telemetry, logger, contextManager, + connectionLogBuffer, }), ); return { @@ -81,6 +83,7 @@ describe("WorkspaceMonitor", () => { statusBar, contextManager, logger, + connectionLogBuffer, }; } @@ -112,6 +115,18 @@ describe("WorkspaceMonitor", () => { }); }); + describe("connection failure", () => { + it("flushes the connection log buffer when the socket errors", async () => { + const { stream, connectionLogBuffer } = await setup(); + + stream.pushError(new Error("socket boom")); + + expect(connectionLogBuffer.flush).toHaveBeenCalledWith( + "workspace_monitor_error", + ); + }); + }); + describe("state logging", () => { it("logs the initial workspace state as observed with flat scalars", async () => { const { logger } = await setup(