mirror of
https://github.com/PrefectHQ/fastmcp.git
synced 2026-08-23 05:54:19 +02:00
Use lowercase namespace for fastmcp logger (#1791)
This commit is contained in:
parent
d6aa980ff5
commit
b96e6ebbb2
7 changed files with 406 additions and 106 deletions
|
|
@ -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"],
|
||||
|
|
|
|||
|
|
@ -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(
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
|
|
@ -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: <FastMCPTransport(server='LoggingTestServer')>
|
||||
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: <FastMCPTransport(server='LoggingTestServer')>
|
||||
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"})
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue