Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions packages/mcp-server/src/server.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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}]`);
}
}

/**
Expand Down
29 changes: 28 additions & 1 deletion packages/mcp-server/src/utils/sse-error-logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand All @@ -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;

Expand All @@ -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;
}
38 changes: 38 additions & 0 deletions packages/mcp-server/test/server.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
179 changes: 179 additions & 0 deletions packages/mcp-server/test/utils/sse-error-logger.test.ts
Original file line number Diff line number Diff line change
@@ -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<Logger>;
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)');
});
});
});
Loading