diff --git a/src/common/atlas/accessListUtils.ts b/src/common/atlas/accessListUtils.ts index dddb8605..dd759aba 100644 --- a/src/common/atlas/accessListUtils.ts +++ b/src/common/atlas/accessListUtils.ts @@ -30,25 +30,25 @@ export async function ensureCurrentIpInAccessList(apiClient: ApiClient, projectI params: { path: { groupId: projectId } }, body: [entry], }); - logger.debug( - LogId.atlasIpAccessListAdded, - "accessListUtils", - `IP access list created: ${JSON.stringify(entry)}` - ); + logger.debug({ + id: LogId.atlasIpAccessListAdded, + context: "accessListUtils", + message: `IP access list created: ${JSON.stringify(entry)}`, + }); } catch (err) { if (err instanceof ApiClientError && err.response?.status === 409) { // 409 Conflict: entry already exists, log info - logger.debug( - LogId.atlasIpAccessListAdded, - "accessListUtils", - `IP address ${entry.ipAddress} is already present in the access list for project ${projectId}.` - ); + logger.debug({ + id: LogId.atlasIpAccessListAdded, + context: "accessListUtils", + message: `IP address ${entry.ipAddress} is already present in the access list for project ${projectId}.`, + }); return; } - logger.warning( - LogId.atlasIpAccessListAddFailure, - "accessListUtils", - `Error adding IP access list: ${err instanceof Error ? err.message : String(err)}` - ); + logger.warning({ + id: LogId.atlasIpAccessListAddFailure, + context: "accessListUtils", + message: `Error adding IP access list: ${err instanceof Error ? err.message : String(err)}`, + }); } } diff --git a/src/common/atlas/apiClient.ts b/src/common/atlas/apiClient.ts index 6c885584..c99b43a8 100644 --- a/src/common/atlas/apiClient.ts +++ b/src/common/atlas/apiClient.ts @@ -180,7 +180,11 @@ export class ApiClient { }; } catch (error: unknown) { const err = error instanceof Error ? error : new Error(String(error)); - logger.error(LogId.atlasConnectFailure, "apiClient", `Failed to request access token: ${err.message}`); + logger.error({ + id: LogId.atlasConnectFailure, + context: "apiClient", + message: `Failed to request access token: ${err.message}`, + }); } return this.accessToken; } @@ -200,7 +204,11 @@ export class ApiClient { } } catch (error: unknown) { const err = error instanceof Error ? error : new Error(String(error)); - logger.error(LogId.atlasApiRevokeFailure, "apiClient", `Failed to revoke access token: ${err.message}`); + logger.error({ + id: LogId.atlasApiRevokeFailure, + context: "apiClient", + message: `Failed to revoke access token: ${err.message}`, + }); } this.accessToken = undefined; } diff --git a/src/common/atlas/cluster.ts b/src/common/atlas/cluster.ts index f3557890..2e8d7f28 100644 --- a/src/common/atlas/cluster.ts +++ b/src/common/atlas/cluster.ts @@ -87,7 +87,11 @@ export async function inspectCluster(apiClient: ApiClient, projectId: string, cl return formatFlexCluster(cluster); } catch (flexError) { const err = flexError instanceof Error ? flexError : new Error(String(flexError)); - logger.error(LogId.atlasInspectFailure, "inspect-cluster", `error inspecting cluster: ${err.message}`); + logger.error({ + id: LogId.atlasInspectFailure, + context: "inspect-cluster", + message: `error inspecting cluster: ${err.message}`, + }); throw error; } } diff --git a/src/common/logger.ts b/src/common/logger.ts index 7281977b..53421d3f 100644 --- a/src/common/logger.ts +++ b/src/common/logger.ts @@ -50,44 +50,96 @@ export const LogId = { streamableHttpTransportCloseFailure: mongoLogId(1_006_006), } as const; +interface LogPayload { + id: MongoLogId; + context: string; + message: string; + noRedaction?: boolean | LoggerType | LoggerType[]; +} + +export type LoggerType = "console" | "disk" | "mcp"; + export abstract class LoggerBase { - abstract log(level: LogLevel, id: MongoLogId, context: string, message: string): void; + private defaultUnredactedLogger: LoggerType = "mcp"; - info(id: MongoLogId, context: string, message: string): void { - this.log("info", id, context, message); + public log(level: LogLevel, payload: LogPayload): void { + // If no explicit value is supplied for unredacted loggers, default to "mcp" + const noRedaction = payload.noRedaction !== undefined ? payload.noRedaction : this.defaultUnredactedLogger; + + this.logCore(level, { + ...payload, + message: this.redactIfNecessary(payload.message, noRedaction), + }); } - error(id: MongoLogId, context: string, message: string): void { - this.log("error", id, context, message); + protected abstract type: LoggerType; + + protected abstract logCore(level: LogLevel, payload: LogPayload): void; + + private redactIfNecessary(message: string, noRedaction: LogPayload["noRedaction"]): string { + if (typeof noRedaction === "boolean" && noRedaction) { + // If the consumer has supplied noRedaction: true, we don't redact the log message + // regardless of the logger type + return message; + } + + if (typeof noRedaction === "string" && noRedaction === this.type) { + // If the consumer has supplied noRedaction: logger-type, we skip redacting if + // our logger type is the same as what the consumer requested + return message; + } + + if ( + typeof noRedaction === "object" && + Array.isArray(noRedaction) && + this.type !== null && + noRedaction.indexOf(this.type) !== -1 + ) { + // If the consumer has supplied noRedaction: array, we skip redacting if our logger + // type is included in that array + return message; + } + + return redact(message); + } + + info(payload: LogPayload): void { + this.log("info", payload); } - debug(id: MongoLogId, context: string, message: string): void { - this.log("debug", id, context, message); + + error(payload: LogPayload): void { + this.log("error", payload); + } + debug(payload: LogPayload): void { + this.log("debug", payload); } - notice(id: MongoLogId, context: string, message: string): void { - this.log("notice", id, context, message); + notice(payload: LogPayload): void { + this.log("notice", payload); } - warning(id: MongoLogId, context: string, message: string): void { - this.log("warning", id, context, message); + warning(payload: LogPayload): void { + this.log("warning", payload); } - critical(id: MongoLogId, context: string, message: string): void { - this.log("critical", id, context, message); + critical(payload: LogPayload): void { + this.log("critical", payload); } - alert(id: MongoLogId, context: string, message: string): void { - this.log("alert", id, context, message); + alert(payload: LogPayload): void { + this.log("alert", payload); } - emergency(id: MongoLogId, context: string, message: string): void { - this.log("emergency", id, context, message); + emergency(payload: LogPayload): void { + this.log("emergency", payload); } } export class ConsoleLogger extends LoggerBase { - log(level: LogLevel, id: MongoLogId, context: string, message: string): void { - message = redact(message); + protected type: LoggerType = "console"; + + protected logCore(level: LogLevel, payload: LogPayload): void { + const { id, context, message } = payload; console.error(`[${level.toUpperCase()}] ${id.__value} - ${context}: ${message} (${process.pid})`); } } @@ -97,6 +149,8 @@ export class DiskLogger extends LoggerBase { super(); } + protected type: LoggerType = "disk"; + static async fromPath(logPath: string): Promise { await fs.mkdir(logPath, { recursive: true }); @@ -116,8 +170,8 @@ export class DiskLogger extends LoggerBase { return new DiskLogger(logWriter); } - log(level: LogLevel, id: MongoLogId, context: string, message: string): void { - message = redact(message); + protected logCore(level: LogLevel, payload: LogPayload): void { + const { id, context, message } = payload; const mongoDBLevel = this.mapToMongoDBLogLevel(level); this.logWriter[mongoDBLevel]("MONGODB-MCP", id, context, message); @@ -149,7 +203,9 @@ export class McpLogger extends LoggerBase { super(); } - log(level: LogLevel, _: MongoLogId, context: string, message: string): void { + type: LoggerType = "mcp"; + + protected logCore(level: LogLevel, payload: LogPayload): void { // Only log if the server is connected if (!this.server?.isConnected()) { return; @@ -157,12 +213,15 @@ export class McpLogger extends LoggerBase { void this.server.server.sendLoggingMessage({ level, - data: `[${context}]: ${message}`, + data: `[${payload.context}]: ${payload.message}`, }); } } -class CompositeLogger extends LoggerBase { +export class CompositeLogger extends LoggerBase { + // This is not a real logger type - it should not be used anyway. + protected type: LoggerType = "composite" as unknown as LoggerType; + private loggers: LoggerBase[] = []; constructor(...loggers: LoggerBase[]) { @@ -178,11 +237,16 @@ class CompositeLogger extends LoggerBase { this.loggers = [...loggers]; } - log(level: LogLevel, id: MongoLogId, context: string, message: string): void { + public log(level: LogLevel, payload: LogPayload): void { + // Override the public method to avoid the base logger redacting the message payload for (const logger of this.loggers) { - logger.log(level, id, context, message); + logger.log(level, payload); } } + + protected logCore(): void { + throw new Error("logCore should never be invoked on CompositeLogger"); + } } const logger = new CompositeLogger(new ConsoleLogger()); diff --git a/src/common/session.ts b/src/common/session.ts index 0baccc9b..d70f7c6e 100644 --- a/src/common/session.ts +++ b/src/common/session.ts @@ -70,7 +70,11 @@ export class Session extends EventEmitter { await this.connectionManager.disconnect(); } catch (err: unknown) { const error = err instanceof Error ? err : new Error(String(err)); - logger.error(LogId.mongodbDisconnectFailure, "Error closing service provider:", error.message); + logger.error({ + id: LogId.mongodbDisconnectFailure, + context: "session", + message: `Error closing service provider: ${error.message}`, + }); } if (atlasCluster?.username && atlasCluster?.projectId) { @@ -86,11 +90,11 @@ export class Session extends EventEmitter { }) .catch((err: unknown) => { const error = err instanceof Error ? err : new Error(String(err)); - logger.error( - LogId.atlasDeleteDatabaseUserFailure, - "atlas-connect-cluster", - `Error deleting previous database user: ${error.message}` - ); + logger.error({ + id: LogId.atlasDeleteDatabaseUserFailure, + context: "session", + message: `Error deleting previous database user: ${error.message}`, + }); }); } } diff --git a/src/common/sessionStore.ts b/src/common/sessionStore.ts index e37358fc..20ef98dd 100644 --- a/src/common/sessionStore.ts +++ b/src/common/sessionStore.ts @@ -47,18 +47,18 @@ export class SessionStore { private sendNotification(sessionId: string): void { const session = this.sessions[sessionId]; if (!session) { - logger.warning( - LogId.streamableHttpTransportSessionCloseNotificationFailure, - "sessionStore", - `session ${sessionId} not found, no notification delivered` - ); + logger.warning({ + id: LogId.streamableHttpTransportSessionCloseNotificationFailure, + context: "sessionStore", + message: `session ${sessionId} not found, no notification delivered`, + }); return; } - session.logger.info( - LogId.streamableHttpTransportSessionCloseNotification, - "sessionStore", - "Session is about to be closed due to inactivity" - ); + session.logger.info({ + id: LogId.streamableHttpTransportSessionCloseNotification, + context: "sessionStore", + message: "Session is about to be closed due to inactivity", + }); } setSession(sessionId: string, transport: StreamableHTTPServerTransport, mcpServer: McpServer): void { @@ -68,11 +68,11 @@ export class SessionStore { } const abortTimeout = setManagedTimeout(async () => { if (this.sessions[sessionId]) { - this.sessions[sessionId].logger.info( - LogId.streamableHttpTransportSessionCloseNotification, - "sessionStore", - "Session closed due to inactivity" - ); + this.sessions[sessionId].logger.info({ + id: LogId.streamableHttpTransportSessionCloseNotification, + context: "sessionStore", + message: "Session closed due to inactivity", + }); await this.closeSession(sessionId); } @@ -95,11 +95,11 @@ export class SessionStore { try { await session.transport.close(); } catch (error) { - logger.error( - LogId.streamableHttpTransportSessionCloseFailure, - "streamableHttpTransport", - `Error closing transport ${sessionId}: ${error instanceof Error ? error.message : String(error)}` - ); + logger.error({ + id: LogId.streamableHttpTransportSessionCloseFailure, + context: "streamableHttpTransport", + message: `Error closing transport ${sessionId}: ${error instanceof Error ? error.message : String(error)}`, + }); } } delete this.sessions[sessionId]; diff --git a/src/index.ts b/src/index.ts index 59a6c76c..406569b6 100644 --- a/src/index.ts +++ b/src/index.ts @@ -9,16 +9,28 @@ async function main() { const transportRunner = config.transport === "stdio" ? new StdioRunner(config) : new StreamableHttpRunner(config); const shutdown = () => { - logger.info(LogId.serverCloseRequested, "server", `Server close requested`); + logger.info({ + id: LogId.serverCloseRequested, + context: "server", + message: `Server close requested`, + }); transportRunner .close() .then(() => { - logger.info(LogId.serverClosed, "server", `Server closed`); + logger.info({ + id: LogId.serverClosed, + context: "server", + message: `Server closed`, + }); process.exit(0); }) .catch((error: unknown) => { - logger.error(LogId.serverCloseFailure, "server", `Error closing server: ${error as string}`); + logger.error({ + id: LogId.serverCloseFailure, + context: "server", + message: `Error closing server: ${error as string}`, + }); process.exit(1); }); }; @@ -31,18 +43,34 @@ async function main() { try { await transportRunner.start(); } catch (error: unknown) { - logger.info(LogId.serverCloseRequested, "server", "Closing server"); + logger.info({ + id: LogId.serverCloseRequested, + context: "server", + message: "Closing server", + }); try { await transportRunner.close(); - logger.info(LogId.serverClosed, "server", "Server closed"); + logger.info({ + id: LogId.serverClosed, + context: "server", + message: "Server closed", + }); } catch (error: unknown) { - logger.error(LogId.serverCloseFailure, "server", `Error closing server: ${error as string}`); + logger.error({ + id: LogId.serverCloseFailure, + context: "server", + message: `Error closing server: ${error as string}`, + }); } throw error; } } main().catch((error: unknown) => { - logger.emergency(LogId.serverStartFailure, "server", `Fatal error running server: ${error as string}`); + logger.emergency({ + id: LogId.serverStartFailure, + context: "server", + message: `Fatal error running server: ${error as string}`, + }); process.exit(1); }); diff --git a/src/resources/resource.ts b/src/resources/resource.ts index cc903033..f1da56fa 100644 --- a/src/resources/resource.ts +++ b/src/resources/resource.ts @@ -63,11 +63,11 @@ export function ReactiveResource { switch (reason) { case "resolutionError": - logger.debug(LogId.telemetryDeviceIdFailure, "telemetry", String(error)); + logger.debug({ + id: LogId.telemetryDeviceIdFailure, + context: "telemetry", + message: String(error), + }); break; case "timeout": - logger.debug(LogId.telemetryDeviceIdTimeout, "telemetry", "Device ID retrieval timed out"); + logger.debug({ + id: LogId.telemetryDeviceIdTimeout, + context: "telemetry", + message: "Device ID retrieval timed out", + noRedaction: true, + }); break; case "abort": // No need to log in the case of aborts @@ -99,13 +108,23 @@ export class Telemetry { public async emitEvents(events: BaseEvent[]): Promise { try { if (!this.isTelemetryEnabled()) { - logger.info(LogId.telemetryEmitFailure, "telemetry", `Telemetry is disabled.`); + logger.info({ + id: LogId.telemetryEmitFailure, + context: "telemetry", + message: "Telemetry is disabled.", + noRedaction: true, + }); return; } await this.emit(events); } catch { - logger.debug(LogId.telemetryEmitFailure, "telemetry", `Error emitting telemetry events.`); + logger.debug({ + id: LogId.telemetryEmitFailure, + context: "telemetry", + message: "Error emitting telemetry events.", + noRedaction: true, + }); } } @@ -155,28 +174,28 @@ export class Telemetry { const cachedEvents = this.eventCache.getEvents(); const allEvents = [...cachedEvents, ...events]; - logger.debug( - LogId.telemetryEmitStart, - "telemetry", - `Attempting to send ${allEvents.length} events (${cachedEvents.length} cached)` - ); + logger.debug({ + id: LogId.telemetryEmitStart, + context: "telemetry", + message: `Attempting to send ${allEvents.length} events (${cachedEvents.length} cached)`, + }); const result = await this.sendEvents(this.session.apiClient, allEvents); if (result.success) { this.eventCache.clearEvents(); - logger.debug( - LogId.telemetryEmitSuccess, - "telemetry", - `Sent ${allEvents.length} events successfully: ${JSON.stringify(allEvents, null, 2)}` - ); + logger.debug({ + id: LogId.telemetryEmitSuccess, + context: "telemetry", + message: `Sent ${allEvents.length} events successfully: ${JSON.stringify(allEvents, null, 2)}`, + }); return; } - logger.debug( - LogId.telemetryEmitFailure, - "telemetry", - `Error sending event to client: ${result.error instanceof Error ? result.error.message : String(result.error)}` - ); + logger.debug({ + id: LogId.telemetryEmitFailure, + context: "telemetry", + message: `Error sending event to client: ${result.error instanceof Error ? result.error.message : String(result.error)}`, + }); this.eventCache.appendEvents(events); } diff --git a/src/tools/atlas/atlasTool.ts b/src/tools/atlas/atlasTool.ts index 21ae7e8c..58cc5849 100644 --- a/src/tools/atlas/atlasTool.ts +++ b/src/tools/atlas/atlasTool.ts @@ -79,11 +79,11 @@ For more information on Atlas API access roles, visit: https://www.mongodb.com/d const parsedResult = argsShape.safeParse(args[0]); if (!parsedResult.success) { - logger.debug( - LogId.telemetryMetadataError, - "tool", - `Error parsing tool arguments: ${parsedResult.error.message}` - ); + logger.debug({ + id: LogId.telemetryMetadataError, + context: "tool", + message: `Error parsing tool arguments: ${parsedResult.error.message}`, + }); return toolMetadata; } diff --git a/src/tools/atlas/connect/connectCluster.ts b/src/tools/atlas/connect/connectCluster.ts index 1af1aa3d..92ffb158 100644 --- a/src/tools/atlas/connect/connectCluster.ts +++ b/src/tools/atlas/connect/connectCluster.ts @@ -49,11 +49,11 @@ export class ConnectClusterTool extends AtlasToolBase { case "connected": return "connected"; case "errored": - logger.debug( - LogId.atlasConnectFailure, - "atlas-connect-cluster", - `error querying cluster: ${currentConectionState.errorReason}` - ); + logger.debug({ + id: LogId.atlasConnectFailure, + context: "atlas-connect-cluster", + message: `error querying cluster: ${currentConectionState.errorReason}`, + }); return "unknown"; } } @@ -127,11 +127,12 @@ export class ConnectClusterTool extends AtlasToolBase { private async connectToCluster(connectionString: string, atlas: AtlasClusterConnectionInfo): Promise { let lastError: Error | undefined = undefined; - logger.debug( - LogId.atlasConnectAttempt, - "atlas-connect-cluster", - `attempting to connect to cluster: ${this.session.connectedAtlasCluster?.clusterName}` - ); + logger.debug({ + id: LogId.atlasConnectAttempt, + context: "atlas-connect-cluster", + message: `attempting to connect to cluster: ${this.session.connectedAtlasCluster?.clusterName}`, + noRedaction: true, + }); // try to connect for about 5 minutes for (let i = 0; i < 600; i++) { @@ -145,11 +146,11 @@ export class ConnectClusterTool extends AtlasToolBase { lastError = error; - logger.debug( - LogId.atlasConnectFailure, - "atlas-connect-cluster", - `error connecting to cluster: ${error.message}` - ); + logger.debug({ + id: LogId.atlasConnectFailure, + context: "atlas-connect-cluster", + message: `error connecting to cluster: ${error.message}`, + }); await sleep(500); // wait for 500ms before retrying } @@ -181,21 +182,22 @@ export class ConnectClusterTool extends AtlasToolBase { }) .catch((err: unknown) => { const error = err instanceof Error ? err : new Error(String(err)); - logger.debug( - LogId.atlasConnectFailure, - "atlas-connect-cluster", - `error deleting database user: ${error.message}` - ); + logger.debug({ + id: LogId.atlasConnectFailure, + context: "atlas-connect-cluster", + message: `error deleting database user: ${error.message}`, + }); }); } throw lastError; } - logger.debug( - LogId.atlasConnectSucceeded, - "atlas-connect-cluster", - `connected to cluster: ${this.session.connectedAtlasCluster?.clusterName}` - ); + logger.debug({ + id: LogId.atlasConnectSucceeded, + context: "atlas-connect-cluster", + message: `connected to cluster: ${this.session.connectedAtlasCluster?.clusterName}`, + noRedaction: true, + }); } protected async execute({ projectId, clusterName }: ToolArgs): Promise { @@ -226,11 +228,11 @@ export class ConnectClusterTool extends AtlasToolBase { // try to connect for about 5 minutes asynchronously void this.connectToCluster(connectionString, atlas).catch((err: unknown) => { const error = err instanceof Error ? err : new Error(String(err)); - logger.error( - LogId.atlasConnectFailure, - "atlas-connect-cluster", - `error connecting to cluster: ${error.message}` - ); + logger.error({ + id: LogId.atlasConnectFailure, + context: "atlas-connect-cluster", + message: `error connecting to cluster: ${error.message}`, + }); }); break; } diff --git a/src/tools/mongodb/mongodbTool.ts b/src/tools/mongodb/mongodbTool.ts index 7071b818..6ff09b2c 100644 --- a/src/tools/mongodb/mongodbTool.ts +++ b/src/tools/mongodb/mongodbTool.ts @@ -28,11 +28,11 @@ export abstract class MongoDBToolBase extends ToolBase { try { await this.connectToMongoDB(this.config.connectionString); } catch (error) { - logger.error( - LogId.mongodbConnectFailure, - "mongodbTool", - `Failed to connect to MongoDB instance using the connection string from the config: ${error as string}` - ); + logger.error({ + id: LogId.mongodbConnectFailure, + context: "mongodbTool", + message: `Failed to connect to MongoDB instance using the connection string from the config: ${error as string}`, + }); throw new MongoDBError(ErrorCodes.MisconfiguredConnectionString, "Not connected to MongoDB."); } } diff --git a/src/tools/tool.ts b/src/tools/tool.ts index bb0e0804..09ab8b69 100644 --- a/src/tools/tool.ts +++ b/src/tools/tool.ts @@ -73,13 +73,22 @@ export abstract class ToolBase { const callback: ToolCallback = async (...args) => { const startTime = Date.now(); try { - logger.debug(LogId.toolExecute, "tool", `Executing tool ${this.name}`); + logger.debug({ + id: LogId.toolExecute, + context: "tool", + message: `Executing tool ${this.name}`, + noRedaction: true, + }); const result = await this.execute(...args); await this.emitToolEvent(startTime, result, ...args).catch(() => {}); return result; } catch (error: unknown) { - logger.error(LogId.toolExecuteFailure, "tool", `Error executing ${this.name}: ${error as string}`); + logger.error({ + id: LogId.toolExecuteFailure, + context: "tool", + message: `Error executing ${this.name}: ${error as string}`, + }); const toolResult = await this.handleError(error, args[0] as ToolArgs); await this.emitToolEvent(startTime, toolResult, ...args).catch(() => {}); return toolResult; @@ -98,7 +107,12 @@ export abstract class ToolBase { const existingTool = tools[this.name]; if (!existingTool) { - logger.warning(LogId.toolUpdateFailure, "tool", `Tool ${this.name} not found in update`); + logger.warning({ + id: LogId.toolUpdateFailure, + context: "tool", + message: `Tool ${this.name} not found in update`, + noRedaction: true, + }); return; } @@ -145,11 +159,12 @@ export abstract class ToolBase { } if (errorClarification) { - logger.debug( - LogId.toolDisabled, - "tool", - `Prevented registration of ${this.name} because ${errorClarification} is disabled in the config` - ); + logger.debug({ + id: LogId.toolDisabled, + context: "tool", + message: `Prevented registration of ${this.name} because ${errorClarification} is disabled in the config`, + noRedaction: true, + }); return false; } diff --git a/src/transports/stdio.ts b/src/transports/stdio.ts index 870ec73c..71930341 100644 --- a/src/transports/stdio.ts +++ b/src/transports/stdio.ts @@ -65,7 +65,11 @@ export class StdioRunner extends TransportRunnerBase { await this.server.connect(transport); } catch (error: unknown) { - logger.emergency(LogId.serverStartFailure, "server", `Fatal error running server: ${error as string}`); + logger.emergency({ + id: LogId.serverStartFailure, + context: "server", + message: `Fatal error running server: ${error as string}`, + }); process.exit(1); } } diff --git a/src/transports/streamableHttp.ts b/src/transports/streamableHttp.ts index 4615d79f..f5381756 100644 --- a/src/transports/streamableHttp.ts +++ b/src/transports/streamableHttp.ts @@ -19,11 +19,11 @@ function withErrorHandling( ) { return (req: express.Request, res: express.Response, next: express.NextFunction) => { fn(req, res, next).catch((error) => { - logger.error( - LogId.streamableHttpTransportRequestFailure, - "streamableHttpTransport", - `Error handling request: ${error instanceof Error ? error.message : String(error)}` - ); + logger.error({ + id: LogId.streamableHttpTransportRequestFailure, + context: "streamableHttpTransport", + message: `Error handling request: ${error instanceof Error ? error.message : String(error)}`, + }); res.status(400).json({ jsonrpc: "2.0", error: { @@ -116,22 +116,22 @@ export class StreamableHttpRunner extends TransportRunnerBase { try { await this.sessionStore.closeSession(sessionId, false); } catch (error) { - logger.error( - LogId.streamableHttpTransportSessionCloseFailure, - "streamableHttpTransport", - `Error closing session: ${error instanceof Error ? error.message : String(error)}` - ); + logger.error({ + id: LogId.streamableHttpTransportSessionCloseFailure, + context: "streamableHttpTransport", + message: `Error closing session: ${error instanceof Error ? error.message : String(error)}`, + }); } }, }); transport.onclose = () => { server.close().catch((error) => { - logger.error( - LogId.streamableHttpTransportCloseFailure, - "streamableHttpTransport", - `Error closing server: ${error instanceof Error ? error.message : String(error)}` - ); + logger.error({ + id: LogId.streamableHttpTransportCloseFailure, + context: "streamableHttpTransport", + message: `Error closing server: ${error instanceof Error ? error.message : String(error)}`, + }); }); }; @@ -154,11 +154,12 @@ export class StreamableHttpRunner extends TransportRunnerBase { }); }); - logger.info( - LogId.streamableHttpTransportStarted, - "streamableHttpTransport", - `Server started on http://${this.userConfig.httpHost}:${this.userConfig.httpPort}` - ); + logger.info({ + id: LogId.streamableHttpTransportStarted, + context: "streamableHttpTransport", + message: `Server started on http://${this.userConfig.httpHost}:${this.userConfig.httpPort}`, + noRedaction: true, + }); } async close(): Promise { diff --git a/tests/unit/logger.test.ts b/tests/unit/logger.test.ts new file mode 100644 index 00000000..443494f0 --- /dev/null +++ b/tests/unit/logger.test.ts @@ -0,0 +1,164 @@ +import { describe, beforeEach, afterEach, vi, MockInstance, it, expect } from "vitest"; +import { CompositeLogger, ConsoleLogger, LoggerType, LogId, McpLogger } from "../../src/common/logger.js"; +import { McpServer } from "@modelcontextprotocol/sdk/server/mcp.js"; + +describe("Logger", () => { + let consoleErrorSpy: MockInstance; + let consoleLogger: ConsoleLogger; + + let mcpLoggerSpy: MockInstance; + let mcpLogger: McpLogger; + + beforeEach(() => { + // Mock console.error before creating the ConsoleLogger + consoleErrorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + + consoleLogger = new ConsoleLogger(); + + mcpLoggerSpy = vi.fn(); + mcpLogger = new McpLogger({ + server: { + sendLoggingMessage: mcpLoggerSpy, + }, + isConnected: () => true, + } as unknown as McpServer); + }); + + afterEach(() => { + vi.restoreAllMocks(); + }); + + const getLastMcpLogMessage = (): string => { + return (mcpLoggerSpy.mock.lastCall?.[0] as { data: string }).data; + }; + + const getLastConsoleMessage = (): string => { + return consoleErrorSpy.mock.lastCall?.[0] as string; + }; + + const mockSensitivePayload = { + id: LogId.serverInitialized, + context: "test", + message: "My email is foo@bar.com", + }; + + const expectLogMessageRedaction = (logMessage: string, expectRedacted: boolean): void => { + const expectedContain = expectRedacted ? "" : "foo@bar.com"; + const expectedNotContain = expectRedacted ? "foo@bar.com" : ""; + + expect(logMessage).to.contain(expectedContain); + expect(logMessage).to.not.contain(expectedNotContain); + }; + + describe("redaction", () => { + it("redacts sensitive information by default", () => { + consoleLogger.info(mockSensitivePayload); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + + expectLogMessageRedaction(getLastConsoleMessage(), true); + }); + + it("does not redact sensitive information for mcp logger by default", () => { + mcpLogger.info(mockSensitivePayload); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + + expectLogMessageRedaction(getLastMcpLogMessage(), false); + }); + + it("allows disabling redaction for all loggers", () => { + const payload = { + ...mockSensitivePayload, + noRedaction: true, + }; + + consoleLogger.debug(payload); + mcpLogger.error(payload); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), false); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), false); + }); + + it("allows forcing redaction for all loggers", () => { + const payload = { + ...mockSensitivePayload, + noRedaction: false, + }; + + consoleLogger.warning(payload); + mcpLogger.warning(payload); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), true); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), true); + }); + + it("allows disabling redaction for specific loggers", () => { + const payload = { + ...mockSensitivePayload, + noRedaction: "console" as LoggerType, + }; + + consoleLogger.debug(payload); + mcpLogger.debug(payload); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), false); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), true); + }); + + it("allows disabling redaction for multiple loggers", () => { + const payload = { + ...mockSensitivePayload, + noRedaction: ["console", "mcp"] as LoggerType[], + }; + + consoleLogger.notice(payload); + mcpLogger.notice(payload); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), false); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), false); + }); + + describe("CompositeLogger", () => { + it("propagates noRedaction config to child loggers", () => { + const compositeLogger = new CompositeLogger(consoleLogger, mcpLogger); + compositeLogger.info({ + ...mockSensitivePayload, + noRedaction: true, + }); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), false); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), false); + }); + + it("supports redaction for a subset of its child loggers", () => { + const compositeLogger = new CompositeLogger(consoleLogger, mcpLogger); + compositeLogger.info({ + ...mockSensitivePayload, + noRedaction: ["console", "disk"], + }); + + expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastConsoleMessage(), false); + + expect(mcpLoggerSpy).toHaveBeenCalledOnce(); + expectLogMessageRedaction(getLastMcpLogMessage(), true); + }); + }); + }); +}); diff --git a/tests/unit/telemetry.test.ts b/tests/unit/telemetry.test.ts index be1aeb9c..c5afcdb8 100644 --- a/tests/unit/telemetry.test.ts +++ b/tests/unit/telemetry.test.ts @@ -250,11 +250,11 @@ describe("Telemetry", () => { expect(telemetry["isBufferingEvents"]).toBe(false); expect(telemetry.getCommonProperties().device_id).toBe("unknown"); - expect(loggerSpy).toHaveBeenCalledWith( - LogId.telemetryDeviceIdFailure, - "telemetry", - "Error: Failed to get device ID" - ); + expect(loggerSpy).toHaveBeenCalledWith({ + id: LogId.telemetryDeviceIdFailure, + context: "telemetry", + message: "Error: Failed to get device ID", + }); }); it("should timeout if machine ID resolution takes too long", async () => { @@ -277,11 +277,12 @@ describe("Telemetry", () => { expect(telemetry.getCommonProperties().device_id).toBe("unknown"); expect(telemetry["isBufferingEvents"]).toBe(false); - expect(loggerSpy).toHaveBeenCalledWith( - LogId.telemetryDeviceIdTimeout, - "telemetry", - "Device ID retrieval timed out" - ); + expect(loggerSpy).toHaveBeenCalledWith({ + id: LogId.telemetryDeviceIdTimeout, + context: "telemetry", + message: "Device ID retrieval timed out", + noRedaction: true, + }); }); }); });