-
Notifications
You must be signed in to change notification settings - Fork 48
feat: buffer connection logs and flush them on failure #1100
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
a800f6e
69efd2f
bbb9d5b
9c3d21b
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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 | ||
|
Comment on lines
+218
to
+222
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please describe this as a maximum number of entries, not lines or bytes; one entry can contain multiple lines and arguments. Should we also set an upper limit on the configurable capacity? If so, enforce the same limit in |
||
| }, | ||
| "coder.httpClientLogLevel": { | ||
| "markdownDescription": "Controls the verbosity of HTTP client logging. This affects what details are logged for each HTTP request and response.", | ||
| "type": "string", | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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; | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please keep a single field typed as |
||
| this.disposables.push( | ||
| this.connectionLogBuffer, | ||
| vscode.workspace.onDidChangeConfiguration((event) => { | ||
| if (event.affectsConfiguration(CONNECTION_LOG_BUFFER_SIZE_KEY)) { | ||
| this.connectionLogBuffer.setCapacity(readConnectionLogBufferSize()); | ||
| } | ||
| }), | ||
| ); | ||
|
Comment on lines
+67
to
74
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Once the log-level subscription is removed, only the configuration subscription needs cleanup here. Please store it in a named field and dispose it explicitly, matching the surrounding services. A generic |
||
| 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,10 +218,25 @@ 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 { | ||
| this.outputChannel.dispose(); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| const CONNECTION_LOG_BUFFER_SIZE_KEY = "coder.connectionLogBuffer.size"; | ||
| const DEFAULT_CONNECTION_LOG_BUFFER_SIZE = 1000; | ||
|
Comment on lines
+232
to
+233
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please move these constants below the imports, before the class. |
||
|
|
||
| function readConnectionLogBufferSize(): number { | ||
| return vscode.workspace | ||
| .getConfiguration() | ||
| .get<number>( | ||
| CONNECTION_LOG_BUFFER_SIZE_KEY, | ||
| DEFAULT_CONNECTION_LOG_BUFFER_SIZE, | ||
| ); | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -143,6 +143,7 @@ async function doActivate( | |
| deploymentSessionAuth?.token, | ||
| output, | ||
| telemetryService, | ||
| (reason) => serviceContainer.getConnectionLogBuffer().flush(reason), | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This only wires the shared client. Please pass the callback to |
||
| ); | ||
| ctx.subscriptions.push(client); | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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<Level, string> = { | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please use |
||
| 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 { | ||
|
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Could we call this |
||
| 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. | ||
|
Comment on lines
+48
to
+58
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please shorten this to the behavior that matters: “Buffers entries below the current log level and replays them on failure at a level the output channel persists.” The implementation explains the rest. Please also avoid em-dashes in the added comments. |
||
| */ | ||
| 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, | ||
|
Comment on lines
+71
to
+72
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The injected clock mainly supports suppression tests. Once suppression is removed, can we use |
||
| ) { | ||
| this.capacity = normalizeCapacity(capacity); | ||
| this.currentLevel = levelSource.getLogLevel(); | ||
| this.levelSubscription = levelSource.onDidChangeLogLevel((level) => { | ||
| this.currentLevel = level; | ||
| }); | ||
|
Comment on lines
+75
to
+78
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Can we accept a single |
||
| } | ||
|
|
||
| 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; | ||
| } | ||
|
Comment on lines
+125
to
+127
Collaborator
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. If failure A flushes, then new logs arrive before failure B one second later, B’s logs remain buffered with no later write scheduled. Please remove the suppression window and its state. Clearing the buffer already prevents duplicate replay. Add a test showing that two consecutive failures each flush their newly accumulated entries. |
||
| 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(); | ||
| } | ||
| } | ||
| } | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please add this key to
COLLECTED_SETTINGSinsrc/supportBundle/settings.ts. Otherwise Support cannot tell from the bundle whether buffering was disabled or its capacity changed.