From 148190e9855586a765d99565b14ad5abce8da585 Mon Sep 17 00:00:00 2001 From: alban bertolini Date: Wed, 11 Feb 2026 14:12:58 +0100 Subject: [PATCH 1/4] fix(mcp-server): add diagnostic logging for silent HTTP 500 from transport The Hono adapter inside @modelcontextprotocol/sdk catches errors internally and writes 500 directly to the response without going through our logger. This makes debugging impossible when the transport returns 500. Add two diagnostic log points: - Capture and log the HTTP response body when status >= 500 - Log after handleRequest when the transport returned a 500 Co-Authored-By: Claude Opus 4.6 --- packages/mcp-server/src/server.ts | 6 ++++ .../mcp-server/src/utils/sse-error-logger.ts | 29 ++++++++++++++++++- 2 files changed, 34 insertions(+), 1 deletion(-) 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; } From 0084630947961bad245309c2bbc96eb0b0c350da Mon Sep 17 00:00:00 2001 From: alban bertolini Date: Wed, 11 Feb 2026 14:16:38 +0100 Subject: [PATCH 2/4] test(mcp-server): add unit tests for response error logging interceptor Co-Authored-By: Claude Opus 4.6 --- .../test/utils/sse-error-logger.test.ts | 154 ++++++++++++++++++ 1 file changed, 154 insertions(+) create mode 100644 packages/mcp-server/test/utils/sse-error-logger.test.ts 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..a35200c75 --- /dev/null +++ b/packages/mcp-server/test/utils/sse-error-logger.test.ts @@ -0,0 +1,154 @@ +import type { Response } from 'express'; +import type { Logger } from '../../src/server'; + +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 500', () => { + res.statusCode = 500; + res.end(Buffer.from('Error: buffer content')); + + expect(logger).toHaveBeenCalledWith( + 'Error', + 'HTTP 500 response body: Error: buffer content', + ); + }); + + it('should not log body when status is 200', () => { + res.statusCode = 200; + res.write('some response data'); + res.end(); + + const httpBodyCalls = (logger.mock.calls as [string, string][]).filter(([, msg]) => + msg.startsWith('HTTP'), + ); + expect(httpBodyCalls).toHaveLength(0); + }); + + it('should not log body when status is 400', () => { + res.statusCode = 400; + res.end('{"error":"bad request"}'); + + const httpBodyCalls = (logger.mock.calls as [string, string][]).filter(([, msg]) => + msg.startsWith('HTTP'), + ); + expect(httpBodyCalls).toHaveLength(0); + }); + }); + + describe('passthrough behavior', () => { + it('should call original write 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 and return res', () => { + 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).toHaveBeenCalled(); + expect(result).toBe(mockRes); + }); + + it('should not throw when end is called with a function callback', () => { + res.statusCode = 500; + + expect(() => res.end(() => {})).not.toThrow(); + }); + }); +}); From 1c4726eeed5304b6f7170c19b8e32626a7245012 Mon Sep 17 00:00:00 2001 From: alban bertolini Date: Wed, 11 Feb 2026 14:23:01 +0100 Subject: [PATCH 3/4] test(mcp-server): improve test coverage and assertion quality Add edge case tests (Buffer, Uint8Array, late status change, boundary statuses) and strengthen assertions per review feedback. Co-Authored-By: Claude Opus 4.6 --- .../test/utils/sse-error-logger.test.ts | 83 ++++++++++++------- 1 file changed, 54 insertions(+), 29 deletions(-) diff --git a/packages/mcp-server/test/utils/sse-error-logger.test.ts b/packages/mcp-server/test/utils/sse-error-logger.test.ts index a35200c75..5fc0f1288 100644 --- a/packages/mcp-server/test/utils/sse-error-logger.test.ts +++ b/packages/mcp-server/test/utils/sse-error-logger.test.ts @@ -1,5 +1,5 @@ -import type { Response } from 'express'; import type { Logger } from '../../src/server'; +import type { Response } from 'express'; import interceptResponseForErrorLogging from '../../src/utils/sse-error-logger'; @@ -56,10 +56,7 @@ describe('interceptResponseForErrorLogging', () => { res.statusCode = 500; res.end('Error: stream failed'); - expect(logger).toHaveBeenCalledWith( - 'Error', - 'HTTP 500 response body: Error: stream failed', - ); + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: stream failed'); }); it('should log concatenated body from write + end chunks', () => { @@ -67,10 +64,7 @@ describe('interceptResponseForErrorLogging', () => { res.write('Error: '); res.end('stream failed'); - expect(logger).toHaveBeenCalledWith( - 'Error', - 'HTTP 500 response body: Error: stream failed', - ); + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: Error: stream failed'); }); it('should log (empty) when 500 has no body', () => { @@ -89,14 +83,35 @@ describe('interceptResponseForErrorLogging', () => { expect(logger).toHaveBeenCalledWith('Error', 'HTTP 502 response body: chunk1chunk2chunk3'); }); - it('should handle Buffer chunks on 500', () => { + 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', - ); + 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', () => { @@ -104,27 +119,32 @@ describe('interceptResponseForErrorLogging', () => { res.write('some response data'); res.end(); - const httpBodyCalls = (logger.mock.calls as [string, string][]).filter(([, msg]) => - msg.startsWith('HTTP'), - ); - expect(httpBodyCalls).toHaveLength(0); + 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"}'); - const httpBodyCalls = (logger.mock.calls as [string, string][]).filter(([, msg]) => - msg.startsWith('HTTP'), - ); - expect(httpBodyCalls).toHaveLength(0); + 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 and return its result', () => { + 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; + const mockRes = { + statusCode: 200, + write: originalWrite, + end: jest.fn(), + } as unknown as Response; interceptResponseForErrorLogging(mockRes, logger); const result = mockRes.write('data'); @@ -133,22 +153,27 @@ describe('interceptResponseForErrorLogging', () => { expect(result).toBe(true); }); - it('should call original end and return res', () => { + 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; + 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).toHaveBeenCalled(); + expect(originalEnd).toHaveBeenCalledWith('final', undefined, undefined); expect(result).toBe(mockRes); }); - it('should not throw when end is called with a function callback', () => { + it('should treat function callback as non-body content and log (empty) on 500', () => { res.statusCode = 500; + res.end(() => {}); - expect(() => res.end(() => {})).not.toThrow(); + expect(logger).toHaveBeenCalledWith('Error', 'HTTP 500 response body: (empty)'); }); }); }); From f28b6921da6fe1d7689ebb9252f5e37a475f640d Mon Sep 17 00:00:00 2001 From: alban bertolini Date: Wed, 11 Feb 2026 14:36:10 +0100 Subject: [PATCH 4/4] test(mcp-server): add test for silent HTTP 500 from transport Co-Authored-By: Claude Opus 4.6 --- packages/mcp-server/test/server.test.ts | 38 +++++++++++++++++++++++++ 1 file changed, 38 insertions(+) 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