Fix client-side logging bug #1394 (#1397)

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:

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"}