From 043fd8468b5e4a921d6a97f56b48472e78c12355 Mon Sep 17 00:00:00 2001 From: weiguangli-io Date: Sat, 2 May 2026 20:29:11 +0800 Subject: [PATCH] fix: configure_logging uses named 'mcp' logger instead of root logger (#2527) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously configure_logging() called logging.basicConfig(), which adds a RichHandler at INFO level to the **root** logger. This caused every library (httpx, urllib3, openai, …) to emit INFO records through Rich → stderr. In stdio MCP servers spawned by Node.js hosts (Claude Desktop, Cline, …) the kernel's stderr SNDBUF (8 KB on macOS) fills under modest log volume, and write(2) blocks the asyncio event loop, deadlocking the server. Changes: - configure_logging() now targets logging.getLogger("mcp") instead of the root logger via basicConfig. - Sets mcp_logger.propagate = False so records don't reach any root handlers. - Made idempotent: skips setup if the mcp logger already has handlers, allowing application code to configure logging before MCPServer.__init__. - Default log level changed from "INFO" to "WARNING" to reduce noise from MCP's own internals in production/stdio deployments. - MCPServer.__init__ log_level parameter default also changed to "WARNING". - Added regression tests in tests/issues/test_2527_fastmcp_logger_pollution.py. Fixes #2527 Co-Authored-By: Claude Opus 4.6 (1M context) --- src/mcp/server/mcpserver/server.py | 2 +- src/mcp/server/mcpserver/utilities/logging.py | 33 +++++-- .../test_2527_fastmcp_logger_pollution.py | 91 +++++++++++++++++++ 3 files changed, 116 insertions(+), 10 deletions(-) create mode 100644 tests/issues/test_2527_fastmcp_logger_pollution.py diff --git a/src/mcp/server/mcpserver/server.py b/src/mcp/server/mcpserver/server.py index be77705da..26a1a6eb6 100644 --- a/src/mcp/server/mcpserver/server.py +++ b/src/mcp/server/mcpserver/server.py @@ -142,7 +142,7 @@ def __init__( tools: list[Tool] | None = None, resources: list[Resource] | None = None, debug: bool = False, - log_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] = "INFO", + log_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] = "WARNING", warn_on_duplicate_resources: bool = True, warn_on_duplicate_tools: bool = True, warn_on_duplicate_prompts: bool = True, diff --git a/src/mcp/server/mcpserver/utilities/logging.py b/src/mcp/server/mcpserver/utilities/logging.py index 04ca38853..787cbdc2b 100644 --- a/src/mcp/server/mcpserver/utilities/logging.py +++ b/src/mcp/server/mcpserver/utilities/logging.py @@ -17,23 +17,38 @@ def get_logger(name: str) -> logging.Logger: def configure_logging( - level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] = "INFO", + level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] = "WARNING", ) -> None: """Configure logging for MCP. + Configures the ``mcp`` logger (not the root logger) so that library code + does not accidentally install handlers on the root namespace. This keeps + third-party libraries (httpx, urllib3, …) from routing their INFO-level + output through a RichHandler that writes to stderr, which can fill the + kernel's stderr SNDBUF and deadlock a stdio-transport MCP server under + back-pressure from the host process. + + The function is idempotent: if the ``mcp`` logger already has handlers the + call is a no-op, allowing application code to configure logging before + instantiating :class:`~mcp.server.mcpserver.server.MCPServer`. + Args: - level: The log level to use. + level: The log level to use (default ``"WARNING"``). """ - handlers: list[logging.Handler] = [] + mcp_logger = logging.getLogger("mcp") + + # Idempotent: skip if already configured. + if mcp_logger.handlers: + return + try: from rich.console import Console from rich.logging import RichHandler - handlers.append(RichHandler(console=Console(stderr=True), rich_tracebacks=True)) + mcp_logger.addHandler(RichHandler(console=Console(stderr=True), rich_tracebacks=True)) except ImportError: # pragma: no cover - pass - - if not handlers: # pragma: no cover - handlers.append(logging.StreamHandler()) + mcp_logger.addHandler(logging.StreamHandler()) - logging.basicConfig(level=level, format="%(message)s", handlers=handlers) + mcp_logger.setLevel(level) + # Do not propagate to the root logger; we own our own handler. + mcp_logger.propagate = False diff --git a/tests/issues/test_2527_fastmcp_logger_pollution.py b/tests/issues/test_2527_fastmcp_logger_pollution.py new file mode 100644 index 000000000..97b68d264 --- /dev/null +++ b/tests/issues/test_2527_fastmcp_logger_pollution.py @@ -0,0 +1,91 @@ +"""Test for issue #2527: MCPServer.__init__ must not pollute the root logger. + +Regression test verifying that: +1. Instantiating MCPServer does NOT add any handlers to the root logger. +2. configure_logging() targets the "mcp" logger, not the root logger. +3. configure_logging() is idempotent (calling it twice doesn't add a second handler). +4. The "mcp" logger does not propagate to the root logger after configure_logging(). +""" + +import logging + +import pytest + +from mcp.server.mcpserver.utilities.logging import configure_logging + + +def test_configure_logging_does_not_touch_root_logger(): + """configure_logging() must not add handlers to the root logger.""" + root = logging.getLogger() + handlers_before = list(root.handlers) + + # Call explicitly; MCPServer.__init__ calls this too. + configure_logging() + + assert root.handlers == handlers_before, ( + "configure_logging() added a handler to the root logger, which pollutes " + "all third-party loggers and can deadlock stdio servers under back-pressure." + ) + + +def test_configure_logging_adds_handler_to_mcp_logger(): + """configure_logging() must add a handler to the 'mcp' logger.""" + mcp_logger = logging.getLogger("mcp") + # Remove any handlers that may have been added by a previous test run. + mcp_logger.handlers.clear() + mcp_logger.propagate = True # reset + + configure_logging() + + assert mcp_logger.handlers, "configure_logging() did not add any handler to the 'mcp' logger." + + +def test_configure_logging_sets_propagate_false(): + """The 'mcp' logger must not propagate to root after configure_logging().""" + mcp_logger = logging.getLogger("mcp") + mcp_logger.handlers.clear() + mcp_logger.propagate = True # reset + + configure_logging() + + assert not mcp_logger.propagate, ( + "mcp logger propagates to root; any INFO log from mcp can reach third-party " + "root handlers and cause back-pressure on stdio stderr." + ) + + +def test_configure_logging_is_idempotent(): + """Calling configure_logging() twice must not add a second handler.""" + mcp_logger = logging.getLogger("mcp") + mcp_logger.handlers.clear() + mcp_logger.propagate = True # reset + + configure_logging() + handler_count_after_first = len(mcp_logger.handlers) + + configure_logging() + handler_count_after_second = len(mcp_logger.handlers) + + assert handler_count_after_first == handler_count_after_second, ( + "configure_logging() is not idempotent: calling it twice added extra handlers." + ) + + +def test_mcpserver_init_does_not_pollute_root_logger(): + """MCPServer() must not add handlers to the root logger.""" + # Remove any mcp logger handlers first so configure_logging runs fresh. + mcp_logger = logging.getLogger("mcp") + mcp_logger.handlers.clear() + + root = logging.getLogger() + handlers_before = list(root.handlers) + + # Import here to avoid side-effects at module import time. + from mcp.server.mcpserver.server import MCPServer + + MCPServer("test-server") + + assert root.handlers == handlers_before, ( + "MCPServer.__init__ added a handler to the root logger. " + "This pollutes all third-party loggers and can deadlock stdio servers." + )