diff --git a/src/fastmcp/cli/install/gemini_cli.py b/src/fastmcp/cli/install/gemini_cli.py index c6c7c1b5d..c09016990 100644 --- a/src/fastmcp/cli/install/gemini_cli.py +++ b/src/fastmcp/cli/install/gemini_cli.py @@ -104,7 +104,6 @@ def install_gemini_cli( ) return False - # Build uv run command using Environment.build_uv_run_command() env_config = UVEnvironment( python=python_version, dependencies=(with_packages or []) + ["fastmcp"], diff --git a/src/fastmcp/utilities/logging.py b/src/fastmcp/utilities/logging.py index 095cb3375..4d06418df 100644 --- a/src/fastmcp/utilities/logging.py +++ b/src/fastmcp/utilities/logging.py @@ -19,7 +19,7 @@ def get_logger(name: str) -> logging.Logger: Returns: a configured logger instance """ - return logging.getLogger(f"FastMCP.{name}") + return logging.getLogger(f"fastmcp.{name}") def configure_logging( @@ -45,7 +45,7 @@ def configure_logging( enable_rich_tracebacks = fastmcp.settings.enable_rich_tracebacks if logger is None: - logger = logging.getLogger("FastMCP") + logger = logging.getLogger("fastmcp") # Only configure the FastMCP logger namespace handler = RichHandler( diff --git a/src/fastmcp/utilities/tests.py b/src/fastmcp/utilities/tests.py index 4ddee9597..309a4bf9d 100644 --- a/src/fastmcp/utilities/tests.py +++ b/src/fastmcp/utilities/tests.py @@ -143,10 +143,10 @@ def run_server_in_process( def caplog_for_fastmcp(caplog): """Context manager to capture logs from FastMCP loggers even when propagation is disabled.""" caplog.clear() - logger = logging.getLogger("FastMCP") + logger = logging.getLogger("fastmcp") logger.addHandler(caplog.handler) try: - yield + yield caplog finally: logger.removeHandler(caplog.handler) diff --git a/tests/server/middleware/test_error_handling.py b/tests/server/middleware/test_error_handling.py index 0983cfb1c..6c7c3cde3 100644 --- a/tests/server/middleware/test_error_handling.py +++ b/tests/server/middleware/test_error_handling.py @@ -11,6 +11,7 @@ from fastmcp.server.middleware.error_handling import ( RetryMiddleware, ) from fastmcp.server.middleware.middleware import MiddlewareContext +from fastmcp.utilities.tests import caplog_for_fastmcp @pytest.fixture @@ -60,8 +61,9 @@ class TestErrorHandlingMiddleware: middleware = ErrorHandlingMiddleware() error = ValueError("test error") - with caplog.at_level(logging.ERROR): - middleware._log_error(error, mock_context) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + middleware._log_error(error, mock_context) assert "Error in test_method: ValueError: test error" in caplog.text assert "ValueError:test_method" in middleware.error_counts @@ -72,8 +74,9 @@ class TestErrorHandlingMiddleware: middleware = ErrorHandlingMiddleware(include_traceback=True) error = ValueError("test error") - with caplog.at_level(logging.ERROR): - middleware._log_error(error, mock_context) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + middleware._log_error(error, mock_context) assert "Error in test_method: ValueError: test error" in caplog.text # The traceback is added to the log message @@ -95,8 +98,9 @@ class TestErrorHandlingMiddleware: middleware = ErrorHandlingMiddleware(error_callback=callback) error = ValueError("test error") - with caplog.at_level(logging.ERROR): - middleware._log_error(error, mock_context) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + middleware._log_error(error, mock_context) assert "Error in error callback: callback error" in caplog.text @@ -189,9 +193,10 @@ class TestErrorHandlingMiddleware: middleware = ErrorHandlingMiddleware() mock_call_next = AsyncMock(side_effect=ValueError("test error")) - with caplog.at_level(logging.ERROR): - with pytest.raises(McpError) as exc_info: - await middleware.on_message(mock_context, mock_call_next) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + with pytest.raises(McpError) as exc_info: + await middleware.on_message(mock_context, mock_call_next) assert isinstance(exc_info.value, McpError) assert exc_info.value.error.code == -32602 @@ -293,8 +298,9 @@ class TestRetryMiddleware: ] ) - with caplog.at_level(logging.WARNING): - result = await middleware.on_request(mock_context, mock_call_next) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.WARNING): + result = await middleware.on_request(mock_context, mock_call_next) assert result == "test_result" assert mock_call_next.call_count == 3 @@ -307,9 +313,10 @@ class TestRetryMiddleware: # Fail all attempts mock_call_next = AsyncMock(side_effect=ConnectionError("connection failed")) - with caplog.at_level(logging.WARNING): - with pytest.raises(ConnectionError): - await middleware.on_request(mock_context, mock_call_next) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.WARNING): + with pytest.raises(ConnectionError): + await middleware.on_request(mock_context, mock_call_next) assert mock_call_next.call_count == 3 # initial + 2 retries assert "Retrying in" in caplog.text @@ -385,14 +392,19 @@ class TestErrorHandlingMiddlewareIntegration: error_handling_server.add_middleware(ErrorHandlingMiddleware()) - with caplog.at_level(logging.ERROR): - async with Client(error_handling_server) as client: - # Test different types of errors - with pytest.raises(Exception): - await client.call_tool("failing_operation", {"error_type": "value"}) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + async with Client(error_handling_server) as client: + # Test different types of errors + with pytest.raises(Exception): + await client.call_tool( + "failing_operation", {"error_type": "value"} + ) - with pytest.raises(Exception): - await client.call_tool("failing_operation", {"error_type": "file"}) + with pytest.raises(Exception): + await client.call_tool( + "failing_operation", {"error_type": "file"} + ) log_text = caplog.text @@ -443,17 +455,20 @@ class TestErrorHandlingMiddlewareIntegration: error_handling_server.add_middleware(ErrorHandlingMiddleware()) - with caplog.at_level(logging.ERROR): - async with Client(error_handling_server) as client: - # Successful operation (should not generate error logs) - await client.call_tool("reliable_operation", {"data": "test"}) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + async with Client(error_handling_server) as client: + # Successful operation (should not generate error logs) + await client.call_tool("reliable_operation", {"data": "test"}) - # Failed operation (should generate error log) - with pytest.raises(Exception): - await client.call_tool("failing_operation", {"error_type": "value"}) + # Failed operation (should generate error log) + with pytest.raises(Exception): + await client.call_tool( + "failing_operation", {"error_type": "value"} + ) - # Another successful operation - await client.call_tool("reliable_operation", {"data": "test2"}) + # Another successful operation + await client.call_tool("reliable_operation", {"data": "test2"}) log_text = caplog.text @@ -533,18 +548,19 @@ class TestRetryMiddlewareIntegration: ) ) - with caplog.at_level(logging.WARNING): - async with Client(error_handling_server) as client: - # This operation fails intermittently - try several times - success_count = 0 - for _ in range(5): - try: - await client.call_tool( - "intermittent_operation", {"fail_rate": 0.7} - ) - success_count += 1 - except Exception: - pass # Some failures expected even with retries + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.WARNING): + async with Client(error_handling_server) as client: + # This operation fails intermittently - try several times + success_count = 0 + for _ in range(5): + try: + await client.call_tool( + "intermittent_operation", {"fail_rate": 0.7} + ) + success_count += 1 + except Exception: + pass # Some failures expected even with retries # Should have some retry log messages # Note: Retry logs might not appear if the underlying errors are wrapped by FastMCP @@ -584,17 +600,22 @@ class TestRetryMiddlewareIntegration: ) ) - with caplog.at_level(logging.ERROR): - async with Client(error_handling_server) as client: - # Try intermittent operation - try: - await client.call_tool("intermittent_operation", {"fail_rate": 0.9}) - except Exception: - pass # May still fail even with retries + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.ERROR): + async with Client(error_handling_server) as client: + # Try intermittent operation + try: + await client.call_tool( + "intermittent_operation", {"fail_rate": 0.9} + ) + except Exception: + pass # May still fail even with retries - # Try permanent failure - with pytest.raises(Exception): - await client.call_tool("failing_operation", {"error_type": "value"}) + # Try permanent failure + with pytest.raises(Exception): + await client.call_tool( + "failing_operation", {"error_type": "value"} + ) log_text = caplog.text diff --git a/tests/server/middleware/test_logging.py b/tests/server/middleware/test_logging.py index aca1b5767..2bbeda9fa 100644 --- a/tests/server/middleware/test_logging.py +++ b/tests/server/middleware/test_logging.py @@ -1,6 +1,7 @@ """Tests for logging middleware.""" import datetime +import json import logging import re from typing import Any, Literal, TypeVar @@ -10,14 +11,17 @@ import mcp import mcp.types import pytest from inline_snapshot import snapshot +from pydantic import AnyUrl from fastmcp import FastMCP from fastmcp.client import Client +from fastmcp.resources.template import ResourceTemplate from fastmcp.server.middleware.logging import ( LoggingMiddleware, StructuredLoggingMiddleware, ) -from fastmcp.server.middleware.middleware import MiddlewareContext +from fastmcp.server.middleware.middleware import CallNext, MiddlewareContext +from fastmcp.utilities.tests import caplog_for_fastmcp FIXED_DATE = datetime.datetime(2023, 1, 1, tzinfo=datetime.timezone.utc) @@ -186,7 +190,7 @@ class TestStructuredLoggingMiddleware: middleware = StructuredLoggingMiddleware() mock_call_next = AsyncMock(return_value="test_result") - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_message(mock_context, mock_call_next) assert result == "test_result" @@ -204,7 +208,7 @@ INFO fastmcp.structured:logging.py:LINE_NUMBER Completed message: {"event": middleware = StructuredLoggingMiddleware() mock_call_next = AsyncMock(side_effect=ValueError("test error")) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): with pytest.raises(ValueError): await middleware.on_message(mock_context, mock_call_next) @@ -247,6 +251,257 @@ class TestLoggingMiddleware: assert "payload=" in formatted assert "..." in formatted + async def test_on_message_failure( + self, mock_context: MiddlewareContext[Any], caplog: pytest.LogCaptureFixture + ): + """Test structured logging of failed messages.""" + middleware = StructuredLoggingMiddleware() + mock_call_next = AsyncMock(side_effect=ValueError("test error")) + + with caplog_for_fastmcp(caplog): + with pytest.raises(ValueError): + await middleware.on_message(mock_context, mock_call_next) + + # Check that we have structured JSON logs + log_lines = [record.message for record in caplog.records] + assert len(log_lines) == 2 # start and error entries + + # Extract JSON from "Processing message: {JSON}" + start_message = log_lines[0] + assert start_message.startswith("Processing message: ") + start_json = start_message[len("Processing message: ") :] + start_entry = json.loads(start_json) + assert start_entry["event"] == "request_start" + + # Error messages have different format - check the second log entry + assert "Failed message:" in log_lines[1] + + async def test_on_message_with_pydantic_types_in_payload( + self, + mock_call_next: CallNext[Any, Any], + caplog: pytest.LogCaptureFixture, + ): + """Ensure Pydantic AnyUrl in payload serializes correctly when include_payloads=True.""" + + mock_context = new_mock_context( + message=mcp.types.ReadResourceRequest( + method="resources/read", + params=mcp.types.ReadResourceRequestParams( + uri=AnyUrl("test://example/1"), + ), + ) + ) + + middleware = StructuredLoggingMiddleware(include_payloads=True) + + with caplog_for_fastmcp(caplog): + result = await middleware.on_message(mock_context, mock_call_next) + + assert result == "test_result" + + log_lines = [record.message for record in caplog.records] + + assert len(log_lines) == 2 + + # Extract JSON from log messages + start_message = log_lines[0] + assert start_message.startswith("Processing message: ") + start_json = start_message[len("Processing message: ") :] + assert json.loads(start_json) == snapshot( + { + "event": "request_start", + "timestamp": "2023-01-01T00:00:00+00:00", + "source": "client", + "type": "request", + "method": "test_method", + "payload": '{"method":"resources/read","params":{"_meta":null,"uri":"test://example/1"}}', + "payload_type": "ReadResourceRequest", + } + ) + + success_message = log_lines[1] + assert success_message.startswith("Completed message: ") + success_json = success_message[len("Completed message: ") :] + assert json.loads(success_json) == snapshot( + { + "event": "request_success", + "timestamp": "2023-01-01T00:00:00+00:00", + "source": "client", + "type": "request", + "method": "test_method", + } + ) + + async def test_on_message_with_resource_template_in_payload( + self, + mock_call_next: CallNext[Any, Any], + caplog: pytest.LogCaptureFixture, + ): + """Ensure ResourceTemplate in payload serializes via pydantic conversion without errors.""" + + mock_context = new_mock_context( + message=ResourceTemplate( + name="tmpl", + uri_template="tmpl://{id}", + parameters={"id": {"type": "string"}}, + ) + ) + + middleware = StructuredLoggingMiddleware(include_payloads=True) + + with caplog_for_fastmcp(caplog): + result = await middleware.on_message(mock_context, mock_call_next) + + assert result == "test_result" + + log_lines = [record.message for record in caplog.records] + assert len(log_lines) == 2 + + # Extract JSON from log message + start_message = log_lines[0] + assert start_message.startswith("Processing message: ") + start_json = start_message[len("Processing message: ") :] + assert json.loads(start_json) == snapshot( + { + "event": "request_start", + "timestamp": "2023-01-01T00:00:00+00:00", + "source": "client", + "type": "request", + "method": "test_method", + "payload": '{"name":"tmpl","title":null,"description":null,"tags":[],"meta":null,"enabled":true,"uri_template":"tmpl://{id}","mime_type":"text/plain","parameters":{"id":{"type":"string"}},"annotations":null}', + "payload_type": "ResourceTemplate", + } + ) + + async def test_on_message_with_nonserializable_payload_falls_back_to_str( + self, mock_call_next: CallNext[Any, Any], caplog: pytest.LogCaptureFixture + ): + """Ensure non-JSONable objects fall back to string serialization in payload.""" + + class NonSerializable: + def __str__(self) -> str: + return "NON_SERIALIZABLE" + + mock_context = new_mock_context( + message=mcp.types.CallToolRequest( + method="tools/call", + params=mcp.types.CallToolRequestParams( + name="test_method", + arguments={"obj": NonSerializable()}, + ), + ) + ) + + middleware = StructuredLoggingMiddleware(include_payloads=True) + + with caplog_for_fastmcp(caplog): + result = await middleware.on_message(mock_context, mock_call_next) + + assert result == "test_result" + + log_lines = [record.message for record in caplog.records] + assert len(log_lines) >= 2 + + # Extract JSON from log message + start_message = log_lines[0] + assert start_message.startswith("Processing message: ") + start_json = start_message[len("Processing message: ") :] + assert json.loads(start_json) == snapshot( + { + "event": "request_start", + "timestamp": "2023-01-01T00:00:00+00:00", + "source": "client", + "type": "request", + "method": "test_method", + "payload": '{"method":"tools/call","params":{"_meta":null,"name":"test_method","arguments":{"obj":"NON_SERIALIZABLE"}}}', + "payload_type": "CallToolRequest", + } + ) + + async def test_on_message_with_custom_serializer_applied( + self, mock_call_next: CallNext[Any, Any], caplog: pytest.LogCaptureFixture + ): + """Ensure a custom serializer is used for non-JSONable payloads.""" + + # Provide a serializer that replaces entire payload with a fixed string + def custom_serializer(_: Any) -> str: + return "CUSTOM_PAYLOAD" + + mock_context = new_mock_context( + message=mcp.types.CallToolRequest( + method="tools/call", + params=mcp.types.CallToolRequestParams( + name="test_method", + arguments={"obj": "OBJECT"}, + ), + ) + ) + + middleware = StructuredLoggingMiddleware( + include_payloads=True, payload_serializer=custom_serializer + ) + + with caplog_for_fastmcp(caplog): + result = await middleware.on_message(mock_context, mock_call_next) + + assert result == "test_result" + + log_lines = [record.message for record in caplog.records] + assert len(log_lines) >= 2 + + # Extract JSON from log message + start_message = log_lines[0] + assert start_message.startswith("Processing message: ") + start_json = start_message[len("Processing message: ") :] + assert json.loads(start_json) == snapshot( + { + "event": "request_start", + "timestamp": "2023-01-01T00:00:00+00:00", + "source": "client", + "type": "request", + "method": "test_method", + "payload": "CUSTOM_PAYLOAD", + "payload_type": "CallToolRequest", + } + ) + + +@pytest.fixture +def logging_server(): + """Create a FastMCP server specifically for logging middleware tests.""" + from fastmcp import FastMCP + + mcp = FastMCP("LoggingTestServer") + + @mcp.tool + def simple_operation(data: str) -> str: + """A simple operation for testing logging.""" + return f"Processed: {data}" + + @mcp.tool + def complex_operation(items: list[str], mode: str = "default") -> dict: + """A complex operation with structured data.""" + return {"processed_items": len(items), "mode": mode, "result": "success"} + + @mcp.tool + def operation_with_error(should_fail: bool = False) -> str: + """An operation that can be made to fail.""" + if should_fail: + raise ValueError("Operation failed intentionally") + return "Operation completed successfully" + + @mcp.resource("log://test") + def test_resource() -> str: + """A test resource for logging.""" + return "Test resource content" + + @mcp.prompt + def test_prompt() -> str: + """A test prompt for logging.""" + return "Test prompt content" + + return mcp + class TestLoggingMiddlewareIntegration: """Integration tests for logging middleware with real FastMCP server.""" @@ -296,15 +551,16 @@ class TestLoggingMiddlewareIntegration: logging_server.add_middleware(logging_middleware) - with caplog.at_level(logging.INFO): - async with Client(logging_server) as client: - await client.call_tool( - name="simple_operation", arguments={"data": "test_data"} - ) - await client.call_tool( - name="complex_operation", - arguments={"items": ["a", "b", "c"], "mode": "batch"}, - ) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.INFO): + async with Client(logging_server) as client: + await client.call_tool( + name="simple_operation", arguments={"data": "test_data"} + ) + await client.call_tool( + name="complex_operation", + arguments={"items": ["a", "b", "c"], "mode": "batch"}, + ) # Should have processing and completion logs for both operations assert remove_line_numbers(caplog.text) == snapshot("""\ @@ -324,7 +580,7 @@ INFO fastmcp.requests:logging.py:LINE_NUMBER Completed message: event=reques """Test that logging middleware captures failed operations.""" logging_server.add_middleware(LoggingMiddleware(methods=["tools/call"])) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(logging_server) as client: # This should fail and be logged with pytest.raises(Exception): @@ -351,17 +607,25 @@ INFO fastmcp.requests:logging.py:LINE_NUMBER Completed message: event=reques ) logging_server.add_middleware(middleware) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(logging_server) as client: await client.call_tool("simple_operation", {"data": "payload_test"}) log_text = caplog.text + # Remove client IDs from log text for consistent snapshots + import re + + log_text = re.sub(r"\[Client-[^\]]+\]", "[Client-XXXX]", log_text) + assert remove_line_numbers(log_text) == snapshot("""\ -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type CallToolRequest +DEBUG fastmcp.fastmcp.client.transports:transports.py:LINE_NUMBER Inferred transport: +DEBUG fastmcp.fastmcp.client.client:client.py:LINE_NUMBER [Client-XXXX] called call_tool: simple_operation +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: call_tool simple_operation with {'data': 'payload_test'} INFO fastmcp.requests:logging.py:LINE_NUMBER Processing message: event=request_start timestamp=2023-01-01T00:00:00+00:00 method=tools/call type=request source=client payload={"_meta":null,"name":"simple_operation","arguments":{"data":"payload_test"}} payload_type=CallToolRequestParams INFO fastmcp.requests:logging.py:LINE_NUMBER Completed message: event=request_success timestamp=2023-01-01T00:00:00+00:00 method=tools/call type=request source=client -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type ListToolsRequest +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools """) @@ -379,7 +643,7 @@ INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of logging_server.add_middleware(logging_middleware) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(logging_server) as client: await client.call_tool( name="simple_operation", arguments={"data": "json_test"} @@ -394,11 +658,19 @@ INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of assert len(log_lines) >= 2 # Should have start and success entries - assert remove_line_numbers(caplog.text) == snapshot("""\ -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type CallToolRequest + # Remove client IDs from log text for consistent snapshots + import re + + log_text = re.sub(r"\[Client-[^\]]+\]", "[Client-XXXX]", caplog.text) + + assert remove_line_numbers(log_text) == snapshot("""\ +DEBUG fastmcp.fastmcp.client.transports:transports.py:LINE_NUMBER Inferred transport: +DEBUG fastmcp.fastmcp.client.client:client.py:LINE_NUMBER [Client-XXXX] called call_tool: simple_operation +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: call_tool simple_operation with {'data': 'json_test'} INFO fastmcp.structured:logging.py:LINE_NUMBER Processing message: {"event": "request_start", "timestamp": "2023-01-01T00:00:00+00:00", "method": "tools/call", "type": "request", "source": "client", "payload": "{\\"_meta\\":null,\\"name\\":\\"simple_operation\\",\\"arguments\\":{\\"data\\":\\"json_test\\"}}", "payload_type": "CallToolRequestParams"} INFO fastmcp.structured:logging.py:LINE_NUMBER Completed message: {"event": "request_success", "timestamp": "2023-01-01T00:00:00+00:00", "method": "tools/call", "type": "request", "source": "client"} -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type ListToolsRequest +DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools """) @@ -414,19 +686,26 @@ INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of logging_server.add_middleware(logging_middleware) - with caplog.at_level(logging.INFO): - async with Client(logging_server) as client: - with pytest.raises(Exception): - await client.call_tool( - "operation_with_error", {"should_fail": True} - ) + with caplog_for_fastmcp(caplog): + with caplog.at_level(logging.INFO): + async with Client(logging_server) as client: + with pytest.raises(Exception): + await client.call_tool( + "operation_with_error", {"should_fail": True} + ) - assert remove_line_numbers(caplog.text) == snapshot("""\ -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type CallToolRequest -INFO fastmcp.structured:logging.py:LINE_NUMBER Processing message: {"event": "request_start", "timestamp": "2023-01-01T00:00:00+00:00", "method": "tools/call", "type": "request", "source": "client"} -ERROR fastmcp.structured:logging.py:LINE_NUMBER Failed message: tools/call - Error calling tool 'operation_with_error': Operation failed intentionally + # Verify that the structured logging middleware properly logs errors + logs = caplog.text -""") + # The key assertion: structured logging middleware logged the error in JSON format + assert re.search( + r"fastmcp\.structured.*Failed message: tools/call.*Operation failed intentionally", + logs, + ) + + # Verify the error contains expected error type and message + assert "ValueError" in logs + assert "Operation failed intentionally" in logs async def test_logging_middleware_with_different_operations( self, logging_server: FastMCP, caplog: pytest.LogCaptureFixture @@ -444,7 +723,7 @@ ERROR fastmcp.structured:logging.py:LINE_NUMBER Failed message: tools/call - ) ) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(logging_server) as client: # Test different operation types await client.call_tool("simple_operation", {"data": "test"}) diff --git a/tests/server/middleware/test_timing.py b/tests/server/middleware/test_timing.py index 999edf039..db726b13e 100644 --- a/tests/server/middleware/test_timing.py +++ b/tests/server/middleware/test_timing.py @@ -11,6 +11,7 @@ from fastmcp import FastMCP from fastmcp.client import Client from fastmcp.server.middleware.middleware import MiddlewareContext from fastmcp.server.middleware.timing import DetailedTimingMiddleware, TimingMiddleware +from fastmcp.utilities.tests import caplog_for_fastmcp @pytest.fixture @@ -47,7 +48,7 @@ class TestTimingMiddleware: """Test timing successful requests.""" middleware = TimingMiddleware() - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_request(mock_context, mock_call_next) assert result == "test_result" @@ -60,7 +61,7 @@ class TestTimingMiddleware: middleware = TimingMiddleware() mock_call_next = AsyncMock(side_effect=ValueError("test error")) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): with pytest.raises(ValueError): await middleware.on_request(mock_context, mock_call_next) @@ -84,7 +85,7 @@ class TestDetailedTimingMiddleware: context.message.name = "test_tool" mock_call_next = AsyncMock(return_value="tool_result") - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_call_tool(context, mock_call_next) assert result == "tool_result" @@ -97,7 +98,7 @@ class TestDetailedTimingMiddleware: context.message.uri = "test://resource" mock_call_next = AsyncMock(return_value="resource_result") - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_read_resource(context, mock_call_next) assert result == "resource_result" @@ -110,7 +111,7 @@ class TestDetailedTimingMiddleware: context.message.name = "test_prompt" mock_call_next = AsyncMock(return_value="prompt_result") - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_get_prompt(context, mock_call_next) assert result == "prompt_result" @@ -122,7 +123,7 @@ class TestDetailedTimingMiddleware: context = MagicMock() mock_call_next = AsyncMock(return_value="tools_result") - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): result = await middleware.on_list_tools(context, mock_call_next) assert result == "tools_result" @@ -135,7 +136,7 @@ class TestDetailedTimingMiddleware: context.message.name = "failing_tool" mock_call_next = AsyncMock(side_effect=RuntimeError("operation failed")) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): with pytest.raises(RuntimeError): await middleware.on_call_tool(context, mock_call_next) @@ -194,7 +195,7 @@ class TestTimingMiddlewareIntegration: """Test that timing middleware accurately measures tool execution times.""" timing_server.add_middleware(TimingMiddleware()) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(timing_server) as client: # Test instant task await client.call_tool("instant_task") @@ -225,7 +226,7 @@ class TestTimingMiddlewareIntegration: """Test that timing middleware measures time even for failed operations.""" timing_server.add_middleware(TimingMiddleware()) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(timing_server) as client: # This should fail but still be timed with pytest.raises(Exception): @@ -241,7 +242,7 @@ class TestTimingMiddlewareIntegration: """Test that detailed timing middleware provides operation-specific timing.""" timing_server.add_middleware(DetailedTimingMiddleware()) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(timing_server) as client: # Test tool call await client.call_tool("short_task") @@ -271,7 +272,7 @@ class TestTimingMiddlewareIntegration: """Test timing middleware with concurrent operations.""" timing_server.add_middleware(TimingMiddleware()) - with caplog.at_level(logging.INFO): + with caplog_for_fastmcp(caplog): async with Client(timing_server) as client: # Run multiple operations concurrently tasks = [ @@ -290,7 +291,7 @@ class TestTimingMiddlewareIntegration: len(timing_logs) >= 3 ) # At least 3 tool calls, may have additional list_tools calls - async def test_timing_middleware_custom_logger(self, timing_server): + async def test_timing_middleware_custom_logger(self, timing_server, caplog): """Test timing middleware with custom logger configuration.""" import io import logging diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index 30ea963e9..e6d8086fc 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -5,14 +5,14 @@ from fastmcp.utilities.logging import get_logger def test_logging_doesnt_affect_other_loggers(caplog): # set FastMCP loggers to CRITICAL and ensure other loggers still emit messages - original_level = logging.getLogger("FastMCP").getEffectiveLevel() + original_level = logging.getLogger("fastmcp").getEffectiveLevel() try: - logging.getLogger("FastMCP").setLevel(logging.CRITICAL) + logging.getLogger("fastmcp").setLevel(logging.CRITICAL) root_logger = logging.getLogger() app_logger = logging.getLogger("app") - fastmcp_logger = logging.getLogger("FastMCP") + fastmcp_logger = logging.getLogger("fastmcp") fastmcp_server_logger = get_logger("server") with caplog.at_level(logging.INFO): @@ -27,4 +27,4 @@ def test_logging_doesnt_affect_other_loggers(caplog): assert "--FASTMCP SERVER--" not in caplog.text finally: - logging.getLogger("FastMCP").setLevel(original_level) + logging.getLogger("fastmcp").setLevel(original_level)