diff --git a/packages/mcp-server/src/server.ts b/packages/mcp-server/src/server.ts index 000939b27..d8ba6d32e 100644 --- a/packages/mcp-server/src/server.ts +++ b/packages/mcp-server/src/server.ts @@ -56,6 +56,21 @@ const defaultLogger: Logger = (level, message) => { getDefaultLogFn(level)(message); }; +function logLevelForStatus(statusCode: number): LogLevel { + if (statusCode >= 500) return 'Error'; + if (statusCode >= 400) return 'Warn'; + + return 'Info'; +} + +function logErrorWithStack(logger: Logger, message: string, err: Error): void { + logger('Error', message); + + if (err.stack) { + logger('Error', `Stack: ${err.stack}`); + } +} + /** Fields that are safe to log for each tool (non-sensitive data) */ const SAFE_ARGUMENTS_FOR_LOGGING: Record = { list: ['collectionName'], @@ -234,7 +249,8 @@ export default class ForestMCPServer { * Logs the request, intercepts the response for error logging, and delegates to the transport. */ private async handleMcpRequest(req: express.Request, res: express.Response): Promise { - this.logger('Info', `Incoming ${req.method} ${req.path}`); + const rpcMethod = req.body?.method || 'unknown'; + this.logger('Info', `Incoming ${req.method} ${req.path} [${rpcMethod}]`); if (!this.mcpTransport) { throw new Error('MCP transport not initialized'); @@ -328,17 +344,14 @@ export default class ForestMCPServer { app.use((req, res, next) => { const startTime = Date.now(); - // Capture the original end method to log after response is sent - const originalEnd = res.end.bind(res); - res.end = ((chunk?: unknown, encoding?: BufferEncoding | (() => void)) => { + res.on('finish', () => { const duration = Date.now() - startTime; + const level = logLevelForStatus(res.statusCode); this.logger( - 'Info', + level, `[${res.statusCode}] ${req.method} ${req.baseUrl || req.path} - ${duration}ms`, ); - - return originalEnd(chunk, encoding as BufferEncoding); - }) as typeof res.end; + }); next(); }); @@ -373,17 +386,28 @@ export default class ForestMCPServer { }), (req, res) => { this.handleMcpRequest(req, res).catch(error => { - this.logger('Error', `MCP Error: ${error}`); + const mcpMethod = req.body?.method || 'unknown'; + const err = error instanceof Error ? error : new Error(String(error)); + logErrorWithStack( + this.logger, + `MCP Error on method '${mcpMethod}': ${err.message || error}`, + err, + ); if (!res.headersSent) { res.status(500).json({ jsonrpc: '2.0', error: { code: -32603, - message: (error as Error)?.message || 'Internal server error', + message: err.message || 'Internal server error', }, id: null, }); + } else { + this.logger( + 'Warn', + `Cannot send error response (headers already sent) for method '${mcpMethod}'`, + ); } }); }, @@ -391,12 +415,16 @@ export default class ForestMCPServer { // Global error handler to catch any unhandled errors // Express requires all 4 parameters to recognize this as an error handler - // Capture logger for use in error handler (arrow function would lose context) + // Capture logger reference so the error handler closure does not depend on 'this' const { logger } = this; app.use( // eslint-disable-next-line @typescript-eslint/no-unused-vars - (err: Error, _req: express.Request, res: express.Response, _next: express.NextFunction) => { - logger('Error', `Unhandled error: ${err.message}`); + (err: Error, req: express.Request, res: express.Response, _next: express.NextFunction) => { + logErrorWithStack( + logger, + `Unhandled error on ${req.method} ${req.path}: ${err.message}`, + err, + ); if (!res.headersSent) { res.status(500).json({ diff --git a/packages/mcp-server/test/server.test.ts b/packages/mcp-server/test/server.test.ts index a3f51a3c9..8eb57b019 100644 --- a/packages/mcp-server/test/server.test.ts +++ b/packages/mcp-server/test/server.test.ts @@ -2056,7 +2056,7 @@ describe('ForestMCPServer Instance', () => { .set('Accept', 'application/json, text/event-stream') .send({ jsonrpc: '2.0', method: 'tools/list', id: 1 }); - expect(mockLogger).toHaveBeenCalledWith('Info', 'Incoming POST /mcp'); + expect(mockLogger).toHaveBeenCalledWith('Info', 'Incoming POST /mcp [tools/list]'); }); it('should log tool calls with safe parameters', async () => { @@ -2145,6 +2145,100 @@ describe('ForestMCPServer Instance', () => { ); }); + it('should log with Warn level for 4xx responses', async () => { + // Send unauthenticated request to trigger 401 + await request(loggingHttpServer) + .post('/mcp') + .set('Content-Type', 'application/json') + .send({ jsonrpc: '2.0', method: 'tools/list', id: 1 }); + + expect(mockLogger).toHaveBeenCalledWith( + 'Warn', + expect.stringMatching(/\[401\] POST \/mcp - \d+ms/), + ); + }); + + it('should log MCP error with method name and stack trace when handleMcpRequest fails', async () => { + const authSecret = process.env.FOREST_AUTH_SECRET || 'test-auth-secret'; + const validToken = jsonwebtoken.sign( + { id: 123, email: 'user@example.com', renderingId: 456 }, + authSecret, + { expiresIn: '1h' }, + ); + + // Break the transport to force an error in handleMcpRequest + const originalTransport = loggingServer.mcpTransport; + loggingServer.mcpTransport = undefined; + + await request(loggingHttpServer) + .post('/mcp') + .set('Authorization', `Bearer ${validToken}`) + .set('Content-Type', 'application/json') + .set('Accept', 'application/json, text/event-stream') + .send({ jsonrpc: '2.0', method: 'tools/list', id: 1 }); + + // Restore transport + loggingServer.mcpTransport = originalTransport; + + expect(mockLogger).toHaveBeenCalledWith( + 'Error', + expect.stringContaining("MCP Error on method 'tools/list'"), + ); + expect(mockLogger).toHaveBeenCalledWith('Error', expect.stringContaining('Stack:')); + }); + + it('should log warning when headersSent prevents MCP error response', async () => { + const authSecret = process.env.FOREST_AUTH_SECRET || 'test-auth-secret'; + const validToken = jsonwebtoken.sign( + { id: 123, email: 'user@example.com', renderingId: 456 }, + authSecret, + { expiresIn: '1h' }, + ); + + // Mock handleMcpRequest to send headers, end response, then throw + const serverRecord = loggingServer as unknown as Record; + const originalHandle = serverRecord.handleMcpRequest; + + serverRecord.handleMcpRequest = async ( + _req: unknown, + res: { writeHead: (s: number) => void; end: () => void }, + ) => { + res.writeHead(200); + res.end(); + throw new Error('Error after headers sent'); + }; + + await request(loggingHttpServer) + .post('/mcp') + .set('Authorization', `Bearer ${validToken}`) + .set('Content-Type', 'application/json') + .set('Accept', 'application/json, text/event-stream') + .send({ jsonrpc: '2.0', method: 'tools/list', id: 1 }); + + // Restore + serverRecord.handleMcpRequest = originalHandle; + + expect(mockLogger).toHaveBeenCalledWith( + 'Warn', + expect.stringContaining('Cannot send error response (headers already sent)'), + ); + }); + + it('should log unhandled Express error with stack trace', async () => { + // Send malformed JSON to trigger express.json() parse error, + // which calls next(err) and reaches the global error handler + await request(loggingHttpServer) + .post('/mcp') + .set('Content-Type', 'application/json') + .send('invalid json'); + + expect(mockLogger).toHaveBeenCalledWith( + 'Error', + expect.stringContaining('Unhandled error on POST /mcp'), + ); + expect(mockLogger).toHaveBeenCalledWith('Error', expect.stringContaining('Stack:')); + }); + it('should log in correct order: incoming, tool call, response', async () => { const authSecret = process.env.FOREST_AUTH_SECRET || 'test-auth-secret'; const validToken = jsonwebtoken.sign( @@ -2172,7 +2266,9 @@ describe('ForestMCPServer Instance', () => { }); const { calls } = mockLogger.mock; - const incomingIndex = calls.findIndex((c: [string, string]) => c[1] === 'Incoming POST /mcp'); + const incomingIndex = calls.findIndex((c: [string, string]) => + c[1].startsWith('Incoming POST /mcp'), + ); const toolCallIndex = calls.findIndex((c: [string, string]) => c[1].includes('Tool call: list'), );