From ab7c9d3e8334c3f90a26ceb9fe6be757848ccb64 Mon Sep 17 00:00:00 2001 From: JF Date: Fri, 21 Aug 2026 23:38:52 -0400 Subject: [PATCH] fix(http): detach per-session loggers from the shared file transport on stop() MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every Streamable HTTP session's DebugMcpServer piped its logger into the process-lifetime shared file transport and nothing ever unpiped — one listener set + retained logger per session, forever (issue #404). createLogger now records the attached shared transport in a WeakMap; detachSharedFileTransport(logger) removes it without closing it — shadowing transport.close during the remove because winston-transport's close-on-unpipe fires when the FIRST attacher unpipes and would close the shared file stream for everyone. The DI container exposes the detach as Dependencies.disposeLogger and DebugMcpServer.stop() calls it last. Co-Authored-By: Claude Fable 5 --- src/container/dependencies.ts | 13 ++- src/server.ts | 9 +- src/utils/logger.ts | 46 +++++++++- .../core/unit/server/server-lifecycle.test.ts | 14 ++- tests/unit/container/dependencies.test.ts | 17 +++- tests/unit/utils/logger-detach.test.ts | 87 +++++++++++++++++++ 6 files changed, 179 insertions(+), 7 deletions(-) create mode 100644 tests/unit/utils/logger-detach.test.ts diff --git a/src/container/dependencies.ts b/src/container/dependencies.ts index 373126df..9b21cb7f 100644 --- a/src/container/dependencies.ts +++ b/src/container/dependencies.ts @@ -3,7 +3,7 @@ * Manages all dependencies and their wiring for production use */ import { ContainerConfig } from './types.js'; -import { createLogger } from '../utils/logger.js'; +import { createLogger, detachSharedFileTransport } from '../utils/logger.js'; import { IFileSystem, IProcessManager, @@ -55,6 +55,14 @@ export interface Dependencies { // Adapter support adapterRegistry: IAdapterRegistry; + + /** + * Detach this container's logger from the shared file transport (issue + * #404). Called from DebugMcpServer.stop() so per-session servers in + * Streamable HTTP mode don't accumulate pipe edges on the process-lifetime + * transport. Optional: test containers may omit it. + */ + disposeLogger?: () => void; } /** @@ -158,6 +166,7 @@ export function createProductionDependencies(config: ContainerConfig = {}): Depe proxyProcessLauncher, proxyManagerFactory, sessionStoreFactory, - adapterRegistry + adapterRegistry, + disposeLogger: () => detachSharedFileTransport(logger) }; } diff --git a/src/server.ts b/src/server.ts index 504f3d44..479697fe 100644 --- a/src/server.ts +++ b/src/server.ts @@ -248,6 +248,8 @@ export class DebugMcpServer { public server: Server; private sessionManager: SessionManager; private logger; + /** Detaches this server's logger from the shared file transport on stop() (issue #404). */ + private readonly disposeLogger?: () => void; private fileChecker: SimpleFileChecker; private lineReader: LineReader; private environment: IEnvironment; @@ -938,8 +940,9 @@ export class DebugMcpServer { }; const dependencies = createProductionDependencies(containerConfig); - + this.logger = dependencies.logger; + this.disposeLogger = dependencies.disposeLogger; this.environment = dependencies.environment; this.logger.info('[DebugMcpServer Constructor] Main server logger instance assigned.'); @@ -2888,6 +2891,10 @@ export class DebugMcpServer { this.subscribedUris.clear(); this.sessionManager.removeListener('output-captured', this.handleOutputCaptured); this.logger.info('Debug MCP Server stopped'); + // Last: detach this server's logger from the shared file transport so + // per-session servers in HTTP mode don't accumulate on it (issue #404). + // After this line the logger no longer writes to the shared file. + this.disposeLogger?.(); } /** diff --git a/src/utils/logger.ts b/src/utils/logger.ts index eef9f674..0fc5bdf8 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -48,6 +48,13 @@ const STALE_LOG_MAX_AGE_MS = 7 * 24 * 60 * 60 * 1000; */ const fileTransportCache = new Map(); +/** + * Which shared file transport each logger attached, so per-session loggers + * can be detached on DebugMcpServer.stop() without closing the transport for + * everyone (issue #404). WeakMap: a discarded logger must not be retained here. + */ +const loggerFileTransports = new WeakMap(); + let staleLogCleanupDone = false; /** Sends a signal to a pid; injectable so tests never spy the global process.kill (issue #183). */ @@ -189,6 +196,7 @@ export function createLogger(namespace: string, options: LoggerOptions = {}): Wi cleanupStaleLogFiles(path.dirname(logFilePath)); } + let attachedFileTransport: winston.transport | undefined; try { const cacheKey = path.resolve(logFilePath); let fileTransport = fileTransportCache.get(cacheKey); @@ -206,13 +214,14 @@ export function createLogger(namespace: string, options: LoggerOptions = {}): Wi fileTransportCache.set(cacheKey, fileTransport); } transports.push(fileTransport); + attachedFileTransport = fileTransport; } catch (fileTransportError) { // When console output is silenced we must not write to console as it corrupts transports if (!isConsoleSilenced) { console.error(`[Logger Init Error] Failed to create file transport for ${logFilePath}:`, fileTransportError); } } - + const logger = winston.createLogger({ level, transports, @@ -220,6 +229,10 @@ export function createLogger(namespace: string, options: LoggerOptions = {}): Wi exitOnError: false }); + if (attachedFileTransport) { + loggerFileTransports.set(logger, attachedFileTransport); + } + logger.on('error', (error: Error) => { // When console output is silenced we must not write to console as it corrupts transports if (!isConsoleSilenced) { @@ -235,6 +248,37 @@ export function createLogger(namespace: string, options: LoggerOptions = {}): Wi return logger; } +/** + * Detach a logger from the shared file transport it attached in createLogger, + * WITHOUT closing the transport for the other loggers still piping into it + * (issue #404). This is the per-session disposal path for Streamable HTTP + * mode, where every MCP session builds a DebugMcpServer whose logger would + * otherwise stay piped into the process-lifetime shared transport forever. + * + * winston-transport registers `once('unpipe', src => { if (src === + * this.parent) { this.parent = null; this.close(); } })`, where `parent` is + * the FIRST logger that piped the transport — so a plain logger.remove() from + * that logger would close the shared file stream for everyone. The close is + * neutralized by shadowing `close` with an own undefined property for the + * duration of the remove (`if (this.close)` in the handler is then falsy), + * and restored in finally. logger.close() remains forbidden as documented on + * the transport cache above. + */ +export function detachSharedFileTransport(logger: WinstonLoggerType): void { + const transport = loggerFileTransports.get(logger); + if (!transport) { + return; + } + loggerFileTransports.delete(logger); + const t = transport as unknown as Record; + t.close = undefined; + try { + logger.remove(transport); + } finally { + delete t.close; + } +} + /** * Get the default logger instance. If no root logger has been created, a fallback logger is created. * @returns The default logger instance. diff --git a/tests/core/unit/server/server-lifecycle.test.ts b/tests/core/unit/server/server-lifecycle.test.ts index 24d9bdfe..62f1a91d 100644 --- a/tests/core/unit/server/server-lifecycle.test.ts +++ b/tests/core/unit/server/server-lifecycle.test.ts @@ -58,13 +58,23 @@ describe('Server Lifecycle Tests', () => { it('should stop server and close all sessions', async () => { debugServer = new DebugMcpServer(); mockSessionManager.closeAllSessions.mockResolvedValue(undefined); - + await debugServer.stop(); - + expect(mockSessionManager.closeAllSessions).toHaveBeenCalled(); expect(mockDependencies.logger.info).toHaveBeenCalledWith('Debug MCP Server stopped'); }); + it('stop() disposes the container logger so churning HTTP sessions do not leak (issue #404)', async () => { + mockDependencies.disposeLogger = vi.fn(); + debugServer = new DebugMcpServer(); + mockSessionManager.closeAllSessions.mockResolvedValue(undefined); + + await debugServer.stop(); + + expect(mockDependencies.disposeLogger).toHaveBeenCalledTimes(1); + }); + it('should propagate closeAllSessions errors from stop', async () => { debugServer = new DebugMcpServer(); mockSessionManager.closeAllSessions.mockRejectedValue(new Error('Close sessions failed')); diff --git a/tests/unit/container/dependencies.test.ts b/tests/unit/container/dependencies.test.ts index c1598546..d83cf19d 100644 --- a/tests/unit/container/dependencies.test.ts +++ b/tests/unit/container/dependencies.test.ts @@ -15,8 +15,11 @@ const sessionStoreFactoryInstance = { tag: 'session-factory' }; const registerMock = vi.fn(); const getSupportedLanguagesMock = vi.fn(() => []); +const detachSharedFileTransportMock = vi.fn(); + vi.mock('../../../src/utils/logger.js', () => ({ - createLogger: createLoggerMock + createLogger: createLoggerMock, + detachSharedFileTransport: detachSharedFileTransportMock })); vi.mock('../../../src/implementations/index.js', () => ({ @@ -114,6 +117,18 @@ describe('createProductionDependencies', () => { ); }); + it('returns a disposeLogger that detaches the shared file transport (issue #404)', () => { + const dependencies = createProductionDependencies({ logFile: '/tmp/debug.log' }); + + expect(typeof dependencies.disposeLogger).toBe('function'); + expect(detachSharedFileTransportMock).not.toHaveBeenCalled(); + + dependencies.disposeLogger!(); + + expect(detachSharedFileTransportMock).toHaveBeenCalledTimes(1); + expect(detachSharedFileTransportMock).toHaveBeenCalledWith(dependencies.logger); + }); + it('registers bundled adapters and logs async failures', async () => { const firstFactoryInstance = { instance: 'first' }; const secondFactoryInstance = { instance: 'second' }; diff --git a/tests/unit/utils/logger-detach.test.ts b/tests/unit/utils/logger-detach.test.ts new file mode 100644 index 00000000..7b306a36 --- /dev/null +++ b/tests/unit/utils/logger-detach.test.ts @@ -0,0 +1,87 @@ +/** + * Leak regression tests for issue #404: every per-session DebugMcpServer's + * logger pipes into the process-lifetime shared file transport and nothing + * ever unpiped, so the transport accumulated one listener set + retained + * logger per HTTP session forever. + * + * Uses REAL winston (no module mock): the leak lives in winston's pipe + * mechanics, and the fix must neutralize winston-transport's close-on-unpipe + * behavior (transport.parent is the FIRST logger that piped it; a plain + * logger.remove() from that logger closes the shared transport for everyone). + */ +import { describe, it, expect, beforeAll, afterAll, vi } from 'vitest'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; +import { createLogger, detachSharedFileTransport } from '../../../src/utils/logger.js'; + +let tmpDir: string; +let logFile: string; + +beforeAll(() => { + tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'logger-detach-test-')); + logFile = path.join(tmpDir, 'shared.log'); +}); + +afterAll(() => { + // The shared transport deliberately stays open for the process lifetime; + // best-effort cleanup only. + try { + fs.rmSync(tmpDir, { recursive: true, force: true }); + } catch { + // Windows may hold the handle — fine, it's a temp dir. + } +}); + +function fileTransportOf(logger: ReturnType) { + const t = logger.transports.find((tr) => (tr as { filename?: string }).filename !== undefined); + expect(t).toBeDefined(); + return t!; +} + +describe('detachSharedFileTransport (issue #404)', () => { + it('detaches a later logger without growing or closing the shared transport', () => { + const first = createLogger('detach-test-first', { file: logFile }); + const shared = fileTransportOf(first); + + const baselineUnpipe = shared.listenerCount('unpipe'); + const baselineError = shared.listenerCount('error'); + + // N churning sessions attach and detach + for (let i = 0; i < 5; i++) { + const session = createLogger(`detach-test-session-${i}`, { file: logFile }); + expect(fileTransportOf(session)).toBe(shared); // cache: one transport per path + detachSharedFileTransport(session); + expect(session.transports).not.toContain(shared); + } + + // No listener growth on the shared transport after the churn + expect(shared.listenerCount('unpipe')).toBeLessThanOrEqual(baselineUnpipe); + expect(shared.listenerCount('error')).toBeLessThanOrEqual(baselineError); + }); + + it('does not close the shared transport even when the FIRST attacher detaches', () => { + const file = path.join(tmpDir, 'first-attacher.log'); + const first = createLogger('detach-test-owner', { file }); + const shared = fileTransportOf(first); + const closeSpy = vi.spyOn(shared as unknown as { close: () => void }, 'close'); + + const second = createLogger('detach-test-tenant', { file }); + expect(fileTransportOf(second)).toBe(shared); + + // winston-transport's close-on-unpipe fires when transport.parent (the + // first attacher) unpipes — the detach must neutralize it. + detachSharedFileTransport(first); + + expect(closeSpy).not.toHaveBeenCalled(); + // The surviving logger still carries the open shared transport + expect(second.transports).toContain(shared); + expect(() => second.info('still alive')).not.toThrow(); + closeSpy.mockRestore(); + }); + + it('is a no-op for a logger with no shared file transport', () => { + const bare = createLogger('detach-test-bare'); + expect(() => detachSharedFileTransport(bare)).not.toThrow(); + }); +});