From dd1389178c5846c8e521540ca3219d47f7e23ff2 Mon Sep 17 00:00:00 2001 From: 633WHU Date: Fri, 8 Aug 2025 23:37:10 +0800 Subject: [PATCH] Fix client-side logging bug #1394 (#1397) --- src/fastmcp/client/logging.py | 26 ++++++++- tests/client/test_logs.py | 103 ++++++++++++++++++++++++++++++++++ 2 files changed, 128 insertions(+), 1 deletion(-) diff --git a/src/fastmcp/client/logging.py b/src/fastmcp/client/logging.py index f3c323b4e..62a83db27 100644 --- a/src/fastmcp/client/logging.py +++ b/src/fastmcp/client/logging.py @@ -13,7 +13,31 @@ LogHandler: TypeAlias = Callable[[LogMessage], Awaitable[None]] async def default_log_handler(message: LogMessage) -> None: - logger.debug(f"Log received: {message}") + """Default handler that properly routes server log messages to appropriate log levels.""" + msg = message.data.get("msg", str(message)) + extra = message.data.get("extra", {}) + + # Map MCP log levels to Python logging levels + level_map = { + "debug": logger.debug, + "info": logger.info, + "notice": logger.info, # Python doesn't have 'notice', map to info + "warning": logger.warning, + "error": logger.error, + "critical": logger.critical, + "alert": logger.critical, # Map alert to critical + "emergency": logger.critical, # Map emergency to critical + } + + # Get the appropriate logging function based on the message level + log_fn = level_map.get(message.level.lower(), logger.info) + + # Include logger name if available + if message.logger: + msg = f"[{message.logger}] {msg}" + + # Log with appropriate level and extra data + log_fn(f"Server log: {msg}", extra=extra) def create_log_callback(handler: LogHandler | None = None) -> LoggingFnT: diff --git a/tests/client/test_logs.py b/tests/client/test_logs.py index 6b765cca7..d98ac725b 100644 --- a/tests/client/test_logs.py +++ b/tests/client/test_logs.py @@ -88,3 +88,106 @@ class TestClientLogs: assert caplog.records[0].levelname == "INFO" assert caplog.records[1].msg == "this is a warning log" assert caplog.records[1].levelname == "WARNING" + + +class TestDefaultLogHandler: + """Tests for default_log_handler bug fix (issue #1394).""" + + async def test_default_handler_routes_to_correct_levels(self): + """Test that default_log_handler routes server logs to appropriate Python log levels.""" + from unittest.mock import MagicMock, patch + + from mcp.types import LoggingMessageNotificationParams + + from fastmcp.client.logging import default_log_handler + + with patch("fastmcp.client.logging.logger") as mock_logger: + # Set up mock methods + mock_logger.debug = MagicMock() + mock_logger.info = MagicMock() + mock_logger.warning = MagicMock() + mock_logger.error = MagicMock() + mock_logger.critical = MagicMock() + + # Test each log level + test_cases = [ + ("debug", mock_logger.debug, "Debug message"), + ("info", mock_logger.info, "Info message"), + ("notice", mock_logger.info, "Notice message"), # notice -> info + ("warning", mock_logger.warning, "Warning message"), + ("error", mock_logger.error, "Error message"), + ("critical", mock_logger.critical, "Critical message"), + ("alert", mock_logger.critical, "Alert message"), # alert -> critical + ( + "emergency", + mock_logger.critical, + "Emergency message", + ), # emergency -> critical + ] + + for level, expected_method, msg in test_cases: + # Reset mocks + mock_logger.reset_mock() + + # Create log message + log_msg = LoggingMessageNotificationParams( + level=level, # type: ignore[arg-type] + logger="test.logger", + data={"msg": msg, "extra": {"test_key": "test_value"}}, + ) + + # Call handler + await default_log_handler(log_msg) + + # Verify correct method was called + expected_method.assert_called_once_with( + f"Server log: [test.logger] {msg}", extra={"test_key": "test_value"} + ) + + async def test_default_handler_without_logger_name(self): + """Test that default_log_handler works when logger name is None.""" + from unittest.mock import MagicMock, patch + + from mcp.types import LoggingMessageNotificationParams + + from fastmcp.client.logging import default_log_handler + + with patch("fastmcp.client.logging.logger") as mock_logger: + mock_logger.info = MagicMock() + + log_msg = LoggingMessageNotificationParams( + level="info", + logger=None, + data={"msg": "Message without logger", "extra": {}}, + ) + + await default_log_handler(log_msg) + + mock_logger.info.assert_called_once_with( + "Server log: Message without logger", extra={} + ) + + async def test_default_handler_with_missing_msg(self): + """Test that default_log_handler handles missing 'msg' gracefully.""" + from unittest.mock import MagicMock, patch + + from mcp.types import LoggingMessageNotificationParams + + from fastmcp.client.logging import default_log_handler + + with patch("fastmcp.client.logging.logger") as mock_logger: + mock_logger.info = MagicMock() + + log_msg = LoggingMessageNotificationParams( + level="info", + logger="test.logger", + data={"extra": {"key": "value"}}, # Missing 'msg' key + ) + + await default_log_handler(log_msg) + + # Should use str(message) as fallback + mock_logger.info.assert_called_once() + call_args = mock_logger.info.call_args + assert "Server log:" in call_args[0][0] + assert call_args[1]["extra"] == {"key": "value"}