diff --git a/.gitignore b/.gitignore index 75f80c5f..faf84830 100644 --- a/.gitignore +++ b/.gitignore @@ -6,3 +6,4 @@ /coverage/ *.vsix yarn-error.log +.DS_Store \ No newline at end of file diff --git a/CLAUDE.md b/CLAUDE.md index 04c75edc..7acd9bb9 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -25,3 +25,54 @@ - Error handling: wrap and type errors appropriately - Use async/await for promises, avoid explicit Promise construction where possible - Test files must be named `*.test.ts` and use Vitest + +## Development Workflow: Spec → Code + +THESE INSTRUCTIONS ARE CRITICAL! + +They dramatically improve the quality of the work you create. + +### Phase 1: Requirements First + +When asked to implement any feature or make changes, ALWAYS start by asking: +"Should I create a Spec for this task first?" + +IFF user agrees: + +- Create a markdown file in `.claude/scopes/FeatureName.md` +- Interview the user to clarify: +- Purpose & user problem +- Success criteria +- Scope & constraints +- Technical considerations +- Out of scope items + +### Phase 2: Review & Refine + +After drafting the Spec: + +- Present it to the user +- Ask: "Does this capture your intent? Any changes needed?" +- Iterate until user approves +- End with: "Spec looks good? Type 'GO!' when ready to implement" + +### Phase 3: Implementation + +ONLY after user types "GO!" or explicitly approves: + +- Begin coding based on the Spec +- Reference the Spec for decisions +- Update Spec if scope changes, but ask user first. + +### File Organization + +``` + +.claude/ +├── scopes/ +│ ├── FeatureName.md # Shared/committed Specs +│ └── OtherFeature.md # Other Specs, for future or past work + +``` + +**Remember: Think first, ask clarifying questions, _then_ code. The Spec is your north star.** diff --git a/src/api.ts b/src/api.ts index 22de2618..986fc84e 100644 --- a/src/api.ts +++ b/src/api.ts @@ -105,7 +105,7 @@ export function makeCoderSdk( restClient.getAxiosInstance().interceptors.response.use( (r) => r, async (err) => { - throw await CertificateError.maybeWrap(err, baseUrl, storage); + throw await CertificateError.maybeWrap(err, baseUrl); }, ); diff --git a/src/commands.ts b/src/commands.ts index d6734376..0f89de1a 100644 --- a/src/commands.ts +++ b/src/commands.ts @@ -10,6 +10,7 @@ import * as vscode from "vscode"; import { makeCoderSdk, needToken } from "./api"; import { extractAgents } from "./api-helper"; import { CertificateError } from "./error"; +import { logger } from "./logger"; import { Storage } from "./storage"; import { toRemoteAuthority, toSafeHost } from "./util"; import { OpenableTreeItem } from "./workspacesProvider"; @@ -245,9 +246,7 @@ export class Commands { } catch (err) { const message = getErrorMessage(err, "no response from the server"); if (isAutologin) { - this.storage.writeToCoderOutputChannel( - `Failed to log in to Coder server: ${message}`, - ); + logger.info(`Failed to log in to Coder server: ${message}`); } else { this.vscodeProposed.window.showErrorMessage( "Failed to log in to Coder server", diff --git a/src/error.test.ts b/src/error.test.ts index 3c4a50c3..eb710b0e 100644 --- a/src/error.test.ts +++ b/src/error.test.ts @@ -19,16 +19,19 @@ const isElectron = // TODO: Remove the vscode mock once we revert the testing framework. beforeAll(() => { vi.mock("vscode", () => { - return {}; + return { + workspace: { + getConfiguration: vi.fn().mockReturnValue({ + get: vi.fn().mockReturnValue(false), + }), + onDidChangeConfiguration: vi.fn().mockReturnValue({ + dispose: vi.fn(), + }), + }, + }; }); }); -const logger = { - writeToCoderOutputChannel(message: string) { - throw new Error(message); - }, -}; - const disposers: (() => void)[] = []; afterAll(() => { disposers.forEach((d) => d()); @@ -89,7 +92,7 @@ it("detects partial chains", async () => { try { await request; } catch (error) { - const wrapped = await CertificateError.maybeWrap(error, address, logger); + const wrapped = await CertificateError.maybeWrap(error, address); expect(wrapped instanceof CertificateError).toBeTruthy(); expect((wrapped as CertificateError).x509Err).toBe(X509_ERR.PARTIAL_CHAIN); } @@ -126,7 +129,7 @@ it("detects self-signed certificates without signing capability", async () => { try { await request; } catch (error) { - const wrapped = await CertificateError.maybeWrap(error, address, logger); + const wrapped = await CertificateError.maybeWrap(error, address); expect(wrapped instanceof CertificateError).toBeTruthy(); expect((wrapped as CertificateError).x509Err).toBe(X509_ERR.NON_SIGNING); } @@ -157,7 +160,7 @@ it("detects self-signed certificates", async () => { try { await request; } catch (error) { - const wrapped = await CertificateError.maybeWrap(error, address, logger); + const wrapped = await CertificateError.maybeWrap(error, address); expect(wrapped instanceof CertificateError).toBeTruthy(); expect((wrapped as CertificateError).x509Err).toBe(X509_ERR.UNTRUSTED_LEAF); } @@ -200,7 +203,7 @@ it("detects an untrusted chain", async () => { try { await request; } catch (error) { - const wrapped = await CertificateError.maybeWrap(error, address, logger); + const wrapped = await CertificateError.maybeWrap(error, address); expect(wrapped instanceof CertificateError).toBeTruthy(); expect((wrapped as CertificateError).x509Err).toBe( X509_ERR.UNTRUSTED_CHAIN, @@ -247,7 +250,7 @@ it("falls back with different error", async () => { try { await request; } catch (error) { - const wrapped = await CertificateError.maybeWrap(error, "1", logger); + const wrapped = await CertificateError.maybeWrap(error, "1"); expect(wrapped instanceof CertificateError).toBeFalsy(); expect((wrapped as Error).message).toMatch(/failed with status code 500/); } diff --git a/src/error.ts b/src/error.ts index 53cc3389..e2ef93d4 100644 --- a/src/error.ts +++ b/src/error.ts @@ -3,6 +3,7 @@ import { isApiError, isApiErrorResponse } from "coder/site/src/api/errors"; import * as forge from "node-forge"; import * as tls from "tls"; import * as vscode from "vscode"; +import { logger } from "./logger"; // X509_ERR_CODE represents error codes as returned from BoringSSL/OpenSSL. export enum X509_ERR_CODE { @@ -21,10 +22,6 @@ export enum X509_ERR { UNTRUSTED_CHAIN = "Your Coder deployment's certificate chain does not appear to be trusted by this system. The root of the certificate chain must be added to this system's trust store. ", } -export interface Logger { - writeToCoderOutputChannel(message: string): void; -} - interface KeyUsage { keyCertSign: boolean; } @@ -47,7 +44,6 @@ export class CertificateError extends Error { static async maybeWrap( err: T, address: string, - logger: Logger, ): Promise { if (isAxiosError(err)) { switch (err.code) { @@ -59,7 +55,7 @@ export class CertificateError extends Error { await CertificateError.determineVerifyErrorCause(address); return new CertificateError(err.message, cause); } catch (error) { - logger.writeToCoderOutputChannel( + logger.info( `Failed to parse certificate from ${address}: ${error}`, ); break; diff --git a/src/extension.ts b/src/extension.ts index 05eb7319..c2a31136 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -7,6 +7,7 @@ import { makeCoderSdk, needToken } from "./api"; import { errToStr } from "./api-helper"; import { Commands } from "./commands"; import { CertificateError, getErrorDetail } from "./error"; +import { logger } from "./logger"; import { Remote } from "./remote"; import { Storage } from "./storage"; import { toSafeHost } from "./util"; @@ -48,6 +49,10 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { } const output = vscode.window.createOutputChannel("Coder"); + + // Initialize logger with the output channel + logger.initialize(output); + const storage = new Storage( output, ctx.globalState, @@ -317,7 +322,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { } } catch (ex) { if (ex instanceof CertificateError) { - storage.writeToCoderOutputChannel(ex.x509Err || ex.message); + logger.info(ex.x509Err || ex.message); await ex.showModal("Failed to open workspace"); } else if (isAxiosError(ex)) { const msg = getErrorMessage(ex, "None"); @@ -326,7 +331,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { const method = ex.config?.method?.toUpperCase() || "request"; const status = ex.response?.status || "None"; const message = `API ${method} to '${urlString}' failed.\nStatus code: ${status}\nMessage: ${msg}\nDetail: ${detail}`; - storage.writeToCoderOutputChannel(message); + logger.info(message); await vscodeProposed.window.showErrorMessage( "Failed to open workspace", { @@ -337,7 +342,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { ); } else { const message = errToStr(ex, "No error message was provided"); - storage.writeToCoderOutputChannel(message); + logger.info(message); await vscodeProposed.window.showErrorMessage( "Failed to open workspace", { @@ -356,14 +361,12 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { // See if the plugin client is authenticated. const baseUrl = restClient.getAxiosInstance().defaults.baseURL; if (baseUrl) { - storage.writeToCoderOutputChannel( - `Logged in to ${baseUrl}; checking credentials`, - ); + logger.info(`Logged in to ${baseUrl}; checking credentials`); restClient .getAuthenticatedUser() .then(async (user) => { if (user && user.roles) { - storage.writeToCoderOutputChannel("Credentials are valid"); + logger.info("Credentials are valid"); vscode.commands.executeCommand( "setContext", "coder.authenticated", @@ -381,17 +384,13 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { myWorkspacesProvider.fetchAndRefresh(); allWorkspacesProvider.fetchAndRefresh(); } else { - storage.writeToCoderOutputChannel( - `No error, but got unexpected response: ${user}`, - ); + logger.info(`No error, but got unexpected response: ${user}`); } }) .catch((error) => { // This should be a failure to make the request, like the header command // errored. - storage.writeToCoderOutputChannel( - `Failed to check user authentication: ${error.message}`, - ); + logger.info(`Failed to check user authentication: ${error.message}`); vscode.window.showErrorMessage( `Failed to check user authentication: ${error.message}`, ); @@ -400,7 +399,7 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { vscode.commands.executeCommand("setContext", "coder.loaded", true); }); } else { - storage.writeToCoderOutputChannel("Not currently logged in"); + logger.info("Not currently logged in"); vscode.commands.executeCommand("setContext", "coder.loaded", true); // Handle autologin, if not already logged in. diff --git a/src/headers.test.ts b/src/headers.test.ts index 5cf333f5..9ef80010 100644 --- a/src/headers.test.ts +++ b/src/headers.test.ts @@ -1,86 +1,94 @@ import * as os from "os"; -import { it, expect, describe, beforeEach, afterEach, vi } from "vitest"; +import { + it, + expect, + describe, + beforeEach, + afterEach, + vi, + beforeAll, +} from "vitest"; import { WorkspaceConfiguration } from "vscode"; import { getHeaderCommand, getHeaders } from "./headers"; -const logger = { - writeToCoderOutputChannel() { - // no-op - }, -}; +// Mock vscode module before importing anything that uses logger +beforeAll(() => { + vi.mock("vscode", () => { + return { + workspace: { + getConfiguration: vi.fn().mockReturnValue({ + get: vi.fn().mockReturnValue(false), + }), + onDidChangeConfiguration: vi.fn().mockReturnValue({ + dispose: vi.fn(), + }), + }, + }; + }); +}); it("should return no headers", async () => { - await expect(getHeaders(undefined, undefined, logger)).resolves.toStrictEqual( - {}, - ); - await expect( - getHeaders("localhost", undefined, logger), - ).resolves.toStrictEqual({}); - await expect(getHeaders(undefined, "command", logger)).resolves.toStrictEqual( - {}, - ); - await expect(getHeaders("localhost", "", logger)).resolves.toStrictEqual({}); - await expect(getHeaders("", "command", logger)).resolves.toStrictEqual({}); - await expect(getHeaders("localhost", " ", logger)).resolves.toStrictEqual( - {}, - ); - await expect(getHeaders(" ", "command", logger)).resolves.toStrictEqual({}); - await expect( - getHeaders("localhost", "printf ''", logger), - ).resolves.toStrictEqual({}); + await expect(getHeaders(undefined, undefined)).resolves.toStrictEqual({}); + await expect(getHeaders("localhost", undefined)).resolves.toStrictEqual({}); + await expect(getHeaders(undefined, "command")).resolves.toStrictEqual({}); + await expect(getHeaders("localhost", "")).resolves.toStrictEqual({}); + await expect(getHeaders("", "command")).resolves.toStrictEqual({}); + await expect(getHeaders("localhost", " ")).resolves.toStrictEqual({}); + await expect(getHeaders(" ", "command")).resolves.toStrictEqual({}); + await expect(getHeaders("localhost", "printf ''")).resolves.toStrictEqual({}); }); it("should return headers", async () => { await expect( - getHeaders("localhost", "printf 'foo=bar\\nbaz=qux'", logger), + getHeaders("localhost", "printf 'foo=bar\\nbaz=qux'"), ).resolves.toStrictEqual({ foo: "bar", baz: "qux", }); await expect( - getHeaders("localhost", "printf 'foo=bar\\r\\nbaz=qux'", logger), + getHeaders("localhost", "printf 'foo=bar\\r\\nbaz=qux'"), ).resolves.toStrictEqual({ foo: "bar", baz: "qux", }); await expect( - getHeaders("localhost", "printf 'foo=bar\\r\\n'", logger), + getHeaders("localhost", "printf 'foo=bar\\r\\n'"), ).resolves.toStrictEqual({ foo: "bar" }); await expect( - getHeaders("localhost", "printf 'foo=bar'", logger), + getHeaders("localhost", "printf 'foo=bar'"), ).resolves.toStrictEqual({ foo: "bar" }); await expect( - getHeaders("localhost", "printf 'foo=bar='", logger), + getHeaders("localhost", "printf 'foo=bar='"), ).resolves.toStrictEqual({ foo: "bar=" }); await expect( - getHeaders("localhost", "printf 'foo=bar=baz'", logger), + getHeaders("localhost", "printf 'foo=bar=baz'"), ).resolves.toStrictEqual({ foo: "bar=baz" }); - await expect( - getHeaders("localhost", "printf 'foo='", logger), - ).resolves.toStrictEqual({ foo: "" }); + await expect(getHeaders("localhost", "printf 'foo='")).resolves.toStrictEqual( + { foo: "" }, + ); }); it("should error on malformed or empty lines", async () => { await expect( - getHeaders("localhost", "printf 'foo=bar\\r\\n\\r\\n'", logger), - ).rejects.toMatch(/Malformed/); - await expect( - getHeaders("localhost", "printf '\\r\\nfoo=bar'", logger), + getHeaders("localhost", "printf 'foo=bar\\r\\n\\r\\n'"), ).rejects.toMatch(/Malformed/); await expect( - getHeaders("localhost", "printf '=foo'", logger), + getHeaders("localhost", "printf '\\r\\nfoo=bar'"), ).rejects.toMatch(/Malformed/); - await expect(getHeaders("localhost", "printf 'foo'", logger)).rejects.toMatch( + await expect(getHeaders("localhost", "printf '=foo'")).rejects.toMatch( + /Malformed/, + ); + await expect(getHeaders("localhost", "printf 'foo'")).rejects.toMatch( + /Malformed/, + ); + await expect(getHeaders("localhost", "printf ' =foo'")).rejects.toMatch( + /Malformed/, + ); + await expect(getHeaders("localhost", "printf 'foo =bar'")).rejects.toMatch( /Malformed/, ); await expect( - getHeaders("localhost", "printf ' =foo'", logger), - ).rejects.toMatch(/Malformed/); - await expect( - getHeaders("localhost", "printf 'foo =bar'", logger), - ).rejects.toMatch(/Malformed/); - await expect( - getHeaders("localhost", "printf 'foo foo=bar'", logger), + getHeaders("localhost", "printf 'foo foo=bar'"), ).rejects.toMatch(/Malformed/); }); @@ -92,13 +100,12 @@ it("should have access to environment variables", async () => { os.platform() === "win32" ? "printf url=%CODER_URL%" : "printf url=$CODER_URL", - logger, ), ).resolves.toStrictEqual({ url: coderUrl }); }); it("should error on non-zero exit", async () => { - await expect(getHeaders("localhost", "exit 10", logger)).rejects.toMatch( + await expect(getHeaders("localhost", "exit 10")).rejects.toMatch( /exited unexpectedly with code 10/, ); }); diff --git a/src/headers.ts b/src/headers.ts index 4d4b5f44..aa549f1b 100644 --- a/src/headers.ts +++ b/src/headers.ts @@ -2,12 +2,9 @@ import * as cp from "child_process"; import * as os from "os"; import * as util from "util"; import type { WorkspaceConfiguration } from "vscode"; +import { logger } from "./logger"; import { escapeCommandArg } from "./util"; -export interface Logger { - writeToCoderOutputChannel(message: string): void; -} - interface ExecException { code?: number; stderr?: string; @@ -59,7 +56,6 @@ export function getHeaderArgs(config: WorkspaceConfiguration): string[] { export async function getHeaders( url: string | undefined, command: string | undefined, - logger: Logger, ): Promise> { const headers: Record = {}; if ( @@ -78,11 +74,11 @@ export async function getHeaders( }); } catch (error) { if (isExecException(error)) { - logger.writeToCoderOutputChannel( + logger.info( `Header command exited unexpectedly with code ${error.code}`, ); - logger.writeToCoderOutputChannel(`stdout: ${error.stdout}`); - logger.writeToCoderOutputChannel(`stderr: ${error.stderr}`); + logger.info(`stdout: ${error.stdout}`); + logger.info(`stderr: ${error.stderr}`); throw new Error( `Header command exited unexpectedly with code ${error.code}`, ); diff --git a/src/inbox.ts b/src/inbox.ts index 709dfbd8..a36ccc81 100644 --- a/src/inbox.ts +++ b/src/inbox.ts @@ -8,6 +8,7 @@ import * as vscode from "vscode"; import { WebSocket } from "ws"; import { coderSessionTokenHeader } from "./api"; import { errToStr } from "./api-helper"; +import { logger } from "./logger"; import { type Storage } from "./storage"; // These are the template IDs of our notifications. @@ -63,7 +64,7 @@ export class Inbox implements vscode.Disposable { }); this.#socket.on("open", () => { - this.#storage.writeToCoderOutputChannel("Listening to Coder Inbox"); + logger.info("Listening to Coder Inbox"); }); this.#socket.on("error", (error) => { @@ -86,9 +87,7 @@ export class Inbox implements vscode.Disposable { dispose() { if (!this.#disposed) { - this.#storage.writeToCoderOutputChannel( - "No longer listening to Coder Inbox", - ); + logger.info("No longer listening to Coder Inbox"); this.#socket.close(); this.#disposed = true; } @@ -99,6 +98,6 @@ export class Inbox implements vscode.Disposable { error, "Got empty error while monitoring Coder Inbox", ); - this.#storage.writeToCoderOutputChannel(message); + logger.info(message); } } diff --git a/src/logger.test.ts b/src/logger.test.ts new file mode 100644 index 00000000..8830d093 --- /dev/null +++ b/src/logger.test.ts @@ -0,0 +1,476 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +// Mock vscode module before importing logger +vi.mock("vscode", () => ({ + workspace: { + getConfiguration: vi.fn().mockReturnValue({ + get: vi.fn().mockReturnValue(false), + }), + onDidChangeConfiguration: vi.fn().mockReturnValue({ + dispose: vi.fn(), + }), + }, + Disposable: class { + dispose = vi.fn(); + }, +})); + +import * as vscode from "vscode"; +import { + ArrayAdapter, + LogLevel, + NoOpAdapter, + OutputChannelAdapter, + logger, +} from "./logger"; + +describe("Logger", () => { + beforeEach(() => { + process.env.NODE_ENV = "test"; + logger.reset(); + }); + + afterEach(() => { + logger.reset(); + vi.clearAllMocks(); + }); + + describe("ArrayAdapter", () => { + it("should store messages in array", () => { + const adapter = new ArrayAdapter(); + adapter.write("test message 1"); + adapter.write("test message 2"); + + const snapshot = adapter.getSnapshot(); + expect(snapshot).toEqual(["test message 1", "test message 2"]); + }); + + it("should clear messages", () => { + const adapter = new ArrayAdapter(); + adapter.write("test message"); + adapter.clear(); + + const snapshot = adapter.getSnapshot(); + expect(snapshot).toEqual([]); + }); + + it("should return immutable snapshot", () => { + const adapter = new ArrayAdapter(); + adapter.write("test message"); + + const snapshot1 = adapter.getSnapshot(); + const snapshot2 = adapter.getSnapshot(); + + expect(snapshot1).not.toBe(snapshot2); + expect(snapshot1).toEqual(snapshot2); + }); + }); + + describe("OutputChannelAdapter", () => { + it("should write to output channel", () => { + const mockChannel = { + appendLine: vi.fn(), + clear: vi.fn(), + } as unknown as vscode.OutputChannel; + + const adapter = new OutputChannelAdapter(mockChannel); + adapter.write("test message"); + + expect(mockChannel.appendLine).toHaveBeenCalledWith("test message"); + }); + + it("should clear output channel", () => { + const mockChannel = { + appendLine: vi.fn(), + clear: vi.fn(), + } as unknown as vscode.OutputChannel; + + const adapter = new OutputChannelAdapter(mockChannel); + adapter.clear(); + + expect(mockChannel.clear).toHaveBeenCalled(); + }); + + it("should not throw if output channel is disposed", () => { + const mockChannel = { + appendLine: vi.fn().mockImplementation(() => { + throw new Error("Channel disposed"); + }), + clear: vi.fn().mockImplementation(() => { + throw new Error("Channel disposed"); + }), + } as unknown as vscode.OutputChannel; + + const adapter = new OutputChannelAdapter(mockChannel); + + expect(() => adapter.write("test")).not.toThrow(); + expect(() => adapter.clear()).not.toThrow(); + }); + }); + + describe("NoOpAdapter", () => { + it("should do nothing", () => { + const adapter = new NoOpAdapter(); + expect(() => adapter.write("test")).not.toThrow(); + expect(() => adapter.clear()).not.toThrow(); + }); + }); + + describe("Logger core functionality", () => { + it("should format info messages correctly", () => { + const adapter = new ArrayAdapter(); + logger.setAdapter(adapter); + + const beforeTime = new Date().toISOString(); + logger.info("Test info message"); + const afterTime = new Date().toISOString(); + + const logs = adapter.getSnapshot(); + expect(logs).toHaveLength(1); + + const logMatch = logs[0].match(/\[info\] (\S+) Test info message/); + expect(logMatch).toBeTruthy(); + + const timestamp = logMatch![1]; + expect(timestamp >= beforeTime).toBe(true); + expect(timestamp <= afterTime).toBe(true); + }); + + it("should format debug messages correctly", () => { + const adapter = new ArrayAdapter(); + logger.setAdapter(adapter); + logger.setLevel(LogLevel.DEBUG); + + logger.debug("Test debug message"); + + const logs = adapter.getSnapshot(); + expect(logs).toHaveLength(1); + expect(logs[0]).toMatch(/\[debug\] \S+ Test debug message/); + }); + + it("should include source location in debug messages when verbose", () => { + const adapter = new ArrayAdapter(); + logger.setAdapter(adapter); + logger.setLevel(LogLevel.DEBUG); + + logger.debug("Test debug with location"); + + const logs = adapter.getSnapshot(); + expect(logs).toHaveLength(1); + expect(logs[0]).toContain("[debug]"); + expect(logs[0]).toContain("Test debug with location"); + // Should contain source location - may be in either format + expect(logs[0]).toMatch(/\n\s+at .+:\d+|\n\s+at .+ \(.+:\d+\)/); + }); + + it("should respect log levels", () => { + const adapter = new ArrayAdapter(); + logger.setAdapter(adapter); + logger.setLevel(LogLevel.INFO); + + logger.debug("Debug message"); + logger.info("Info message"); + + const logs = adapter.getSnapshot(); + expect(logs).toHaveLength(1); + expect(logs[0]).toContain("Info message"); + }); + + it("should handle NONE log level", () => { + const adapter = new ArrayAdapter(); + logger.setAdapter(adapter); + logger.setLevel(LogLevel.NONE); + + logger.debug("Debug message"); + logger.info("Info message"); + + const logs = adapter.getSnapshot(); + expect(logs).toHaveLength(0); + }); + }); + + describe("Configuration", () => { + it("should read verbose setting on initialization", () => { + const mockConfig = { + get: vi.fn().mockReturnValue(true), + }; + vi.mocked(vscode.workspace.getConfiguration).mockReturnValue( + mockConfig as unknown as vscode.WorkspaceConfiguration, + ); + + logger.reset(); // Reset triggers re-initialization + + expect(vscode.workspace.getConfiguration).toHaveBeenCalledWith("coder"); + expect(mockConfig.get).toHaveBeenCalledWith("verbose", false); + }); + + it("should update log level when configuration changes", () => { + let configChangeCallback: ( + e: vscode.ConfigurationChangeEvent, + ) => void = () => {}; + const mockDisposable = { dispose: vi.fn() }; + + vi.mocked(vscode.workspace.onDidChangeConfiguration).mockImplementation( + (callback) => { + configChangeCallback = callback; + return mockDisposable as vscode.Disposable; + }, + ); + + const mockConfig = { + get: vi.fn().mockReturnValue(false), + }; + vi.mocked(vscode.workspace.getConfiguration).mockReturnValue( + mockConfig as unknown as vscode.WorkspaceConfiguration, + ); + + logger.reset(); + + // Change config to verbose + mockConfig.get.mockReturnValue(true); + configChangeCallback({ + affectsConfiguration: (section: string) => section === "coder.verbose", + } as vscode.ConfigurationChangeEvent); + + // Verify it reads the new config + expect(mockConfig.get).toHaveBeenCalledWith("verbose", false); + }); + + it("should ignore non-coder.verbose configuration changes", () => { + let configChangeCallback: ( + e: vscode.ConfigurationChangeEvent, + ) => void = () => {}; + vi.mocked(vscode.workspace.onDidChangeConfiguration).mockImplementation( + (callback) => { + configChangeCallback = callback; + return { dispose: vi.fn() } as unknown as vscode.Disposable; + }, + ); + + const mockConfig = { + get: vi.fn().mockReturnValue(false), + }; + vi.mocked(vscode.workspace.getConfiguration).mockReturnValue( + mockConfig as unknown as vscode.WorkspaceConfiguration, + ); + + logger.reset(); + mockConfig.get.mockClear(); + + // Trigger non-verbose config change + configChangeCallback({ + affectsConfiguration: (section: string) => section === "other.setting", + } as vscode.ConfigurationChangeEvent); + + // Should not re-read config + expect(mockConfig.get).not.toHaveBeenCalled(); + }); + }); + + describe("Adapter management", () => { + it("should throw when setAdapter called in non-test environment", () => { + const originalEnv = process.env.NODE_ENV; + process.env.NODE_ENV = "production"; + try { + expect(() => logger.setAdapter(new ArrayAdapter())).toThrow( + "setAdapter can only be called in test environment", + ); + } finally { + process.env.NODE_ENV = originalEnv; + } + }); + + it("should throw when reset called in non-test environment", () => { + const originalEnv = process.env.NODE_ENV; + process.env.NODE_ENV = "production"; + try { + expect(() => logger.reset()).toThrow( + "reset can only be called in test environment", + ); + } finally { + process.env.NODE_ENV = originalEnv; + } + }); + + it("should throw when adapter already set", () => { + logger.setAdapter(new ArrayAdapter()); + expect(() => logger.setAdapter(new ArrayAdapter())).toThrow( + "Adapter already set. Use reset() first or withAdapter() for temporary changes", + ); + }); + + it("should allow temporary adapter changes with withAdapter", () => { + const adapter1 = new ArrayAdapter(); + const adapter2 = new ArrayAdapter(); + + logger.setAdapter(adapter1); + logger.info("Message 1"); + + const result = logger.withAdapter(adapter2, () => { + logger.info("Message 2"); + return "test result"; + }); + + logger.info("Message 3"); + + expect(result).toBe("test result"); + expect(adapter1.getSnapshot()).toEqual( + expect.arrayContaining([ + expect.stringContaining("Message 1"), + expect.stringContaining("Message 3"), + ]), + ); + expect(adapter2.getSnapshot()).toEqual( + expect.arrayContaining([expect.stringContaining("Message 2")]), + ); + }); + + it("should restore adapter even if function throws", () => { + const adapter1 = new ArrayAdapter(); + const adapter2 = new ArrayAdapter(); + + logger.setAdapter(adapter1); + + expect(() => + logger.withAdapter(adapter2, () => { + throw new Error("Test error"); + }), + ).toThrow("Test error"); + + logger.info("After error"); + expect(adapter1.getSnapshot()).toEqual( + expect.arrayContaining([expect.stringContaining("After error")]), + ); + expect(adapter2.getSnapshot()).toHaveLength(0); + }); + + it("should dispose configuration listener on reset", () => { + const mockDisposable = { dispose: vi.fn() }; + vi.mocked(vscode.workspace.onDidChangeConfiguration).mockReturnValue( + mockDisposable as unknown as vscode.Disposable, + ); + + logger.reset(); + logger.reset(); // Second reset should dispose the first listener + + expect(mockDisposable.dispose).toHaveBeenCalled(); + }); + }); + + describe("Initialize", () => { + it("should initialize with OutputChannel", () => { + const mockChannel = { + appendLine: vi.fn(), + clear: vi.fn(), + } as unknown as vscode.OutputChannel; + + logger.initialize(mockChannel); + + // Verify we can log after initialization + logger.info("Test message"); + expect(mockChannel.appendLine).toHaveBeenCalled(); + }); + + it("should throw if already initialized", () => { + const mockChannel = {} as vscode.OutputChannel; + logger.initialize(mockChannel); + + expect(() => logger.initialize(mockChannel)).toThrow( + "Logger already initialized", + ); + }); + }); + + describe("Performance", () => { + it("should have minimal overhead for disabled debug calls", () => { + const noOpAdapter = new NoOpAdapter(); + const arrayAdapter = new ArrayAdapter(); + + // Measure NoOp baseline + logger.setAdapter(noOpAdapter); + logger.setLevel(LogLevel.INFO); // Debug disabled + + const noOpStart = performance.now(); + for (let i = 0; i < 10000; i++) { + logger.debug(`Debug message ${i}`); + } + const noOpTime = performance.now() - noOpStart; + + // Measure with ArrayAdapter + logger.reset(); + logger.setAdapter(arrayAdapter); + logger.setLevel(LogLevel.INFO); // Debug disabled + + const arrayStart = performance.now(); + for (let i = 0; i < 10000; i++) { + logger.debug(`Debug message ${i}`); + } + const arrayTime = performance.now() - arrayStart; + + // Should have less than 10% overhead when disabled + const overhead = (arrayTime - noOpTime) / noOpTime; + expect(overhead).toBeLessThan(0.1); + expect(arrayAdapter.getSnapshot()).toHaveLength(0); // No messages logged + }); + + it("should have acceptable overhead for enabled debug calls", () => { + const noOpAdapter = new NoOpAdapter(); + const arrayAdapter = new ArrayAdapter(); + + // Measure NoOp baseline + logger.setAdapter(noOpAdapter); + logger.setLevel(LogLevel.DEBUG); // Debug enabled + + const noOpStart = performance.now(); + for (let i = 0; i < 1000; i++) { + logger.debug(`Debug message ${i}`); + } + const noOpTime = performance.now() - noOpStart; + + // Measure with ArrayAdapter + logger.reset(); + logger.setAdapter(arrayAdapter); + logger.setLevel(LogLevel.DEBUG); // Debug enabled + + const arrayStart = performance.now(); + for (let i = 0; i < 1000; i++) { + logger.debug(`Debug message ${i}`); + } + const arrayTime = performance.now() - arrayStart; + + // Should have less than 10x overhead when enabled + const overhead = arrayTime / noOpTime; + expect(overhead).toBeLessThan(10); + expect(arrayAdapter.getSnapshot()).toHaveLength(1000); // All messages logged + }); + + it("should have acceptable overhead for info calls", () => { + const noOpAdapter = new NoOpAdapter(); + const arrayAdapter = new ArrayAdapter(); + + // Measure NoOp baseline + logger.setAdapter(noOpAdapter); + + const noOpStart = performance.now(); + for (let i = 0; i < 1000; i++) { + logger.info(`Info message ${i}`); + } + const noOpTime = performance.now() - noOpStart; + + // Measure with ArrayAdapter + logger.reset(); + logger.setAdapter(arrayAdapter); + + const arrayStart = performance.now(); + for (let i = 0; i < 1000; i++) { + logger.info(`Info message ${i}`); + } + const arrayTime = performance.now() - arrayStart; + + // Should have less than 5x overhead for info + const overhead = arrayTime / noOpTime; + expect(overhead).toBeLessThan(5); + expect(arrayAdapter.getSnapshot()).toHaveLength(1000); // All messages logged + }); + }); +}); diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 00000000..a1b8757d --- /dev/null +++ b/src/logger.ts @@ -0,0 +1,198 @@ +import * as vscode from "vscode"; + +export enum LogLevel { + DEBUG = 0, + INFO = 1, + NONE = 2, +} + +export interface LogAdapter { + write(message: string): void; + clear(): void; +} + +export class OutputChannelAdapter implements LogAdapter { + constructor(private outputChannel: vscode.OutputChannel) {} + + write(message: string): void { + try { + this.outputChannel.appendLine(message); + } catch { + // Silently ignore - channel may be disposed + } + } + + clear(): void { + try { + this.outputChannel.clear(); + } catch { + // Silently ignore - channel may be disposed + } + } +} + +export class ArrayAdapter implements LogAdapter { + private logs: string[] = []; + + write(message: string): void { + this.logs.push(message); + } + + clear(): void { + this.logs = []; + } + + getSnapshot(): readonly string[] { + return [...this.logs]; + } +} + +export class NoOpAdapter implements LogAdapter { + // eslint-disable-next-line @typescript-eslint/no-unused-vars + write(_message: string): void { + // Intentionally empty - baseline for performance tests + } + + clear(): void { + // Intentionally empty - baseline for performance tests + } +} + +class LoggerImpl { + private adapter: LogAdapter | null = null; + private level: LogLevel = LogLevel.INFO; + private configListener: vscode.Disposable | null = null; + + constructor() { + this.updateLogLevel(); + this.setupConfigListener(); + } + + private setupConfigListener(): void { + // In test environment, vscode.workspace might not be available + if (!vscode.workspace?.onDidChangeConfiguration) { + return; + } + this.configListener = vscode.workspace.onDidChangeConfiguration((e) => { + if (e.affectsConfiguration("coder.verbose")) { + this.updateLogLevel(); + } + }); + } + + private updateLogLevel(): void { + // In test environment, vscode.workspace might not be available + if (!vscode.workspace?.getConfiguration) { + this.level = LogLevel.INFO; + return; + } + const config = vscode.workspace.getConfiguration("coder"); + const verbose = config.get("verbose", false); + this.level = verbose ? LogLevel.DEBUG : LogLevel.INFO; + } + + private formatMessage(message: string, level: LogLevel): string { + const levelStr = LogLevel[level].toLowerCase(); + const timestamp = new Date().toISOString(); + let formatted = `[${levelStr}] ${timestamp} ${message}`; + + // Add source location for debug messages when verbose is enabled + if (level === LogLevel.DEBUG && this.level === LogLevel.DEBUG) { + const stack = new Error().stack; + if (stack) { + const lines = stack.split("\n"); + // Find the first line that's not from the logger itself + for (let i = 2; i < lines.length; i++) { + const line = lines[i]; + if (!line.includes("logger.ts") && !line.includes("Logger.")) { + const match = + line.match(/at\s+(.+)\s+\((.+):(\d+):(\d+)\)/) || + line.match(/at\s+(.+):(\d+):(\d+)/); + if (match) { + const location = + match.length === 5 + ? `${match[1]} (${match[2]}:${match[3]})` + : `${match[1]}:${match[2]}`; + formatted += `\n at ${location}`; + } + break; + } + } + } + } + + return formatted; + } + + log(message: string, severity: LogLevel = LogLevel.INFO): void { + if (!this.adapter || severity < this.level) { + return; + } + + const formatted = this.formatMessage(message, severity); + this.adapter.write(formatted); + } + + debug(message: string): void { + this.log(message, LogLevel.DEBUG); + } + + info(message: string): void { + this.log(message, LogLevel.INFO); + } + + setLevel(level: LogLevel): void { + this.level = level; + } + + setAdapter(adapter: LogAdapter): void { + if (process.env.NODE_ENV !== "test") { + throw new Error("setAdapter can only be called in test environment"); + } + if (this.adapter !== null) { + throw new Error( + "Adapter already set. Use reset() first or withAdapter() for temporary changes", + ); + } + this.adapter = adapter; + } + + withAdapter(adapter: LogAdapter, fn: () => T): T { + const previous = this.adapter; + this.adapter = adapter; + try { + return fn(); + } finally { + this.adapter = previous; + } + } + + reset(): void { + if (process.env.NODE_ENV !== "test") { + throw new Error("reset can only be called in test environment"); + } + this.adapter = null; + this.level = LogLevel.INFO; + if (this.configListener) { + this.configListener.dispose(); + this.configListener = null; + } + // Re-setup config listener for next test + this.updateLogLevel(); + this.setupConfigListener(); + } + + // Initialize with OutputChannel for production use + initialize(outputChannel: vscode.OutputChannel): void { + if (this.adapter !== null) { + throw new Error("Logger already initialized"); + } + this.adapter = new OutputChannelAdapter(outputChannel); + } +} + +// Export singleton instance +export const logger = new LoggerImpl(); + +// Export types for testing +export type Logger = typeof logger; diff --git a/src/remote.ts b/src/remote.ts index 4a13ae56..6caebdcf 100644 --- a/src/remote.ts +++ b/src/remote.ts @@ -22,6 +22,7 @@ import { Commands } from "./commands"; import { featureSetForVersion, FeatureSet } from "./featureSet"; import { getHeaderArgs } from "./headers"; import { Inbox } from "./inbox"; +import { logger } from "./logger"; import { SSHConfig, SSHValues, mergeSSHConfigValues } from "./sshConfig"; import { computeSSHProperties, sshSupportsSetEnv } from "./sshSupport"; import { Storage } from "./storage"; @@ -117,9 +118,7 @@ export class Remote { case "starting": case "stopping": writeEmitter = initWriteEmitterAndTerminal(); - this.storage.writeToCoderOutputChannel( - `Waiting for ${workspaceName}...`, - ); + logger.info(`Waiting for ${workspaceName}...`); workspace = await waitForBuild( restClient, writeEmitter, @@ -131,9 +130,7 @@ export class Remote { return undefined; } writeEmitter = initWriteEmitterAndTerminal(); - this.storage.writeToCoderOutputChannel( - `Starting ${workspaceName}...`, - ); + logger.info(`Starting ${workspaceName}...`); workspace = await startWorkspaceIfStoppedOrFailed( restClient, globalConfigDir, @@ -150,9 +147,7 @@ export class Remote { return undefined; } writeEmitter = initWriteEmitterAndTerminal(); - this.storage.writeToCoderOutputChannel( - `Starting ${workspaceName}...`, - ); + logger.info(`Starting ${workspaceName}...`); workspace = await startWorkspaceIfStoppedOrFailed( restClient, globalConfigDir, @@ -175,7 +170,7 @@ export class Remote { ); } } - this.storage.writeToCoderOutputChannel( + logger.info( `${workspaceName} status is now ${workspace.latest_build.status}`, ); } @@ -243,12 +238,8 @@ export class Remote { return; } - this.storage.writeToCoderOutputChannel( - `Using deployment URL: ${baseUrlRaw}`, - ); - this.storage.writeToCoderOutputChannel( - `Using deployment label: ${parts.label || "n/a"}`, - ); + logger.info(`Using deployment URL: ${baseUrlRaw}`); + logger.info(`Using deployment label: ${parts.label || "n/a"}`); // We could use the plugin client, but it is possible for the user to log // out or log into a different deployment while still connected, which would @@ -314,14 +305,12 @@ export class Remote { // Next is to find the workspace from the URI scheme provided. let workspace: Workspace; try { - this.storage.writeToCoderOutputChannel( - `Looking for workspace ${workspaceName}...`, - ); + logger.info(`Looking for workspace ${workspaceName}...`); workspace = await workspaceRestClient.getWorkspaceByOwnerAndName( parts.username, parts.workspace, ); - this.storage.writeToCoderOutputChannel( + logger.info( `Found workspace ${workspaceName} with status ${workspace.latest_build.status}`, ); this.commands.workspace = workspace; @@ -404,9 +393,7 @@ export class Remote { this.commands.workspace = workspace; // Pick an agent. - this.storage.writeToCoderOutputChannel( - `Finding agent for ${workspaceName}...`, - ); + logger.info(`Finding agent for ${workspaceName}...`); const gotAgent = await this.commands.maybeAskAgent(workspace, parts.agent); if (!gotAgent) { // User declined to pick an agent. @@ -414,12 +401,10 @@ export class Remote { return; } let agent = gotAgent; // Reassign so it cannot be undefined in callbacks. - this.storage.writeToCoderOutputChannel( - `Found agent ${agent.name} with status ${agent.status}`, - ); + logger.info(`Found agent ${agent.name} with status ${agent.status}`); // Do some janky setting manipulation. - this.storage.writeToCoderOutputChannel("Modifying settings..."); + logger.info("Modifying settings..."); const remotePlatforms = this.vscodeProposed.workspace .getConfiguration() .get>("remote.SSH.remotePlatform", {}); @@ -491,9 +476,7 @@ export class Remote { // write here is not necessarily catastrophic since the user will be // asked for the platform and the default timeout might be sufficient. mungedPlatforms = mungedConnTimeout = false; - this.storage.writeToCoderOutputChannel( - `Failed to configure settings: ${ex}`, - ); + logger.info(`Failed to configure settings: ${ex}`); } } @@ -521,9 +504,7 @@ export class Remote { // Wait for the agent to connect. if (agent.status === "connecting") { - this.storage.writeToCoderOutputChannel( - `Waiting for ${workspaceName}/${agent.name}...`, - ); + logger.info(`Waiting for ${workspaceName}/${agent.name}...`); await vscode.window.withProgress( { title: "Waiting for the agent to connect...", @@ -552,9 +533,7 @@ export class Remote { }); }, ); - this.storage.writeToCoderOutputChannel( - `Agent ${agent.name} status is now ${agent.status}`, - ); + logger.info(`Agent ${agent.name} status is now ${agent.status}`); } // Make sure the agent is connected. @@ -584,7 +563,7 @@ export class Remote { // If we didn't write to the SSH config file, connecting would fail with // "Host not found". try { - this.storage.writeToCoderOutputChannel("Updating SSH config..."); + logger.info("Updating SSH config..."); await this.updateSSHConfig( workspaceRestClient, parts.label, @@ -594,9 +573,7 @@ export class Remote { featureSet, ); } catch (error) { - this.storage.writeToCoderOutputChannel( - `Failed to configure SSH: ${error}`, - ); + logger.info(`Failed to configure SSH: ${error}`); throw error; } @@ -633,7 +610,7 @@ export class Remote { }), ); - this.storage.writeToCoderOutputChannel("Remote setup complete"); + logger.info("Remote setup complete"); // Returning the URL and token allows the plugin to authenticate its own // client, for example to display the list of workspaces belonging to this @@ -674,9 +651,7 @@ export class Remote { return ""; } await fs.mkdir(logDir, { recursive: true }); - this.storage.writeToCoderOutputChannel( - `SSH proxy diagnostics are being written to ${logDir}`, - ); + logger.info(`SSH proxy diagnostics are being written to ${logDir}`); return ` --log-dir ${escapeCommandArg(logDir)}`; } diff --git a/src/storage.ts b/src/storage.ts index 8453bc5d..8c981169 100644 --- a/src/storage.ts +++ b/src/storage.ts @@ -8,6 +8,7 @@ import * as vscode from "vscode"; import { errToStr } from "./api-helper"; import * as cli from "./cliManager"; import { getHeaderCommand, getHeaders } from "./headers"; +import { logger } from "./logger"; // Maximium number of recent URLs to store. const MAX_URLS = 10; @@ -507,12 +508,12 @@ export class Storage { : path.join(this.globalStorageUri.fsPath, "url"); } - public writeToCoderOutputChannel(message: string) { - this.output.appendLine(`[${new Date().toISOString()}] ${message}`); - // We don't want to focus on the output here, because the - // Coder server is designed to restart gracefully for users - // because of P2P connections, and we don't want to draw - // attention to it. + /** + * Compatibility method for Logger interface used by headers.ts and error.ts. + * Delegates to the logger module. + */ + public writeToCoderOutputChannel(message: string): void { + logger.info(message); } /** @@ -614,7 +615,6 @@ export class Storage { return getHeaders( url, getHeaderCommand(vscode.workspace.getConfiguration()), - this, ); } } diff --git a/src/workspaceMonitor.ts b/src/workspaceMonitor.ts index 18df50b2..23138035 100644 --- a/src/workspaceMonitor.ts +++ b/src/workspaceMonitor.ts @@ -5,6 +5,7 @@ import { EventSource } from "eventsource"; import * as vscode from "vscode"; import { createStreamingFetchAdapter } from "./api"; import { errToStr } from "./api-helper"; +import { logger } from "./logger"; import { Storage } from "./storage"; /** @@ -42,7 +43,7 @@ export class WorkspaceMonitor implements vscode.Disposable { this.name = `${workspace.owner_name}/${workspace.name}`; const url = this.restClient.getAxiosInstance().defaults.baseURL; const watchUrl = new URL(`${url}/api/v2/workspaces/${workspace.id}/watch`); - this.storage.writeToCoderOutputChannel(`Monitoring ${this.name}...`); + logger.info(`Monitoring ${this.name}...`); const eventSource = new EventSource(watchUrl.toString(), { fetch: createStreamingFetchAdapter(this.restClient.getAxiosInstance()), @@ -85,7 +86,7 @@ export class WorkspaceMonitor implements vscode.Disposable { */ dispose() { if (!this.disposed) { - this.storage.writeToCoderOutputChannel(`Unmonitoring ${this.name}...`); + logger.info(`Unmonitoring ${this.name}...`); this.statusBarItem.dispose(); this.eventSource.close(); this.disposed = true; @@ -202,7 +203,7 @@ export class WorkspaceMonitor implements vscode.Disposable { error, "Got empty error while monitoring workspace", ); - this.storage.writeToCoderOutputChannel(message); + logger.info(message); } private updateContext(workspace: Workspace) { diff --git a/src/workspacesProvider.ts b/src/workspacesProvider.ts index a77b31ad..08eb64ad 100644 --- a/src/workspacesProvider.ts +++ b/src/workspacesProvider.ts @@ -15,6 +15,7 @@ import { extractAgents, errToStr, } from "./api-helper"; +import { logger } from "./logger"; import { Storage } from "./storage"; export enum WorkspaceQuery { @@ -96,7 +97,7 @@ export class WorkspaceProvider */ private async fetch(): Promise { if (vscode.env.logLevel <= vscode.LogLevel.Debug) { - this.storage.writeToCoderOutputChannel( + logger.info( `Fetching workspaces: ${this.getWorkspacesQuery || "no filter"}...`, ); } diff --git a/vitest.config.ts b/vitest.config.ts index 2007fb45..11fbfa44 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -13,5 +13,8 @@ export default defineConfig({ "./src/test/**", ], environment: "node", + env: { + NODE_ENV: "test", + }, }, });