From 1ec2bd7d925887578e890cd89b595e42a4fa12ef Mon Sep 17 00:00:00 2001 From: William Easton Date: Tue, 14 Oct 2025 13:38:26 -0500 Subject: [PATCH] Also push client messages (info/warn/debug) to server debug log (#2063) Co-authored-by: William Easton Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> Co-authored-by: claude[bot] <41898282+claude[bot]@users.noreply.github.com> Co-authored-by: Jeremiah Lowin <153965+jlowin@users.noreply.github.com> --- docs/servers/logging.mdx | 29 ++++++--- src/fastmcp/client/logging.py | 26 ++++---- src/fastmcp/server/context.py | 104 ++++++++++++++++++++++++++----- src/fastmcp/utilities/logging.py | 89 +++++++++++++++++++++++++- tests/client/test_logs.py | 13 ++-- tests/server/test_context.py | 5 +- 6 files changed, 223 insertions(+), 43 deletions(-) diff --git a/docs/servers/logging.mdx b/docs/servers/logging.mdx index 6e27aa72d..23283b083 100644 --- a/docs/servers/logging.mdx +++ b/docs/servers/logging.mdx @@ -1,5 +1,5 @@ --- -title: Server Logging +title: Client Logging sidebarTitle: Logging description: Send log messages back to MCP clients through the context. icon: receipt @@ -71,12 +71,25 @@ async def process_transaction(transaction_id: str, amount: float, ctx: Context): # ... processing logic ... ``` +## Server Logs + +Client Logging in the form of `ctx.log()` and its convenience methods (`debug`, `info`, `warning`, `error`) are meant for sending messages to the MCP clients. Messages sent to clients are also logged to the server's log at `DEBUG` level. Enable debug logging on the server or enable debug logging on the `fastmcp.server.context.to_client` logger to see these messages in the server's log. + +```python +import logging + +from fastmcp.utilities.logging import get_logger + +to_client_logger = get_logger(name="fastmcp.server.context.to_client") +to_client_logger.setLevel(level=logging.DEBUG) +``` + ## Logging Methods Send debug-level messages for detailed execution information - + The debug message to send to the client @@ -89,7 +102,7 @@ async def process_transaction(transaction_id: str, amount: float, ctx: Context): Send informational messages about normal execution - + The information message to send to the client @@ -102,7 +115,7 @@ async def process_transaction(transaction_id: str, amount: float, ctx: Context): Send warning messages for potential issues that didn't prevent execution - + The warning message to send to the client @@ -115,7 +128,7 @@ async def process_transaction(transaction_id: str, amount: float, ctx: Context): Send error messages for problems that occurred during execution - + The error message to send to the client @@ -128,16 +141,16 @@ async def process_transaction(transaction_id: str, amount: float, ctx: Context): Generic logging method with custom level and logger name - + The log level for the message - + The message to send to the client - + Optional custom logger name for categorizing messages diff --git a/src/fastmcp/client/logging.py b/src/fastmcp/client/logging.py index 62a83db27..6451591c5 100644 --- a/src/fastmcp/client/logging.py +++ b/src/fastmcp/client/logging.py @@ -1,4 +1,5 @@ from collections.abc import Awaitable, Callable +from logging import Logger from typing import TypeAlias from mcp.client.session import LoggingFnT @@ -6,7 +7,8 @@ from mcp.types import LoggingMessageNotificationParams from fastmcp.utilities.logging import get_logger -logger = get_logger(__name__) +logger: Logger = get_logger(name=__name__) +from_server_logger: Logger = get_logger(name="fastmcp.client.from_server") LogMessage: TypeAlias = LoggingMessageNotificationParams LogHandler: TypeAlias = Callable[[LogMessage], Awaitable[None]] @@ -19,25 +21,27 @@ async def default_log_handler(message: LogMessage) -> None: # 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 + "debug": from_server_logger.debug, + "info": from_server_logger.info, + "notice": from_server_logger.info, # Python doesn't have 'notice', map to info + "warning": from_server_logger.warning, + "error": from_server_logger.error, + "critical": from_server_logger.critical, + "alert": from_server_logger.critical, # Map alert to critical + "emergency": from_server_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 + msg_prefix: str = f"Received {message.level.upper()} from server" + if message.logger: - msg = f"[{message.logger}] {msg}" + msg_prefix += f" ({message.logger})" # Log with appropriate level and extra data - log_fn(f"Server log: {msg}", extra=extra) + log_fn(msg=f"{msg_prefix}: {msg}", extra=extra) def create_log_callback(handler: LogHandler | None = None) -> LoggingFnT: diff --git a/src/fastmcp/server/context.py b/src/fastmcp/server/context.py index c1b39b805..8b46b7a0d 100644 --- a/src/fastmcp/server/context.py +++ b/src/fastmcp/server/context.py @@ -3,13 +3,16 @@ from __future__ import annotations import asyncio import copy import inspect +import logging import warnings import weakref +from asyncio.locks import Lock from collections.abc import Generator, Mapping, Sequence from contextlib import contextmanager from contextvars import ContextVar, Token from dataclasses import dataclass from enum import Enum +from logging import Logger from typing import Any, Literal, cast, get_origin, overload from mcp import LoggingLevel, ServerSession @@ -44,14 +47,21 @@ from fastmcp.server.elicitation import ( get_elicitation_schema, ) from fastmcp.server.server import FastMCP -from fastmcp.utilities.logging import get_logger +from fastmcp.utilities.logging import _clamp_logger, get_logger from fastmcp.utilities.types import get_cached_typeadapter -logger = get_logger(__name__) +logger: Logger = get_logger(name=__name__) +to_client_logger: Logger = logger.getChild(suffix="to_client") + +# Convert all levels of server -> client messages to debug level +# This clamp can be undone at runtime by calling `_unclamp_logger` or calling +# `_clamp_logger` with a different max level. +_clamp_logger(logger=to_client_logger, max_level="DEBUG") + T = TypeVar("T", default=Any) _current_context: ContextVar[Context | None] = ContextVar("context", default=None) # type: ignore[assignment] -_flush_lock = asyncio.Lock() +_flush_lock: Lock = asyncio.Lock() @dataclass @@ -66,6 +76,18 @@ class LogData: extra: Mapping[str, Any] | None = None +_mcp_level_to_python_level = { + "debug": logging.DEBUG, + "info": logging.INFO, + "notice": logging.INFO, + "warning": logging.WARNING, + "error": logging.ERROR, + "critical": logging.CRITICAL, + "alert": logging.CRITICAL, + "emergency": logging.CRITICAL, +} + + @contextmanager def set_context(context: Context) -> Generator[Context, None, None]: token = _current_context.set(context) @@ -216,6 +238,8 @@ class Context: ) -> None: """Send a log message to the client. + Messages sent to Clients are also logged to the `fastmcp.server.context.to_client` logger with a level of `DEBUG`. + Args: message: Log message level: Optional log level. One of "debug", "info", "notice", "warning", "error", "critical", @@ -223,13 +247,13 @@ class Context: logger_name: Optional logger name extra: Optional mapping for additional arguments """ - if level is None: - level = "info" data = LogData(msg=message, extra=extra) - await self.session.send_log_message( - level=level, + + await _log_to_server_and_client( data=data, - logger=logger_name, + session=self.session, + level=level or "info", + logger_name=logger_name, related_request_id=self.request_id, ) @@ -303,9 +327,14 @@ class Context: logger_name: str | None = None, extra: Mapping[str, Any] | None = None, ) -> None: - """Send a debug log message.""" + """Send a `DEBUG`-level message to the connected MCP Client. + + Messages sent to Clients are also logged to the `fastmcp.server.context.to_client` logger with a level of `DEBUG`.""" await self.log( - level="debug", message=message, logger_name=logger_name, extra=extra + level="debug", + message=message, + logger_name=logger_name, + extra=extra, ) async def info( @@ -314,9 +343,14 @@ class Context: logger_name: str | None = None, extra: Mapping[str, Any] | None = None, ) -> None: - """Send an info log message.""" + """Send a `INFO`-level message to the connected MCP Client. + + Messages sent to Clients are also logged to the `fastmcp.server.context.to_client` logger with a level of `DEBUG`.""" await self.log( - level="info", message=message, logger_name=logger_name, extra=extra + level="info", + message=message, + logger_name=logger_name, + extra=extra, ) async def warning( @@ -325,9 +359,14 @@ class Context: logger_name: str | None = None, extra: Mapping[str, Any] | None = None, ) -> None: - """Send a warning log message.""" + """Send a `WARNING`-level message to the connected MCP Client. + + Messages sent to Clients are also logged to the `fastmcp.server.context.to_client` logger with a level of `DEBUG`.""" await self.log( - level="warning", message=message, logger_name=logger_name, extra=extra + level="warning", + message=message, + logger_name=logger_name, + extra=extra, ) async def error( @@ -336,9 +375,14 @@ class Context: logger_name: str | None = None, extra: Mapping[str, Any] | None = None, ) -> None: - """Send an error log message.""" + """Send a `ERROR`-level message to the connected MCP Client. + + Messages sent to Clients are also logged to the `fastmcp.server.context.to_client` logger with a level of `DEBUG`.""" await self.log( - level="error", message=message, logger_name=logger_name, extra=extra + level="error", + message=message, + logger_name=logger_name, + extra=extra, ) async def list_roots(self) -> list[Root]: @@ -675,3 +719,31 @@ def _parse_model_preferences( raise ValueError( "model_preferences must be one of: ModelPreferences, str, list[str], or None." ) + + +async def _log_to_server_and_client( + data: LogData, + session: ServerSession, + level: LoggingLevel, + logger_name: str | None = None, + related_request_id: str | None = None, +) -> None: + """Log a message to the server and client.""" + + msg_prefix = f"Sending {level.upper()} to client" + + if logger_name: + msg_prefix += f" ({logger_name})" + + to_client_logger.log( + level=_mcp_level_to_python_level[level], + msg=f"{msg_prefix}: {data.msg}", + extra=data.extra, + ) + + await session.send_log_message( + level=level, + data=data, + logger=logger_name, + related_request_id=related_request_id, + ) diff --git a/src/fastmcp/utilities/logging.py b/src/fastmcp/utilities/logging.py index ec7f47023..b6c83fa4a 100644 --- a/src/fastmcp/utilities/logging.py +++ b/src/fastmcp/utilities/logging.py @@ -6,6 +6,7 @@ from typing import Any, Literal, cast from rich.console import Console from rich.logging import RichHandler +from typing_extensions import override import fastmcp @@ -19,7 +20,10 @@ def get_logger(name: str) -> logging.Logger: Returns: a configured logger instance """ - return logging.getLogger(f"fastmcp.{name}") + if name.startswith("fastmcp."): + return logging.getLogger(name=name) + + return logging.getLogger(name=f"fastmcp.{name}") def configure_logging( @@ -141,3 +145,86 @@ def temporary_log_level( ) else: yield + + +class _ClampedLogFilter(logging.Filter): + min_level: tuple[int, str] | None + max_level: tuple[int, str] | None + + def __init__( + self, + min_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] + | None = None, + max_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] + | None = None, + ): + self.min_level = None + self.max_level = None + + if min_level_no := self._level_to_no(level=min_level): + self.min_level = (min_level_no, str(min_level)) + if max_level_no := self._level_to_no(level=max_level): + self.max_level = (max_level_no, str(max_level)) + + super().__init__() + + def _level_to_no( + self, level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] | None + ) -> int | None: + if level == "DEBUG": + return logging.DEBUG + elif level == "INFO": + return logging.INFO + elif level == "WARNING": + return logging.WARNING + elif level == "ERROR": + return logging.ERROR + elif level == "CRITICAL": + return logging.CRITICAL + else: + return None + + @override + def filter(self, record: logging.LogRecord) -> bool: + if self.max_level: + max_level_no, max_level_name = self.max_level + + if record.levelno > max_level_no: + record.levelno = max_level_no + record.levelname = max_level_name + return True + + if self.min_level: + min_level_no, min_level_name = self.min_level + if record.levelno < min_level_no: + record.levelno = min_level_no + record.levelname = min_level_name + return True + + return True + + +def _clamp_logger( + logger: logging.Logger, + min_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] | None = None, + max_level: Literal["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"] | None = None, +) -> None: + """Clamp the logger to a minimum and maximum level. + + If min_level is provided, messages logged at a lower level than `min_level` will have their level increased to `min_level`. + If max_level is provided, messages logged at a higher level than `max_level` will have their level decreased to `max_level`. + + Args: + min_level: The lower bound of the clamp + max_level: The upper bound of the clamp + """ + _unclamp_logger(logger=logger) + + logger.addFilter(filter=_ClampedLogFilter(min_level=min_level, max_level=max_level)) + + +def _unclamp_logger(logger: logging.Logger) -> None: + """Remove all clamped log filters from the logger.""" + for filter in logger.filters[:]: + if isinstance(filter, _ClampedLogFilter): + logger.removeFilter(filter) diff --git a/tests/client/test_logs.py b/tests/client/test_logs.py index d98ac725b..f7f728515 100644 --- a/tests/client/test_logs.py +++ b/tests/client/test_logs.py @@ -101,7 +101,7 @@ class TestDefaultLogHandler: from fastmcp.client.logging import default_log_handler - with patch("fastmcp.client.logging.logger") as mock_logger: + with patch("fastmcp.client.logging.from_server_logger") as mock_logger: # Set up mock methods mock_logger.debug = MagicMock() mock_logger.info = MagicMock() @@ -141,7 +141,8 @@ class TestDefaultLogHandler: # Verify correct method was called expected_method.assert_called_once_with( - f"Server log: [test.logger] {msg}", extra={"test_key": "test_value"} + msg=f"Received {level.upper()} from server (test.logger): {msg}", + extra={"test_key": "test_value"}, ) async def test_default_handler_without_logger_name(self): @@ -152,7 +153,7 @@ class TestDefaultLogHandler: from fastmcp.client.logging import default_log_handler - with patch("fastmcp.client.logging.logger") as mock_logger: + with patch("fastmcp.client.logging.from_server_logger") as mock_logger: mock_logger.info = MagicMock() log_msg = LoggingMessageNotificationParams( @@ -164,7 +165,7 @@ class TestDefaultLogHandler: await default_log_handler(log_msg) mock_logger.info.assert_called_once_with( - "Server log: Message without logger", extra={} + msg="Received INFO from server: Message without logger", extra={} ) async def test_default_handler_with_missing_msg(self): @@ -175,7 +176,7 @@ class TestDefaultLogHandler: from fastmcp.client.logging import default_log_handler - with patch("fastmcp.client.logging.logger") as mock_logger: + with patch("fastmcp.client.logging.from_server_logger") as mock_logger: mock_logger.info = MagicMock() log_msg = LoggingMessageNotificationParams( @@ -189,5 +190,5 @@ class TestDefaultLogHandler: # 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 "Received INFO from server" in call_args[1]["msg"] assert call_args[1]["extra"] == {"key": "value"} diff --git a/tests/server/test_context.py b/tests/server/test_context.py index 97c2c51b7..b0a7fc4c4 100644 --- a/tests/server/test_context.py +++ b/tests/server/test_context.py @@ -5,7 +5,10 @@ import pytest from mcp.types import ModelPreferences from starlette.requests import Request -from fastmcp.server.context import Context, _parse_model_preferences +from fastmcp.server.context import ( + Context, + _parse_model_preferences, +) from fastmcp.server.server import FastMCP