diff --git a/src/core/container.ts b/src/core/container.ts index 02fbd70b3e..a93eec37a3 100644 --- a/src/core/container.ts +++ b/src/core/container.ts @@ -1,6 +1,8 @@ import * as vscode from "vscode"; import { AuthTelemetry } from "../instrumentation/auth"; +import { prefixLogger } from "../logging/prefixLogger"; +import { shortId } from "../logging/utils"; import { LoginCoordinator } from "../login/loginCoordinator"; import { OAuthCallback } from "../oauth/oauthCallback"; import { buildSession, extractExtensionVersion } from "../telemetry/event"; @@ -26,7 +28,9 @@ import type { Logger } from "../logging/logger"; * Centralizes the creation and management of all core services. */ export class ServiceContainer implements vscode.Disposable { - private readonly logger: vscode.LogOutputChannel; + private readonly outputChannel: vscode.LogOutputChannel; + private readonly sessionId: string; + private readonly logger: Logger; private readonly pathResolver: PathResolver; private readonly mementoManager: MementoManager; private readonly secretsManager: SecretsManager; @@ -42,7 +46,16 @@ export class ServiceContainer implements vscode.Disposable { private readonly commandManager: CommandManager; constructor(context: vscode.ExtensionContext) { - this.logger = vscode.window.createOutputChannel("Coder", { log: true }); + this.outputChannel = vscode.window.createOutputChannel("Coder", { + log: true, + }); + // One session ID per activation, shared by logs, API requests, + // telemetry, and the CLI so all data for a session correlates. + this.sessionId = newSessionId(); + this.logger = prefixLogger( + this.outputChannel, + `[session ${shortId(this.sessionId)}]`, + ); this.pathResolver = new PathResolver( context.globalStorageUri.fsPath, context.logUri.fsPath, @@ -56,7 +69,7 @@ export class ServiceContainer implements vscode.Disposable { const session = buildSession( extractExtensionVersion(context.extension.packageJSON), - newSessionId(), + this.sessionId, ); const localJsonlSink = LocalJsonlSink.start( { @@ -187,7 +200,7 @@ export class ServiceContainer implements vscode.Disposable { try { await this.telemetryService.dispose(); } finally { - this.logger.dispose(); + this.outputChannel.dispose(); } } } diff --git a/src/logging/httpLogger.ts b/src/logging/httpLogger.ts index 424fd591be..f780342aa5 100644 --- a/src/logging/httpLogger.ts +++ b/src/logging/httpLogger.ts @@ -45,7 +45,7 @@ export function logRequest( const { requestId, method, url, requestSize } = parseConfig(config); const msg = [ - `→ ${shortId(requestId)} ${method} ${url} ${requestSize}`, + `→ [request ${shortId(requestId)}] ${method} ${url} ${requestSize}`, ...buildExtraLogs( config.headers, config.data, @@ -73,7 +73,7 @@ export function logResponse( ); const msg = [ - `← ${shortId(requestId)} ${response.status} ${method} ${url} ${responseSize} ${time}`, + `← [request ${shortId(requestId)}] ${response.status} ${method} ${url} ${responseSize} ${time}`, ...buildExtraLogs( response.headers, response.data, @@ -115,7 +115,7 @@ export function logError( ); } - logPrefix = `← ${shortId(requestId)} ${error.response.status} ${method} ${url} ${time}`; + logPrefix = `← [request ${shortId(requestId)}] ${error.response.status} ${method} ${url} ${time}`; extraLines = buildExtraLogs( error.response.headers, error.response.data, @@ -126,7 +126,7 @@ export function logError( if (errorParts.length === 0) { errorParts.push(error.code || "Network error"); } - logPrefix = `✗ ${shortId(requestId)} ${method} ${url} ${time}`; + logPrefix = `✗ [request ${shortId(requestId)}] ${method} ${url} ${time}`; extraLines = buildExtraLogs( error?.config?.headers ?? {}, error.config?.data, diff --git a/src/logging/prefixLogger.ts b/src/logging/prefixLogger.ts new file mode 100644 index 0000000000..1cf4d2ce12 --- /dev/null +++ b/src/logging/prefixLogger.ts @@ -0,0 +1,18 @@ +import type { Logger } from "./logger"; + +/** + * Wraps a {@link Logger} so every message is prefixed, letting all lines that + * share a prefix (a session ID, a workspace name) be found with one search. + * Extra arguments are forwarded untouched. + */ +export function prefixLogger(inner: Logger, prefix: string): Logger { + const tag = (message: string) => `${prefix} ${message}`; + return { + trace: (message, ...args) => inner.trace(tag(message), ...args), + debug: (message, ...args) => inner.debug(tag(message), ...args), + info: (message, ...args) => inner.info(tag(message), ...args), + warn: (message, ...args) => inner.warn(tag(message), ...args), + error: (message, ...args) => inner.error(tag(message), ...args), + show: () => inner.show(), + }; +} diff --git a/test/unit/logging/httpLogger.test.ts b/test/unit/logging/httpLogger.test.ts index 116c24fe42..84ccb9485b 100644 --- a/test/unit/logging/httpLogger.test.ts +++ b/test/unit/logging/httpLogger.test.ts @@ -72,6 +72,40 @@ describe("REST HTTP Logger", () => { }); }); + describe("request identifiers", () => { + const REQUEST_ID = "abcdef1234567890abcdef1234567890"; + const config = { + method: "GET", + url: "https://api.example.com/endpoint", + headers: {} as unknown as AxiosHeaders, + metadata: { requestId: REQUEST_ID, startedAt: Date.now() }, + } as RequestConfigWithMeta; + + it("labels the shortened request ID on requests", () => { + const logger = createMockLogger(); + + logRequest(logger, config, HttpClientLogLevel.BASIC); + + expect(logger.trace).toHaveBeenCalledWith( + expect.stringContaining("[request abcdef12]"), + ); + }); + + it("labels the shortened request ID on responses", () => { + const logger = createMockLogger(); + + logResponse( + logger, + { status: 200, config, headers: {}, data: {} } as AxiosResponse, + HttpClientLogLevel.BASIC, + ); + + expect(logger.trace).toHaveBeenCalledWith( + expect.stringContaining("[request abcdef12]"), + ); + }); + }); + describe("error handling", () => { it("distinguishes between network errors and response errors", () => { const logger = createMockLogger(); diff --git a/test/unit/logging/prefixLogger.test.ts b/test/unit/logging/prefixLogger.test.ts new file mode 100644 index 0000000000..7fbf0fad9d --- /dev/null +++ b/test/unit/logging/prefixLogger.test.ts @@ -0,0 +1,45 @@ +import { describe, expect, it } from "vitest"; + +import { prefixLogger } from "@/logging/prefixLogger"; + +import { createMockLogger } from "../../mocks/testHelpers"; + +const PREFIX = "[0123456789abcdef0123456789abcdef]"; + +describe("prefixLogger", () => { + it("prefixes every level with the given prefix", () => { + const inner = createMockLogger(); + const logger = prefixLogger(inner, PREFIX); + + logger.trace("trace msg"); + logger.debug("debug msg"); + logger.info("info msg"); + logger.warn("warn msg"); + logger.error("error msg"); + + expect(inner.trace).toHaveBeenCalledWith(`${PREFIX} trace msg`); + expect(inner.debug).toHaveBeenCalledWith(`${PREFIX} debug msg`); + expect(inner.info).toHaveBeenCalledWith(`${PREFIX} info msg`); + expect(inner.warn).toHaveBeenCalledWith(`${PREFIX} warn msg`); + expect(inner.error).toHaveBeenCalledWith(`${PREFIX} error msg`); + }); + + it("forwards additional arguments unchanged", () => { + const inner = createMockLogger(); + const logger = prefixLogger(inner, PREFIX); + const err = new Error("boom"); + + logger.error("failed", err, 42); + + expect(inner.error).toHaveBeenCalledWith(`${PREFIX} failed`, err, 42); + }); + + it("delegates show() to the underlying logger", () => { + const inner = createMockLogger(); + const logger = prefixLogger(inner, PREFIX); + + logger.show(); + + expect(inner.show).toHaveBeenCalledOnce(); + }); +});