diff --git a/packages/mcp-server/src/server.ts b/packages/mcp-server/src/server.ts index d8ba6d32e..a0555abd1 100644 --- a/packages/mcp-server/src/server.ts +++ b/packages/mcp-server/src/server.ts @@ -260,6 +260,12 @@ export default class ForestMCPServer { interceptResponseForErrorLogging(res, this.logger); await this.mcpTransport.handleRequest(req, res, req.body); + + // The Hono adapter inside @modelcontextprotocol/sdk catches errors internally + // and writes 500 directly to the response without logging. Detect and log these. + if (res.statusCode >= 500) { + this.logger('Error', `Transport returned HTTP ${res.statusCode} for [${rpcMethod}]`); + } } /** diff --git a/packages/mcp-server/src/utils/sse-error-logger.ts b/packages/mcp-server/src/utils/sse-error-logger.ts index 34649d6b2..8443b002d 100644 --- a/packages/mcp-server/src/utils/sse-error-logger.ts +++ b/packages/mcp-server/src/utils/sse-error-logger.ts @@ -129,6 +129,7 @@ function logChunkErrors( export default function interceptResponseForErrorLogging(res: Response, logger: Logger): void { const originalWrite = res.write.bind(res); const originalEnd = res.end.bind(res); + const chunks: string[] = []; // Intercept streaming chunks (res.write) res.write = function interceptedWrite( @@ -138,6 +139,12 @@ export default function interceptResponseForErrorLogging(res: Response, logger: ): boolean { logChunkErrors(chunk, logger); + try { + if (chunk != null) chunks.push(chunkToString(chunk)); + } catch { + // Never affect the response + } + return originalWrite(chunk, encodingOrCallback as BufferEncoding, callback); } as typeof res.write; @@ -149,8 +156,28 @@ export default function interceptResponseForErrorLogging(res: Response, logger: ): typeof res { if (chunk && typeof chunk !== 'function') { logChunkErrors(chunk as Buffer | string | Uint8Array, logger); + + try { + chunks.push(chunkToString(chunk as Buffer | string | Uint8Array)); + } catch { + // Never affect the response + } + } + + const result = originalEnd(chunk, encodingOrCallback as BufferEncoding, callback); + + // Log the response body when the transport returns HTTP 500+ + // The Hono adapter inside @modelcontextprotocol/sdk catches errors internally + // and writes 500 directly to the response. This captures those silent errors. + try { + if (res.statusCode >= 500) { + const body = chunks.join(''); + logger('Error', `HTTP ${res.statusCode} response body: ${body || '(empty)'}`); + } + } catch { + // Never affect the response } - return originalEnd(chunk, encodingOrCallback as BufferEncoding, callback); + return result; } as typeof res.end; } diff --git a/packages/mcp-server/test/server.test.ts b/packages/mcp-server/test/server.test.ts index 8eb57b019..71dc52e49 100644 --- a/packages/mcp-server/test/server.test.ts +++ b/packages/mcp-server/test/server.test.ts @@ -2224,6 +2224,44 @@ describe('ForestMCPServer Instance', () => { ); }); + it('should log when transport silently returns HTTP 500', 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 transport.handleRequest to set 500 without throwing (simulates Hono adapter error) + const transport = loggingServer.mcpTransport as NonNullable< + typeof loggingServer.mcpTransport + >; + const originalHandleRequest = transport.handleRequest; + + transport.handleRequest = async ( + _req: unknown, + res: { statusCode: number; end: () => void }, + ) => { + res.statusCode = 500; + res.end(); + }; + + 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: 'notifications/initialized', id: 1 }); + + // Restore + transport.handleRequest = originalHandleRequest; + + expect(mockLogger).toHaveBeenCalledWith( + 'Error', + 'Transport returned HTTP 500 for [notifications/initialized]', + ); + }); + 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 diff --git a/packages/mcp-server/test/utils/sse-error-logger.test.ts b/packages/mcp-server/test/utils/sse-error-logger.test.ts new file mode 100644 index 000000000..5fc0f1288 --- /dev/null +++ b/packages/mcp-server/test/utils/sse-error-logger.test.ts @@ -0,0 +1,179 @@ +import type { Logger } from '../../src/server'; +import type { Response } from 'express'; + +import interceptResponseForErrorLogging from '../../src/utils/sse-error-logger'; + +function createMockResponse(): Response { + const res = { + statusCode: 200, + write: jest.fn(), + end: jest.fn(), + } as unknown as Response; + + return res; +} + +describe('interceptResponseForErrorLogging', () => { + let logger: jest.MockedFunction; + let res: Response; + + beforeEach(() => { + logger = jest.fn(); + res = createMockResponse(); + interceptResponseForErrorLogging(res, logger); + }); + + describe('SSE error logging (existing behavior)', () => { + it('should log JSON-RPC errors from SSE data on write', () => { + res.write('event: message\ndata: {"error":{"message":"Something went wrong"}}\n\n'); + + expect(logger).toHaveBeenCalledWith('Error', 'Something went wrong'); + }); + + it('should log tool errors from SSE data on write', () => { + const sseData = + 'event: message\ndata: {"result":{"isError":true,"content":[{"text":"Tool failed"}]}}\n\n'; + res.write(sseData); + + expect(logger).toHaveBeenCalledWith('Error', 'Tool error: Tool failed'); + }); + + it('should log JSON-RPC errors from SSE data on end', () => { + res.end('event: message\ndata: {"error":{"message":"Final error"}}\n\n'); + + expect(logger).toHaveBeenCalledWith('Error', 'Final error'); + }); + + it('should not log for non-SSE data on write', () => { + res.write('just some plain text'); + + expect(logger).not.toHaveBeenCalled(); + }); + }); + + describe('HTTP 500 body logging', () => { + it('should log response body when status is 500', () => { + res.statusCode = 500; + res.end('Error: stream failed'); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: stream failed'); + }); + + it('should log concatenated body from write + end chunks', () => { + res.statusCode = 500; + res.write('Error: '); + res.end('stream failed'); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: stream failed'); + }); + + it('should log (empty) when 500 has no body', () => { + res.statusCode = 500; + res.end(); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: (empty)'); + }); + + it('should log body from multiple write chunks on 500', () => { + res.statusCode = 502; + res.write('chunk1'); + res.write('chunk2'); + res.end('chunk3'); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 502 response body: chunk1chunk2chunk3'); + }); + + it('should handle Buffer chunks on end', () => { + res.statusCode = 500; + res.end(Buffer.from('Error: buffer content')); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: buffer content'); + }); + + it('should handle Buffer chunks on write', () => { + res.statusCode = 500; + res.write(Buffer.from('buffered ')); + res.end('end'); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: buffered end'); + }); + + it('should handle Uint8Array chunks on 500', () => { + res.statusCode = 500; + res.end(new Uint8Array(Buffer.from('Error: uint8 content'))); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: uint8 content'); + }); + + it('should log all accumulated chunks even when status changes to 500 after write', () => { + res.statusCode = 200; + res.write('early chunk'); + res.statusCode = 500; + res.end('late chunk'); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: early chunklate chunk'); + }); + + it('should not log body when status is 200', () => { + res.statusCode = 200; + res.write('some response data'); + res.end(); + + expect(logger).not.toHaveBeenCalledWith('Error', expect.stringContaining('response body')); + }); + + it('should not log body when status is 400', () => { + res.statusCode = 400; + res.end('{"error":"bad request"}'); + + expect(logger).not.toHaveBeenCalledWith('Error', expect.stringContaining('response body')); + }); + + it('should not log body when status is 499', () => { + res.statusCode = 499; + res.end('some body'); + + expect(logger).not.toHaveBeenCalledWith('Error', expect.stringContaining('response body')); + }); + }); + + describe('passthrough behavior', () => { + it('should call original write with same arguments and return its result', () => { + const originalWrite = jest.fn().mockReturnValue(true); + const mockRes = { + statusCode: 200, + write: originalWrite, + end: jest.fn(), + } as unknown as Response; + interceptResponseForErrorLogging(mockRes, logger); + + const result = mockRes.write('data'); + + expect(originalWrite).toHaveBeenCalledWith('data', undefined, undefined); + expect(result).toBe(true); + }); + + it('should call original end with same arguments and return its result', () => { + const originalEnd = jest.fn(); + const mockRes = { + statusCode: 200, + write: jest.fn(), + end: originalEnd, + } as unknown as Response; + originalEnd.mockReturnValue(mockRes); + interceptResponseForErrorLogging(mockRes, logger); + + const result = mockRes.end('final'); + + expect(originalEnd).toHaveBeenCalledWith('final', undefined, undefined); + expect(result).toBe(mockRes); + }); + + it('should treat function callback as non-body content and log (empty) on 500', () => { + res.statusCode = 500; + res.end(() => {}); + + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: (empty)'); + }); + }); +});