Skip to content

feat: buffer connection logs and flush them on failure - #1100

Open
aqandrew wants to merge 21 commits into
mainfrom
aqandrew/devex-669-vs-code-add-log-buffer
Open

feat: buffer connection logs and flush them on failure#1100
aqandrew wants to merge 21 commits into
mainfrom
aqandrew/devex-669-vs-code-add-log-buffer

Conversation

@aqandrew

Copy link
Copy Markdown
Contributor

Implements RFC requirement 13 / DEVEX-669: buffer connection debug logs in memory below the current log level and flush them on a genuine connection failure, so a support bundle captures the detail leading up to the failure without the user having enabled debug logging beforehand.

What this does

  • Adds a BufferingLogger decorator (src/logging/logBuffer.ts) that wraps the "Coder" output channel and keeps a bounded, in-memory ring of the log lines that sit below the channel's current level — the ones it would otherwise drop. Only below-level lines are buffered, so nothing already written is duplicated.
  • On a connection failure, flush(reason) re-emits the captured lines into the output channel (each marked [buffered] with its original ISO timestamp and level) at the least-verbose level the channel still persists, so they land on disk and in support bundles.
  • Wires the buffer into ServiceContainer and adds the coder.connectionLogBuffer.size setting (default 1000, 0 disables).
  • Flushes 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 (5s) coalesces the burst of signals a single outage often triggers into one flush.
  • Documents the behavior, config, hard-kill/OOM loss limitation, and SSH log scope in CONTRIBUTING.md.

Scope notes

  • 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.
  • The buffer lives in memory, so a hard kill or out-of-memory event loses it (documented).

Commits

  1. BufferingLogger + unit tests
  2. container wiring + config
  3. failure-site wiring + tests
  4. docs

Testing

  • pnpm typecheck, pnpm format:check, and pnpm lint are clean.
  • Affected/dependent unit suites pass (logBuffer, reconnectingWebSocket, workspaceMonitor, workspaceStateMachine, coderApi, plus the container-mock consumers).
Implementation plan & design decisions

Design

  • Buffer: bounded entry-count ring; captures only calls whose severity is below the channel's current level; oldest-eviction; live-resizable via config.
  • Flush target (D3): replay into the existing "Coder" output channel at a level that still persists, with a [buffered] marker plus original level/timestamp, chronologically next to the real failure logs. Support bundles already collect the on-disk VS Code logs, so no separate sink is needed.
  • Flush reasons (D4): genuine, surfaced connection failures only — reconnecting-socket terminal failures, WorkspaceMonitor.notifyError, and agent disconnected. Never on transient retrying drops or intentional teardown (manual_disconnect, normal_close, replaced, dispose/deactivate/reload). A single isConnectionFailure(reason) predicate gates the socket sites, and a short suppression window coalesces bursts.
  • SSH scope (D5): buffer extension SSH debug passing through the shared Logger; do not buffer CLI ProxyCommand file logs already handled via coder.proxyLogDirectory.

Decisions

  • D1: buffer all below-level session logs.
  • D2: bound by entry count.
  • D3: replay into the existing Coder output channel at a persisted level with [buffered] marker/original level/timestamp.
  • D4: flush only on genuine connection failure; not transient or intentional teardown.
  • D5: buffer extension SSH debug through the shared Logger; not CLI ProxyCommand file logs.

🤖 Generated with Coder Agents. Reviewed and authored on behalf of @aqandrew.

Wraps a Logger and keeps a bounded in-memory ring of entries below the sink's
current level (the ones it would drop). flush() replays them into the sink at a
level guaranteed to be written, so a connection failure can preserve the debug
detail leading up to it without the user having enabled debug logging.

Only below-level entries are buffered (no duplication of what the sink already
writes); flush is coalesced by a short suppression window.
@linear-code

linear-code Bot commented Aug 26, 2026

Copy link
Copy Markdown

DEVEX-669

@aqandrew
aqandrew marked this pull request as ready for review September 1, 2026 03:30
@aqandrew
aqandrew requested a review from EhabY September 1, 2026 03:30

@EhabY EhabY left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please address the inline comments on remote-client failure wiring, the monitor's failure trigger, and flush suppression. The remaining comments cover simplification, test coverage, and naming.

Review generated with Coder Agents on behalf of @EhabY.

Comment thread src/extension.ts
Comment thread src/workspace/workspaceMonitor.ts Outdated
Comment thread test/unit/workspace/workspaceMonitor.test.ts Outdated
Comment thread src/logging/logBuffer.ts Outdated
Comment thread src/logging/logBuffer.ts Outdated
Comment thread src/websocket/reconnectingWebSocket.ts Outdated
Comment thread src/logging/logBuffer.ts Outdated
Comment thread src/core/container.ts Outdated
Comment thread src/logging/logBuffer.ts Outdated
Comment thread src/logging/logBuffer.ts Outdated
@aqandrew
aqandrew requested a review from EhabY September 9, 2026 19:53

@EhabY EhabY left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two blocking items: the ws close event shape makes the unrecoverable_close flush unreachable in production, and the monitor test cannot fail. The rest covers trigger scope, where the settings reader lives, and trimming the buffer and its tests.

The PR description also needs a refresh: it still mentions the suppression window, the monitor trigger, isConnectionFailure, and four commits where there are twenty.

error: options.error,
});
this.clearCurrentSocket(options.code, options.closeReason);
if (isTerminalConnectionFailure(reason)) {

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This one's blocking, even though it predates the PR: in production reason never becomes unrecoverable_close, so this flush never runs.

Here's why. OneWayWebSocket.addEventListener (oneWayWebSocket.ts:85) uses ws.on() for everything but messages, and ws emits close as positional (code, reason). So handleSocketClose at :409 gets a bare number, event.code is undefined, and every server close lands in unexpected_close and retries forever. normal_close is dead for the same reason. The new tests only pass because they hand-build { code, reason }.

I checked against the bundled ws 8.21.3: on("close") gives 1002 with no .code, while addEventListener("close") gives a CloseEvent with code: 1002.

The fix is small: switch to this.#socket.addEventListener(event, callback) for the non-message events and mirror it in removeEventListener at :102. Fine to land it here since the feature depends on it, or in a quick PR first.

});

describe("connection failure", () => {
it("does not flush the log buffer on a malformed message", async () => {

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

WorkspaceMonitor doesn't touch the buffer anymore, so this can't fail. Let's drop the block and the connectionLogBuffer plumbing at :58, :75, and :86. I asked for this test before the removal, sorry for the churn.

Comment thread src/logging/logBuffer.ts

const emit = this.replayEmitter();
emit(
`[buffered] connection failure (${reason}): replaying ${entries.length} buffered log line(s)`,

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, do we only flush on a connection failure? Right now it's three socket reasons (unrecoverable_close, unrecoverable_http, certificate_error) plus the agent disconnected arm. That's too wide in one spot and too narrow in two.

Too wide: a 401 on the handshake counts as unrecoverable_http (reconnectingWebSocket.ts:545). With OAuth the token refreshes seconds later and reconnect() runs on the same sockets (coderApi.ts:226), so we dump a failure block for a blip that fixes itself, and the ring is empty when a real failure comes. Let's exclude UNAUTHORIZED, or flush only if the reconnect after the refresh fails too. Side note: isUnrecoverableHttpError at :567 is a substring match, so ECONNREFUSED 127.0.0.1:4040 matches 404.

Too narrow: only the disconnected arm in workspaceStateMachine.ts:195 flushes. Canceled builds, missing agents, the timeout loop, and CLI or certificate failures all end up in the "Failed to open workspace" catch at extension.ts:480, which reloads the window with nothing flushed. One flush in that catch covers all of them, and then this arm, the field at :54, and the testHelpers.ts:629 override can go.

Also too narrow: an unreachable server never produces a terminal reason (reconnectingWebSocket.ts:34), so the most common outage never flushes, and the retry chatter pushes the pre-outage context out of the ring. Follow-up, not a blocker: flush after N failed attempts, which telemetry already counts.

Last thing: the block is hard to attribute. The ring is shared by the sidebar sockets and the remote client, so one outage writes one header per socket and nothing tells them apart. Pass this.#route into the callback at :316 and add it to the error line at :421, the only one missing it.

Comment thread src/core/container.ts
CONNECTION_LOG_BUFFER_SIZE_KEY,
DEFAULT_CONNECTION_LOG_BUFFER_SIZE,
);
}

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reading the setting and its default doesn't belong in the container. I'd add src/settings/logger.ts shaped like telemetry.ts: the key constant, the default, and a readConnectionLogBufferSize(cfg) that owns the 0 to 10000 clamp, the way readNumber does there.

Two things come along. normalizeCapacity and MAX_CONNECTION_LOG_BUFFER_SIZE leave logBuffer.ts, since the logger can trust the number it gets. That also fixes logBuffer.ts:45, where Number.isFinite turns "2000" and 1e400 into 0 without a word. And getLogLevel at coderApi.ts:823 becomes readHttpClientLogLevel(cfg) in the same file; it's a logging setting reader that happens to live in the API client.

While you're there, swap the hand-rolled onDidChangeConfiguration at :64 for watchConfigurationChanges. This is the only direct subscriber outside configWatcher.ts; the other six call sites use the helper.

One correction to my own draft about the callback at logBuffer.ts:61: I wanted the level to come from the same settings file, but it isn't a setting. It's LogOutputChannel.logLevel, set from the gear menu. If the callback feels indirect, pass the channel typed as { readonly logLevel: number } and tests hand in a plain object.

Comment thread src/logging/logBuffer.ts
* 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 {

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few things in this file. Two are real fixes.

:114: at level Off the emitter falls through to info, which the channel drops, but the entries are already gone. Return early when the level is 0 so the context survives until logging comes back on.

:122: flush writes every buffered line to disk no matter what's in it. With coder.httpClientLogLevel: body the trace lines carry bodies, and SENSITIVE_BODY_FIELDS (formatters.ts:19) doesn't list registration_access_token. Add it, and maybe skip HTTP trace entries when body logging is on.

The rest is trimming:

  • :38 promises a memory bound, but it's an entry count and each entry holds live args references. Say "bounds the entry count".
  • :18 LEVEL_LABEL is level.toUpperCase() for every row. Drop it.
  • :134 replayEmitter builds a closure to pick one of three methods. Pick the name inline and call this.inner[sink].
  • :118 says "log line(s)" but the unit is entries, and multi-line entries only get [buffered] on the first physical line. Say "entries" and prefix each line with message.replaceAll("\n", "\n[buffered] ").
  • :55, optional: a factory like prefixLogger turns the five pass-throughs into one wrap(level). Only container.ts:59 constructs this.

}

describe("BufferingLogger", () => {
it("forwards every call to the inner logger", () => {

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The new tests are heavier than the code they cover, in three places.

Here, every test repeats nine lines of setup and flush-and-collect. A setup(level, capacity) returning { buffer, calls, state, flushed } removes most of it. Then :56, :79, :110, :288, :329, and :345 fold into one level table, :128, :224, :251, and :266 into a capacity table, and :149 and :194 can go since :166 proves both with one extra expect. The fake timers at :80 can be vi.spyOn(Date, "now").mockReturnValueOnce(). 15 tests become 6.

In reconnectingWebSocket.test.ts, the tables at :801 to :824 test Set.has. Drop them, un-export isTerminalConnectionFailure, and fix its comment at :37 to "Whether a reason stops automatic retries." For the behavior, default onConnectionFailure: vi.fn() in fromFactory (:1012) and add one expect to the existing tables at :58, :76, :97 and the refresh-fails test at :737. That covers unrecoverable_http and certificate_error, which only the predicate table checks today.

In coderApi.test.ts, give createMockWebSocket (:1230) a fireClose like createMockEventSource already has, and the test at :586 shrinks to ten lines. Once the oneWayWebSocket fix lands, fire it the way ws does.

Comment thread package.json Outdated
"default": 250
},
"coder.connectionLogBuffer.size": {
"markdownDescription": "Maximum number of connection debug log entries to keep in memory below the current log level. Each entry may span multiple lines and structured arguments. 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. Values above `10000` are clamped to `10000`. The buffer is lost on a hard kill or out-of-memory event.",

@EhabY EhabY Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The buffer holds every below-level entry, not only debug or connection ones. The schema maximum already handles the clamp and the hard-kill note lives in CONTRIBUTING, so both sentences can go. How about:

Maximum number of log entries below the Coder output channel's log level to keep in memory. When a connection fails, the extension writes them to the channel so a support bundle includes the detail leading up to the failure without debug logging enabled beforehand. Set to 0 to disable.

CONTRIBUTING.md:142 could use the same pass: there's still an em dash and the section runs long. Say "entries" rather than "log lines", cut the not-buffered paragraph to a sentence, and if the 401 trigger stays, soften "never on transient drops".

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like it! Done in b8bf5ba. Will resolve this thread once I remove the 401 trigger like you suggested in your other comment

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants