diff --git a/package.json b/package.json index 3a4c4d1a..38360ae4 100644 --- a/package.json +++ b/package.json @@ -4,7 +4,7 @@ "displayName": "Coder", "description": "Open any workspace with a single click.", "repository": "https://github.com/coder/vscode-coder", - "version": "1.7.0", + "version": "1.7.0-debug.1", "engines": { "vscode": "^1.73.0" }, diff --git a/src/extension.ts b/src/extension.ts index 0c04bf18..f5b31431 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -7,12 +7,27 @@ import { makeCoderSdk, needToken } from "./api" import { errToStr } from "./api-helper" import { Commands } from "./commands" import { CertificateError, getErrorDetail } from "./error" +import { getMemoryLogger } from "./memoryLogger" import { Remote } from "./remote" import { Storage } from "./storage" import { toSafeHost } from "./util" import { WorkspaceQuery, WorkspaceProvider } from "./workspacesProvider" export async function activate(ctx: vscode.ExtensionContext): Promise { + // Initialize the memory logger right when the extension starts. + const logger = getMemoryLogger() + await logger.initLogFile(ctx.globalStorageUri.fsPath) + + // Log initial memory usage and activation + logger.info("CODER extension activating") + logger.logMemoryUsage("EXTENSION_ACTIVATE") + + // Register disposal of the logger when the extension deactivates + ctx.subscriptions.push({ dispose: () => logger.dispose() }) + + // Log extension mode + logger.info(`Extension mode: ${extensionModeToString(ctx.extensionMode)}`) + // The Remote SSH extension's proposed APIs are used to override the SSH host // name in VS Code itself. It's visually unappealing having a lengthy name! // @@ -25,9 +40,13 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { vscode.extensions.getExtension("codeium.windsurf-remote-openssh") || vscode.extensions.getExtension("ms-vscode-remote.remote-ssh") if (!remoteSSHExtension) { + logger.error("Remote SSH extension not found, cannot activate Coder extension") vscode.window.showErrorMessage("Remote SSH extension not found, cannot activate Coder extension") throw new Error("Remote SSH extension not found") } + + logger.info(`Found Remote SSH extension: ${remoteSSHExtension.id}`) + // eslint-disable-next-line @typescript-eslint/no-explicit-any const vscodeProposed: typeof vscode = (module as any)._load( "vscode", @@ -281,4 +300,25 @@ export async function activate(ctx: vscode.ExtensionContext): Promise { } } } + + logger.info("Coder extension activation complete") +} + +function extensionModeToString(mode: vscode.ExtensionMode): string { + switch (mode) { + case vscode.ExtensionMode.Development: + return "Development" + case vscode.ExtensionMode.Production: + return "Production" + case vscode.ExtensionMode.Test: + return "Test" + default: + return `Unknown (${mode})` + } +} + +export function deactivate(): void { + const logger = getMemoryLogger() + logger.info("Coder extension deactivating") + logger.logMemoryUsage("EXTENSION_DEACTIVATE") } diff --git a/src/inbox.ts b/src/inbox.ts index f682273e..8e9f3047 100644 --- a/src/inbox.ts +++ b/src/inbox.ts @@ -5,6 +5,7 @@ import * as vscode from "vscode" import { WebSocket } from "ws" import { coderSessionTokenHeader } from "./api" import { errToStr } from "./api-helper" +import { getMemoryLogger } from "./memoryLogger" import { type Storage } from "./storage" // These are the template IDs of our notifications. @@ -17,9 +18,17 @@ export class Inbox implements vscode.Disposable { readonly #storage: Storage #disposed = false #socket: WebSocket + #messageCount = 0 + #workspaceId: string + #memoryInterval: NodeJS.Timeout constructor(workspace: Workspace, httpAgent: ProxyAgent, restClient: Api, storage: Storage) { + const logger = getMemoryLogger() this.#storage = storage + this.#workspaceId = workspace.id + + logger.trackResourceCreated("InboxWebSocket", workspace.id) + logger.info(`Creating inbox for workspace: ${workspace.owner_name}/${workspace.name} (${workspace.id})`) const baseUrlRaw = restClient.getAxiosInstance().defaults.baseURL if (!baseUrlRaw) { @@ -38,6 +47,8 @@ export class Inbox implements vscode.Disposable { const socketProto = baseUrl.protocol === "https:" ? "wss:" : "ws:" const socketUrl = `${socketProto}//${baseUrl.host}/api/v2/notifications/inbox/watch?format=plaintext&templates=${watchTemplatesParam}&targets=${watchTargetsParam}` + logger.debug(`Connecting to inbox WebSocket at: ${socketUrl}`) + const token = restClient.getAxiosInstance().defaults.headers.common[coderSessionTokenHeader] as string | undefined this.#socket = new WebSocket(new URL(socketUrl), { agent: httpAgent, @@ -50,35 +61,74 @@ export class Inbox implements vscode.Disposable { }) this.#socket.on("open", () => { + logger.info(`Inbox WebSocket connection opened for workspace: ${workspace.id}`) this.#storage.writeToCoderOutputChannel("Listening to Coder Inbox") }) this.#socket.on("error", (error) => { + logger.error(`Inbox WebSocket error for workspace: ${workspace.id}`, error) this.notifyError(error) this.dispose() }) + this.#socket.on("close", (code, reason) => { + logger.info(`Inbox WebSocket closed for workspace: ${workspace.id}, code: ${code}, reason: ${reason || "none"}`) + if (!this.#disposed) { + this.dispose() + } + }) + this.#socket.on("message", (data) => { + this.#messageCount++ + + // Log periodic message stats + if (this.#messageCount % 10 === 0) { + logger.info(`Inbox received ${this.#messageCount} messages for workspace: ${workspace.id}`) + logger.logMemoryUsage("INBOX_WEBSOCKET") + } + try { const inboxMessage = JSON.parse(data.toString()) as GetInboxNotificationResponse - + logger.debug(`Inbox notification received: ${inboxMessage.notification.title}`) vscode.window.showInformationMessage(inboxMessage.notification.title) } catch (error) { + logger.error(`Error processing inbox message for workspace: ${workspace.id}`, error) this.notifyError(error) } }) + + // Log memory stats periodically + this.#memoryInterval = setInterval( + () => { + if (!this.#disposed) { + logger.logMemoryUsage("INBOX_PERIODIC") + } else { + clearInterval(this.#memoryInterval) + } + }, + 5 * 60 * 1000, + ) // Every 5 minutes } dispose() { + const logger = getMemoryLogger() + if (!this.#disposed) { + logger.info(`Disposing inbox for workspace: ${this.#workspaceId} after ${this.#messageCount} messages`) this.#storage.writeToCoderOutputChannel("No longer listening to Coder Inbox") this.#socket.close() this.#disposed = true + logger.trackResourceDisposed("InboxWebSocket", this.#workspaceId) } + + clearInterval(this.#memoryInterval) } private notifyError(error: unknown) { + const logger = getMemoryLogger() const message = errToStr(error, "Got empty error while monitoring Coder Inbox") + + logger.error(`Inbox error for workspace: ${this.#workspaceId}`, error) this.#storage.writeToCoderOutputChannel(message) } } diff --git a/src/memoryLogger.ts b/src/memoryLogger.ts new file mode 100644 index 00000000..9af9e43d --- /dev/null +++ b/src/memoryLogger.ts @@ -0,0 +1,217 @@ +import * as fs from "fs/promises" +import * as os from "os" +import * as path from "path" +import * as vscode from "vscode" + +/** + * A class for tracking memory usage and logging resource lifecycles + * to help identify memory leaks in the extension. + */ +export class MemoryLogger { + private outputChannel: vscode.OutputChannel + private logFile: string | undefined + private resourceCounts = new Map() + private startTime = Date.now() + private logInterval: NodeJS.Timeout | undefined + private disposed = false + + constructor() { + this.outputChannel = vscode.window.createOutputChannel("Coder Memory Logging") + this.outputChannel.show() + + // Setup periodic logging of memory usage + this.startPeriodicLogging() + } + + /** + * Start logging memory usage periodically + */ + private startPeriodicLogging(intervalMs = 60000) { + if (this.logInterval) { + clearInterval(this.logInterval) + } + + this.logInterval = setInterval(() => { + if (this.disposed) { + return + } + this.logMemoryUsage("PERIODIC") + this.logResourceCounts() + }, intervalMs) + } + + /** + * Initialize the log file for persistent logging + */ + public async initLogFile(globalStoragePath: string): Promise { + try { + const logDir = path.join(globalStoragePath, "logs") + await fs.mkdir(logDir, { recursive: true }) + + this.logFile = path.join(logDir, `memory-log-${new Date().toISOString().replace(/[:.]/g, "-")}.txt`) + + await this.writeToLogFile("Memory logging initialized") + this.info("Memory logging initialized to file: " + this.logFile) + + // Log initial memory state + this.logMemoryUsage("INIT") + } catch (err) { + this.error(`Failed to initialize log file: ${err}`) + } + } + + /** + * Log a new resource creation + */ + public trackResourceCreated(resourceType: string, id: string = ""): void { + const count = (this.resourceCounts.get(resourceType) || 0) + 1 + this.resourceCounts.set(resourceType, count) + this.info(`RESOURCE_CREATED: ${resourceType}${id ? ":" + id : ""} (Total: ${count})`) + } + + /** + * Log a resource disposal + */ + public trackResourceDisposed(resourceType: string, id: string = ""): void { + const count = Math.max(0, (this.resourceCounts.get(resourceType) || 1) - 1) + if (count === 0) { + this.resourceCounts.delete(resourceType) + } else { + this.resourceCounts.set(resourceType, count) + } + + this.info(`RESOURCE_DISPOSED: ${resourceType}${id ? ":" + id : ""} (Remaining: ${count})`) + } + + /** + * Log error with memory usage + */ + public error(message: string, error?: unknown): void { + const errorMsg = error ? `: ${error instanceof Error ? error.stack || error.message : String(error)}` : "" + const fullMessage = `[ERROR] ${message}${errorMsg}` + + this.outputChannel.appendLine(fullMessage) + this.writeToLogFile(fullMessage) + this.logMemoryUsage("ERROR") + } + + /** + * Log info with timestamp + */ + public info(message: string): void { + const fullMessage = `[INFO] ${message}` + this.outputChannel.appendLine(fullMessage) + this.writeToLogFile(fullMessage) + } + + /** + * Log debug info (only to file) + */ + public debug(message: string): void { + const fullMessage = `[DEBUG] ${message}` + this.writeToLogFile(fullMessage) + } + + /** + * Log current memory usage + */ + public logMemoryUsage(context: string): void { + try { + const memoryUsage = process.memoryUsage() + const nodeMemoryInfo = { + rss: `${(memoryUsage.rss / 1024 / 1024).toFixed(2)}MB`, + heapTotal: `${(memoryUsage.heapTotal / 1024 / 1024).toFixed(2)}MB`, + heapUsed: `${(memoryUsage.heapUsed / 1024 / 1024).toFixed(2)}MB`, + external: `${(memoryUsage.external / 1024 / 1024).toFixed(2)}MB`, + uptime: formatDuration(process.uptime() * 1000), + totalUptime: formatDuration(Date.now() - this.startTime), + } + + const systemMemoryInfo = { + totalMem: `${(os.totalmem() / 1024 / 1024 / 1024).toFixed(2)}GB`, + freeMem: `${(os.freemem() / 1024 / 1024 / 1024).toFixed(2)}GB`, + } + + const memoryLog = `[MEMORY:${context}] Node: ${JSON.stringify(nodeMemoryInfo)} | System: ${JSON.stringify(systemMemoryInfo)}` + this.outputChannel.appendLine(memoryLog) + this.writeToLogFile(memoryLog) + } catch (err) { + this.outputChannel.appendLine(`[ERROR] Failed to log memory usage: ${err}`) + } + } + + /** + * Log the current counts of active resources + */ + private logResourceCounts(): void { + const counts = Array.from(this.resourceCounts.entries()) + .map(([type, count]) => `${type}=${count}`) + .join(", ") + + const message = `[RESOURCES] Active resources: ${counts || "none"}` + this.outputChannel.appendLine(message) + this.writeToLogFile(message) + } + + /** + * Write to log file + */ + private async writeToLogFile(message: string): Promise { + if (!this.logFile) { + return + } + + try { + const timestamp = new Date().toISOString() + await fs.appendFile(this.logFile, `${timestamp} ${message}\n`) + } catch (err) { + // Don't recursively call this.error to avoid potential loops + this.outputChannel.appendLine(`[ERROR] Failed to write to log file: ${err}`) + } + } + + /** + * Show the log in the output channel + */ + public show(): void { + this.outputChannel.show() + } + + /** + * Dispose of the logger + */ + public dispose(): void { + this.disposed = true + if (this.logInterval) { + clearInterval(this.logInterval) + this.logInterval = undefined + } + this.logMemoryUsage("DISPOSE") + this.outputChannel.dispose() + } +} + +/** + * Format duration in milliseconds to a human-readable string + */ +function formatDuration(ms: number): string { + const seconds = Math.floor((ms / 1000) % 60) + const minutes = Math.floor((ms / (1000 * 60)) % 60) + const hours = Math.floor((ms / (1000 * 60 * 60)) % 24) + const days = Math.floor(ms / (1000 * 60 * 60 * 24)) + + return `${days}d ${hours}h ${minutes}m ${seconds}s` +} + +// Singleton instance +let instance: MemoryLogger | undefined + +/** + * Get or initialize the memory logger instance + */ +export function getMemoryLogger(): MemoryLogger { + if (!instance) { + instance = new MemoryLogger() + } + return instance +} diff --git a/src/remote.ts b/src/remote.ts index 5b8a9694..9f40188e 100644 --- a/src/remote.ts +++ b/src/remote.ts @@ -16,6 +16,7 @@ import { Commands } from "./commands" import { featureSetForVersion, FeatureSet } from "./featureSet" import { getHeaderCommand } from "./headers" import { Inbox } from "./inbox" +import { getMemoryLogger } from "./memoryLogger" import { SSHConfig, SSHValues, mergeSSHConfigValues } from "./sshConfig" import { computeSSHProperties, sshSupportsSetEnv } from "./sshSupport" import { Storage } from "./storage" @@ -688,9 +689,20 @@ export class Remote { // showNetworkUpdates finds the SSH process ID that is being used by this // workspace and reads the file being created by the Coder CLI. private showNetworkUpdates(sshPid: number): vscode.Disposable { + const logger = getMemoryLogger() + logger.trackResourceCreated("NetworkStatusBar") + logger.info(`Starting network updates monitor for SSH PID: ${sshPid}`) + const networkStatus = vscode.window.createStatusBarItem(vscode.StatusBarAlignment.Left, 1000) + networkStatus.name = "Coder Workspace Update" const networkInfoFile = path.join(this.storage.getNetworkInfoPath(), `${sshPid}.json`) + logger.debug(`Network info file path: ${networkInfoFile}`) + + let refreshCount = 0 + let disposed = false + let lastFileSize = 0 + const updateStatus = (network: { p2p: boolean latency: number @@ -719,10 +731,11 @@ export class Remote { }) + "/s\n" - if (!network.p2p) { - const derpLatency = network.derp_latency[network.preferred_derp] - - networkStatus.tooltip += `You ↔ ${derpLatency.toFixed(2)}ms ↔ ${network.preferred_derp} ↔ ${(network.latency - derpLatency).toFixed(2)}ms ↔ Workspace` + const derpLatency = network.derp_latency[network.preferred_derp] || undefined + if (!network.p2p && derpLatency !== undefined) { + networkStatus.tooltip += `You ↔ ${derpLatency.toFixed(2)}ms ↔ ${network.preferred_derp} ↔ ${( + network.latency - derpLatency + ).toFixed(2)}ms ↔ Workspace` let first = true Object.keys(network.derp_latency).forEach((region) => { @@ -735,42 +748,71 @@ export class Remote { } networkStatus.tooltip += `\n${region}: ${Math.round(network.derp_latency[region] * 100) / 100}ms` }) + } else { + logger.error("Network P2P is false and DERP Latency is undefined") } statusText += "(" + network.latency.toFixed(2) + "ms)" networkStatus.text = statusText networkStatus.show() + + // Log occasional network stats updates (every 20 refreshes) + if (refreshCount % 20 === 0) { + logger.debug( + `Network stats update #${refreshCount}: p2p=${network.p2p}, latency=${network.latency.toFixed(2)}ms`, + ) + } } - let disposed = false + const periodicRefresh = () => { if (disposed) { + logger.debug("Network updates: Skipping refresh as disposed=true") return } + + refreshCount++ + + // Log every 100 refreshes to track long-term operation + if (refreshCount % 100 === 0) { + logger.info(`Network updates: Completed ${refreshCount} refresh cycles for SSH PID: ${sshPid}`) + logger.logMemoryUsage("NETWORK_REFRESH") + } + fs.readFile(networkInfoFile, "utf8") .then((content) => { + const currentSize = content.length + if (lastFileSize !== currentSize) { + logger.debug(`Network info file size changed: ${lastFileSize} -> ${currentSize} bytes`) + lastFileSize = currentSize + } return JSON.parse(content) }) .then((parsed) => { - try { - updateStatus(parsed) - } catch (ex) { - // Ignore - } + updateStatus(parsed) }) - .catch(() => { - // TODO: Log a failure here! + .catch((error) => { + logger.error(`Failed to read or parse network info file: ${networkInfoFile}`, error) }) .finally(() => { // This matches the write interval of `coder vscodessh`. - setTimeout(periodicRefresh, 3000) + if (!disposed) { + setTimeout(periodicRefresh, 3000) + } }) } + + // Log the first refresh + logger.debug(`Starting initial network refresh for SSH PID: ${sshPid}`) periodicRefresh() return { dispose: () => { - disposed = true - networkStatus.dispose() + if (!disposed) { + logger.info(`Disposing network updates monitor for SSH PID: ${sshPid} after ${refreshCount} refreshes`) + disposed = true + networkStatus.dispose() + logger.trackResourceDisposed("NetworkStatusBar") + } }, } } @@ -778,46 +820,100 @@ export class Remote { // findSSHProcessID returns the currently active SSH process ID that is // powering the remote SSH connection. private async findSSHProcessID(timeout = 15000): Promise { + const logger = getMemoryLogger() + logger.info(`Starting SSH process ID search with timeout: ${timeout}ms`) + + let loopAttempts = 0 + let lastFilePath: string | undefined + const search = async (logPath: string): Promise => { - // This searches for the socksPort that Remote SSH is connecting to. We do - // this to find the SSH process that is powering this connection. That SSH - // process will be logging network information periodically to a file. - const text = await fs.readFile(logPath, "utf8") - const matches = text.match(/-> socksPort (\d+) ->/) - if (!matches) { - return - } - if (matches.length < 2) { - return - } - const port = Number.parseInt(matches[1]) - if (!port) { - return - } - const processes = await find("port", port) - if (processes.length < 1) { - return + try { + // This searches for the socksPort that Remote SSH is connecting to. We do + // this to find the SSH process that is powering this connection. That SSH + // process will be logging network information periodically to a file. + const text = await fs.readFile(logPath, "utf8") + + if (loopAttempts % 5 === 0) { + logger.debug(`SSH log file size: ${text.length} bytes`) + } + + const matches = text.match(/-> socksPort (\d+) ->/) + if (!matches) { + return + } + if (matches.length < 2) { + return + } + const port = Number.parseInt(matches[1], 10) + if (!port) { + return + } + + logger.info(`Found SSH socks port: ${port}, searching for process`) + const processes = await find("port", port) + + if (processes.length < 1) { + logger.debug(`No processes found using port: ${port}`) + return + } + + const process = processes[0] + logger.info(`Found SSH process: PID=${process.pid}, CMD=${process.cmd}`) + return process.pid + } catch (error) { + logger.error(`Error searching for SSH process in log: ${logPath}`, error) + return undefined } - const process = processes[0] - return process.pid } + const start = Date.now() + const loop = async (): Promise => { - if (Date.now() - start > timeout) { + loopAttempts++ + + const elapsed = Date.now() - start + if (elapsed > timeout) { + logger.info(`SSH process ID search timed out after ${loopAttempts} attempts, elapsed: ${elapsed}ms`) return undefined } + + // Log progress periodically + if (loopAttempts % 5 === 0) { + logger.info(`SSH process ID search attempt #${loopAttempts}, elapsed: ${elapsed}ms`) + logger.logMemoryUsage("SSH_PROCESS_SEARCH") + } + // Loop until we find the remote SSH log for this window. const filePath = await this.storage.getRemoteSSHLogPath() + if (!filePath) { - return new Promise((resolve) => setTimeout(() => resolve(loop()), 500)) + if (lastFilePath !== filePath) { + lastFilePath = filePath + logger.debug(`SSH log file not found, will retry`) + } + + return new Promise((resolve) => { + setTimeout(() => resolve(loop()), 500) + }) + } + + if (lastFilePath !== filePath) { + lastFilePath = filePath + logger.info(`Found SSH log file: ${filePath}`) } + // Then we search the remote SSH log until we find the port. const result = await search(filePath) if (!result) { - return new Promise((resolve) => setTimeout(() => resolve(loop()), 500)) + return new Promise((resolve) => { + setTimeout(() => resolve(loop()), 500) + }) } + + logger.info(`SSH process ID search completed successfully after ${loopAttempts} attempts, elapsed: ${elapsed}ms`) return result } + return loop() } diff --git a/src/workspacesProvider.ts b/src/workspacesProvider.ts index 0709487e..178cf999 100644 --- a/src/workspacesProvider.ts +++ b/src/workspacesProvider.ts @@ -11,6 +11,7 @@ import { extractAgents, errToStr, } from "./api-helper" +import { getMemoryLogger } from "./memoryLogger" import { Storage } from "./storage" export enum WorkspaceQuery { @@ -56,10 +57,21 @@ export class WorkspaceProvider implements vscode.TreeDataProvider { + logger.debug(`WorkspaceProvider(${this.getWorkspacesQuery}): Executing scheduled refresh`) this.fetchAndRefresh() }, this.timerSeconds * 1000) } } - private _onDidChangeTreeData: vscode.EventEmitter = new vscode.EventEmitter() readonly onDidChangeTreeData: vscode.Event = @@ -193,9 +224,33 @@ export class WorkspaceProvider implements vscode.TreeDataProvider { + logger.debug(`WorkspaceProvider(${this.getWorkspacesQuery}): Disposing agent watcher ${id}`) + this.agentWatchers[id].dispose() + }) + + this.agentWatchers = {} + this.workspaces = undefined + + logger.logMemoryUsage("WORKSPACE_PROVIDER_DISPOSE") + } + async getTreeItem(element: vscode.TreeItem): Promise { return element } @@ -227,41 +282,80 @@ export class WorkspaceProvider implements vscode.TreeDataProvider() const watcher: AgentWatcher = { onChange: onChange.event, dispose: () => { if (!disposed) { + logger.info(`Disposing metadata watcher for agent: ${agentId} after ${eventCount} events`) eventSource.close() + onChange.dispose() disposed = true + logger.trackResourceDisposed("AgentMetadataWatcher", agentId) } }, } + eventSource.addEventListener("open", () => { + logger.info(`Metadata EventSource connection opened for agent: ${agentId}`) + }) + eventSource.addEventListener("data", (event) => { + eventCount++ + + // Log periodic updates + if (eventCount % 50 === 0) { + logger.info(`Received ${eventCount} metadata events for agent: ${agentId}`) + logger.logMemoryUsage("AGENT_METADATA") + } + try { const dataEvent = JSON.parse(event.data) const metadata = AgentMetadataEventSchemaArray.parse(dataEvent) // Overwrite metadata if it changed. if (JSON.stringify(watcher.metadata) !== JSON.stringify(metadata)) { + if (eventCount === 1) { + logger.debug(`Initial metadata received for agent: ${agentId}`) + } + watcher.metadata = metadata onChange.fire(null) } } catch (error) { + logger.error(`Error processing metadata for agent: ${agentId}`, error) watcher.error = error onChange.fire(null) } }) + eventSource.addEventListener("error", (error) => { + logger.error(`Metadata EventSource error for agent: ${agentId}`, error) + + // If connection closes permanently, clean up resources + if (eventSource.readyState === EventSource.CLOSED) { + logger.info(`Metadata EventSource connection closed for agent: ${agentId}`) + if (!disposed) { + watcher.dispose() + } + } + }) + return watcher }