diff --git a/docs/integrations/azure.mdx b/docs/integrations/azure.mdx index 2ceefe482..2d2595a86 100644 --- a/docs/integrations/azure.mdx +++ b/docs/integrations/azure.mdx @@ -10,7 +10,7 @@ import { VersionBadge } from "/snippets/version-badge.mdx" -This guide shows you how to secure your FastMCP server using **Azure OAuth** (Microsoft Entra ID). Since Azure doesn't support Dynamic Client Registration, this integration uses the [**OAuth Proxy**](/servers/auth/oauth-proxy) pattern to bridge Azure's traditional OAuth with MCP's authentication requirements. +This guide shows you how to secure your FastMCP server using **Azure OAuth** (Microsoft Entra ID). Since Azure doesn't support Dynamic Client Registration, this integration uses the [**OAuth Proxy**](/servers/auth/oauth-proxy) pattern to bridge Azure's traditional OAuth with MCP's authentication requirements. FastMCP validates Azure JWTs against your application's client_id. ## Configuration @@ -49,8 +49,39 @@ Create an App registration in Azure Portal to get the credentials needed for aut If you want to use a custom callback path (e.g., `/auth/azure/callback`), make sure to set the same path in both your Azure App registration and the `redirect_path` parameter when configuring the AzureProvider. + + - **Expose an API**: Configure your Application ID URI and define scopes + - Go to **Expose an API** in the App registration sidebar. + - Click **Set** next to "Application ID URI" and choose one of: + - Keep the default `api://{client_id}` + - Set a custom value, following the supported formats (see [Identifier URI restrictions](https://learn.microsoft.com/en-us/entra/identity-platform/identifier-uri-restrictions)) + - Click **Add a scope** and create a scope your app will require, for example: + - Scope name: `read` (or `write`, etc.) + - Admin consent display name/description: as appropriate for your org + - Who can consent: as needed (Admins only or Admins and users) + + - **Configure Access Token Version**: Ensure your app uses access token v2 + - Go to **Manifest** in the App registration sidebar. + - Find the `requestedAccessTokenVersion` property and set it to `2`: + ```json + "api": { + "requestedAccessTokenVersion": 2 + } + ``` + - Click **Save** at the top of the manifest editor. + + + Access token v2 is required for FastMCP's Azure integration to work correctly. If this is not set, you may encounter authentication errors. + + + + In FastMCP's `AzureProvider`, set `identifier_uri` to your Application ID URI (optional; defaults to `api://{client_id}`) and set `required_scopes` to the unprefixed scope names (e.g., `read`, `write`). During authorization, FastMCP automatically prefixes scopes with your `identifier_uri`. + + + + After registration, navigate to **Certificates & secrets** in your app's settings. @@ -91,7 +122,11 @@ auth_provider = AzureProvider( client_secret="your-client-secret", # Your Azure App Client Secret tenant_id="08541b6e-646d-43de-a0eb-834e6713d6d5", # Your Azure Tenant ID (REQUIRED) base_url="http://localhost:8000", # Must match your App registration - required_scopes=["User.Read", "email", "openid", "profile"], # Microsoft Graph permissions + required_scopes=["your-scope"], # Name of scope created when configuring your App + # identifier_uri defaults to api://{client_id} + # identifier_uri="api://your-api-id", + # Optional: request additional upstream scopes in the authorize request + # additional_authorize_scopes=["User.Read", "offline_access", "openid", "email"], # redirect_path="/auth/callback" # Default value, customize if needed ) @@ -215,12 +250,16 @@ Public URL of your FastMCP server for OAuth callbacks Redirect path configured in your Azure App registration - -Comma-, space-, or JSON-separated list of required Microsoft Graph scopes + +Comma-, space-, or JSON-separated list of required scopes for your API. These are validated on tokens and used as defaults if the client does not request specific scopes. - -HTTP request timeout for Microsoft Graph API calls + +Comma-, space-, or JSON-separated list of additional scopes to include in the authorization request without prefixing. Use this to request upstream scopes such as Microsoft Graph permissions. These are not used for token validation. + + + +Application ID URI used to prefix scopes during authorization. @@ -234,7 +273,11 @@ FASTMCP_SERVER_AUTH_AZURE_CLIENT_ID=835f09b6-0f0f-40cc-85cb-f32c5829a149 FASTMCP_SERVER_AUTH_AZURE_CLIENT_SECRET=your-client-secret-here FASTMCP_SERVER_AUTH_AZURE_TENANT_ID=08541b6e-646d-43de-a0eb-834e6713d6d5 FASTMCP_SERVER_AUTH_AZURE_BASE_URL=https://your-server.com -FASTMCP_SERVER_AUTH_AZURE_REQUIRED_SCOPES=User.Read,email,profile +FASTMCP_SERVER_AUTH_AZURE_REQUIRED_SCOPES=read,write +# Optional custom API configuration +# FASTMCP_SERVER_AUTH_AZURE_IDENTIFIER_URI=api://your-api-id +# Request additional upstream scopes (optional) +# FASTMCP_SERVER_AUTH_AZURE_ADDITIONAL_AUTHORIZE_SCOPES=User.Read,Mail.Read ``` With environment variables set, your server code simplifies to: diff --git a/docs/patterns/tool-transformation.mdx b/docs/patterns/tool-transformation.mdx index 89f9370de..730996d51 100644 --- a/docs/patterns/tool-transformation.mdx +++ b/docs/patterns/tool-transformation.mdx @@ -548,7 +548,7 @@ Provide your own schema that differs from the parent. The tool must return data **Remove Output Schema** ```python -Tool.from_tool(parent_tool, output_schema=False) +Tool.from_tool(parent_tool, output_schema=None) ``` Removes the output schema declaration. Automatic structured content still works for object-like returns (dict, dataclass, Pydantic models) but primitive types won't be structured. diff --git a/src/fastmcp/server/auth/providers/azure.py b/src/fastmcp/server/auth/providers/azure.py index 58f8ca5b6..367203e43 100644 --- a/src/fastmcp/server/auth/providers/azure.py +++ b/src/fastmcp/server/auth/providers/azure.py @@ -8,15 +8,21 @@ from __future__ import annotations import httpx from key_value.aio.protocols import AsyncKeyValue +from typing import TYPE_CHECKING + from pydantic import SecretStr, field_validator from pydantic_settings import BaseSettings, SettingsConfigDict -from fastmcp.server.auth import AccessToken, TokenVerifier from fastmcp.server.auth.oauth_proxy import OAuthProxy +from fastmcp.server.auth.providers.jwt import JWTVerifier from fastmcp.utilities.auth import parse_scopes from fastmcp.utilities.logging import get_logger from fastmcp.utilities.types import NotSet, NotSetT +if TYPE_CHECKING: + from mcp.server.auth.provider import AuthorizationParams + from mcp.shared.auth import OAuthClientInformationFull + logger = get_logger(__name__) @@ -32,87 +38,22 @@ class AzureProviderSettings(BaseSettings): client_id: str | None = None client_secret: SecretStr | None = None tenant_id: str | None = None + identifier_uri: str | None = None base_url: str | None = None redirect_path: str | None = None required_scopes: list[str] | None = None - timeout_seconds: int | None = None + additional_authorize_scopes: list[str] | None = None allowed_client_redirect_uris: list[str] | None = None @field_validator("required_scopes", mode="before") @classmethod - def _parse_scopes(cls, v): + def _parse_scopes(cls, v: object) -> list[str] | None: return parse_scopes(v) - -class AzureTokenVerifier(TokenVerifier): - """Token verifier for Azure OAuth tokens. - - Azure tokens are JWTs, but we verify them by calling the Microsoft Graph API - to get user information and validate the token. - """ - - def __init__( - self, - *, - required_scopes: list[str] | None = None, - timeout_seconds: int = 10, - ): - """Initialize the Azure token verifier. - - Args: - required_scopes: Required OAuth scopes - timeout_seconds: HTTP request timeout - """ - super().__init__(required_scopes=required_scopes) - self.timeout_seconds = timeout_seconds - - async def verify_token(self, token: str) -> AccessToken | None: - """Verify Azure OAuth token by calling Microsoft Graph API.""" - try: - async with httpx.AsyncClient(timeout=self.timeout_seconds) as client: - # Use Microsoft Graph API to validate token and get user info - response = await client.get( - "https://graph.microsoft.com/v1.0/me", - headers={ - "Authorization": f"Bearer {token}", - "User-Agent": "FastMCP-Azure-OAuth", - }, - ) - - if response.status_code != 200: - logger.debug( - "Azure token verification failed: %d - %s", - response.status_code, - response.text[:200], - ) - return None - - user_data = response.json() - - # Create AccessToken with Azure user info - return AccessToken( - token=token, - client_id=str(user_data.get("id", "unknown")), - scopes=self.required_scopes or [], - expires_at=None, - claims={ - "sub": user_data.get("id"), - "email": user_data.get("mail") - or user_data.get("userPrincipalName"), - "name": user_data.get("displayName"), - "given_name": user_data.get("givenName"), - "family_name": user_data.get("surname"), - "job_title": user_data.get("jobTitle"), - "office_location": user_data.get("officeLocation"), - }, - ) - - except httpx.RequestError as e: - logger.debug("Failed to verify Azure token: %s", e) - return None - except Exception as e: - logger.debug("Azure token verification error: %s", e) - return None + @field_validator("additional_authorize_scopes", mode="before") + @classmethod + def _parse_additional_authorize_scopes(cls, v: object) -> list[str] | None: + return parse_scopes(v) class AzureProvider(OAuthProxy): @@ -123,16 +64,17 @@ class AzureProvider(OAuthProxy): Microsoft accounts depending on the tenant configuration. Features: - - Transparent OAuth proxy to Azure/Microsoft identity platform - - Automatic token validation via Microsoft Graph API - - User information extraction - - Support for different tenant configurations (common, organizations, consumers) + - OAuth proxy to Azure/Microsoft identity platform + - JWT validation using tenant issuer and JWKS + - Supports tenant configurations: specific tenant ID, "organizations", or "consumers" - Setup Requirements: - 1. Register an application in Azure Portal (portal.azure.com) - 2. Configure redirect URI as: http://localhost:8000/auth/callback - 3. Note your Application (client) ID and create a client secret - 4. Optionally note your Directory (tenant) ID for single-tenant apps + Setup: + 1. Create an App registration in Azure Portal + 2. Configure Web platform redirect URI: http://localhost:8000/auth/callback (or your custom path) + 3. Add an Application ID URI. Either use the default (api://{client_id}) or set a custom one. + 4. Add a custom scope. + 5. Create a client secret. + 6. Get Application (client) ID, Directory (tenant) ID, and client secret Example: ```python @@ -142,8 +84,10 @@ class AzureProvider(OAuthProxy): auth = AzureProvider( client_id="your-client-id", client_secret="your-client-secret", - tenant_id="your-tenant-id", # Required: your Azure tenant ID from Azure Portal - base_url="http://localhost:8000" + tenant_id="your-tenant-id", + required_scopes=["your-scope"], + base_url="http://localhost:8000", + # identifier_uri defaults to api://{client_id} ) mcp = FastMCP("My App", auth=auth) @@ -156,23 +100,31 @@ class AzureProvider(OAuthProxy): client_id: str | NotSetT = NotSet, client_secret: str | NotSetT = NotSet, tenant_id: str | NotSetT = NotSet, + identifier_uri: str | None | NotSetT = NotSet, base_url: str | NotSetT = NotSet, redirect_path: str | NotSetT = NotSet, required_scopes: list[str] | None | NotSetT = NotSet, - timeout_seconds: int | NotSetT = NotSet, + additional_authorize_scopes: list[str] | None | NotSetT = NotSet, allowed_client_redirect_uris: list[str] | NotSetT = NotSet, client_storage: AsyncKeyValue | None = None, ): + ) -> None: """Initialize Azure OAuth provider. Args: client_id: Azure application (client) ID client_secret: Azure client secret tenant_id: Azure tenant ID (your specific tenant ID, "organizations", or "consumers") + identifier_uri: Optional Application ID URI for your API. (defaults to api://{client_id}) + Used only to prefix scopes in authorization requests. Tokens are always validated + against your app's client ID. base_url: Public URL of your FastMCP server (for OAuth callbacks) redirect_path: Redirect path configured in Azure (defaults to "/auth/callback") - required_scopes: Required scopes (defaults to ["User.Read", "email", "openid", "profile"]) - timeout_seconds: HTTP request timeout for Azure API calls + required_scopes: Required scopes. These are validated on tokens and used as defaults + when the client does not request specific scopes. + additional_authorize_scopes: Additional scopes to include in the authorization request + without prefixing. Use this to request upstream scopes such as Microsoft Graph + permissions. These are not used for token validation. allowed_client_redirect_uris: List of allowed redirect URI patterns for MCP clients. If None (default), all URIs are allowed. If empty list, no URIs are allowed. client_storage: Storage implementation for OAuth client registrations. @@ -185,10 +137,11 @@ class AzureProvider(OAuthProxy): "client_id": client_id, "client_secret": client_secret, "tenant_id": tenant_id, + "identifier_uri": identifier_uri, "base_url": base_url, "redirect_path": redirect_path, "required_scopes": required_scopes, - "timeout_seconds": timeout_seconds, + "additional_authorize_scopes": additional_authorize_scopes, "allowed_client_redirect_uris": allowed_client_redirect_uris, }.items() if v is not NotSet @@ -197,45 +150,48 @@ class AzureProvider(OAuthProxy): # Validate required settings if not settings.client_id: - raise ValueError( - "client_id is required - set via parameter or FASTMCP_SERVER_AUTH_AZURE_CLIENT_ID" - ) + msg = "client_id is required - set via parameter or FASTMCP_SERVER_AUTH_AZURE_CLIENT_ID" + raise ValueError(msg) if not settings.client_secret: - raise ValueError( - "client_secret is required - set via parameter or FASTMCP_SERVER_AUTH_AZURE_CLIENT_SECRET" - ) + msg = "client_secret is required - set via parameter or FASTMCP_SERVER_AUTH_AZURE_CLIENT_SECRET" + raise ValueError(msg) # Validate tenant_id is provided if not settings.tenant_id: - raise ValueError( - "tenant_id is required - set via parameter or FASTMCP_SERVER_AUTH_AZURE_TENANT_ID. " - "Use your Azure tenant ID (found in Azure Portal), 'organizations', or 'consumers'" + msg = ( + "tenant_id is required - set via parameter or " + "FASTMCP_SERVER_AUTH_AZURE_TENANT_ID. Use your Azure tenant ID " + "(found in Azure Portal), 'organizations', or 'consumers'" ) + raise ValueError(msg) + + if not settings.required_scopes: + raise ValueError("required_scopes is required") # Apply defaults + self.identifier_uri = settings.identifier_uri or f"api://{settings.client_id}" + self.additional_authorize_scopes = settings.additional_authorize_scopes or [] tenant_id_final = settings.tenant_id - timeout_seconds_final = settings.timeout_seconds or 10 - # Default scopes for Azure - User.Read gives us access to user info via Graph API - scopes_final = settings.required_scopes or [ - "User.Read", - "email", - "openid", - "profile", - ] - allowed_client_redirect_uris_final = settings.allowed_client_redirect_uris + # Always validate tokens against the app's API client ID using JWT + issuer = f"https://login.microsoftonline.com/{tenant_id_final}/v2.0" + jwks_uri = ( + f"https://login.microsoftonline.com/{tenant_id_final}/discovery/v2.0/keys" + ) + + token_verifier = JWTVerifier( + jwks_uri=jwks_uri, + issuer=issuer, + audience=settings.client_id, + algorithm="RS256", + required_scopes=settings.required_scopes, + ) # Extract secret string from SecretStr client_secret_str = ( settings.client_secret.get_secret_value() if settings.client_secret else "" ) - # Create Azure token verifier - token_verifier = AzureTokenVerifier( - required_scopes=scopes_final, - timeout_seconds=timeout_seconds_final, - ) - # Build Azure OAuth endpoints with tenant authorization_endpoint = ( f"https://login.microsoftonline.com/{tenant_id_final}/oauth2/v2.0/authorize" @@ -254,12 +210,65 @@ class AzureProvider(OAuthProxy): base_url=settings.base_url, redirect_path=settings.redirect_path, issuer_url=settings.base_url, - allowed_client_redirect_uris=allowed_client_redirect_uris_final, + allowed_client_redirect_uris=settings.allowed_client_redirect_uris, client_storage=client_storage, ) logger.info( - "Initialized Azure OAuth provider for client %s with tenant %s", + "Initialized Azure OAuth provider for client %s with tenant %s%s", settings.client_id, tenant_id_final, + f" and identifier_uri {self.identifier_uri}" if self.identifier_uri else "", ) + + async def authorize( + self, + client: OAuthClientInformationFull, + params: AuthorizationParams, + ) -> str: + """Start OAuth transaction and redirect to Azure AD. + + Override parent's authorize method to filter out the 'resource' parameter + which is not supported by Azure AD v2.0 endpoints. The v2.0 endpoints use + scopes to determine the resource/audience instead of a separate parameter. + + Args: + client: OAuth client information + params: Authorization parameters from the client + + Returns: + Authorization URL to redirect the user to Azure AD + """ + # Clear the resource parameter that Azure AD v2.0 doesn't support + # This parameter comes from RFC 8707 (OAuth 2.0 Resource Indicators) + # but Azure AD v2.0 uses scopes instead to determine the audience + params_to_use = params + if hasattr(params, "resource"): + original_resource = getattr(params, "resource", None) + if original_resource is not None: + params_to_use = params.model_copy(update={"resource": None}) + if original_resource: + logger.debug( + "Filtering out 'resource' parameter '%s' for Azure AD v2.0 (use scopes instead)", + original_resource, + ) + original_scopes = params_to_use.scopes or self.required_scopes + prefixed_scopes = ( + self._add_prefix_to_scopes(original_scopes) + if self.identifier_uri + else original_scopes + ) + + final_scopes = list(prefixed_scopes) + if self.additional_authorize_scopes: + final_scopes.extend(self.additional_authorize_scopes) + + modified_params = params_to_use.model_copy(update={"scopes": final_scopes}) + + auth_url = await super().authorize(client, modified_params) + separator = "&" if "?" in auth_url else "?" + return f"{auth_url}{separator}prompt=select_account" + + def _add_prefix_to_scopes(self, scopes: list[str]) -> list[str]: + """Add Application ID URI prefix for authorization request.""" + return [f"{self.identifier_uri}/{scope}" for scope in scopes] diff --git a/src/fastmcp/server/middleware/logging.py b/src/fastmcp/server/middleware/logging.py index fe2a46cfc..593ce3bbf 100644 --- a/src/fastmcp/server/middleware/logging.py +++ b/src/fastmcp/server/middleware/logging.py @@ -2,6 +2,7 @@ import json import logging +import time from collections.abc import Callable from logging import Logger from typing import Any @@ -52,14 +53,14 @@ class BaseLoggingMiddleware(Middleware): else: return " ".join([f"{k}={v}" for k, v in message.items()]) - def _get_timestamp_from_context(self, context: MiddlewareContext[Any]) -> str: - """Get a timestamp from the context.""" - return context.timestamp.isoformat() - def _create_before_message( - self, context: MiddlewareContext[Any], event: str + self, context: MiddlewareContext[Any] ) -> dict[str, str | int]: - message = self._create_base_message(context, event) + message = { + "event": context.type + "_start", + "method": context.method or "unknown", + "source": context.source, + } if ( self.include_payloads @@ -85,57 +86,61 @@ class BaseLoggingMiddleware(Middleware): return message - def _create_after_message( - self, context: MiddlewareContext[Any], event: str - ) -> dict[str, str | int]: - return self._create_base_message(context, event) - - def _create_base_message( + def _create_error_message( self, context: MiddlewareContext[Any], - event: str, - ) -> dict[str, str | int]: - """Format a message for logging.""" - - parts: dict[str, str | int] = { - "event": event, - "timestamp": self._get_timestamp_from_context(context), + start_time: float, + error: Exception, + ) -> dict[str, str | int | float]: + duration_ms: float = _get_duration_ms(start_time) + message = { + "event": context.type + "_error", "method": context.method or "unknown", - "type": context.type, "source": context.source, + "duration_ms": duration_ms, + "error": str(object=error), } + return message - return parts + def _create_after_message( + self, + context: MiddlewareContext[Any], + start_time: float, + ) -> dict[str, str | int | float]: + duration_ms: float = _get_duration_ms(start_time) + message = { + "event": context.type + "_success", + "method": context.method or "unknown", + "source": context.source, + "duration_ms": duration_ms, + } + return message + + def _log_message( + self, message: dict[str, str | int | float], log_level: int | None = None + ): + self.logger.log(log_level or self.log_level, self._format_message(message)) async def on_message( self, context: MiddlewareContext[Any], call_next: CallNext[Any, Any] ) -> Any: - """Log all messages.""" + """Log messages for configured methods.""" if self.methods and context.method not in self.methods: return await call_next(context) - request_start_log_message = self._create_before_message( - context, "request_start" - ) - - formatted_message = self._format_message(request_start_log_message) - self.logger.log(self.log_level, f"Processing message: {formatted_message}") + self._log_message(self._create_before_message(context)) + start_time = time.perf_counter() try: result = await call_next(context) - request_success_log_message = self._create_after_message( - context, "request_success" - ) - - formatted_message = self._format_message(request_success_log_message) - self.logger.log(self.log_level, f"Completed message: {formatted_message}") + self._log_message(self._create_after_message(context, start_time)) return result except Exception as e: - self.logger.log( - logging.ERROR, f"Failed message: {context.method or 'unknown'} - {e}" + self._log_message( + self._create_error_message(context, start_time, e), logging.ERROR ) raise @@ -184,7 +189,7 @@ class LoggingMiddleware(BaseLoggingMiddleware): payload_serializer: Callable that converts objects to a JSON string for the payload. If not provided, uses FastMCP's default tool serializer. """ - self.logger: Logger = logger or logging.getLogger("fastmcp.requests") + self.logger: Logger = logger or logging.getLogger("fastmcp.middleware.logging") self.log_level = log_level self.include_payloads: bool = include_payloads self.include_payload_length: bool = include_payload_length @@ -234,7 +239,9 @@ class StructuredLoggingMiddleware(BaseLoggingMiddleware): payload_serializer: Callable that converts objects to a JSON string for the payload. If not provided, uses FastMCP's default tool serializer. """ - self.logger: Logger = logger or logging.getLogger("fastmcp.structured") + self.logger: Logger = logger or logging.getLogger( + "fastmcp.middleware.structured_logging" + ) self.log_level: int = log_level self.include_payloads: bool = include_payloads self.include_payload_length: bool = include_payload_length @@ -243,3 +250,7 @@ class StructuredLoggingMiddleware(BaseLoggingMiddleware): self.payload_serializer: Callable[[Any], str] | None = payload_serializer self.max_payload_length: int | None = None self.structured_logging: bool = True + + +def _get_duration_ms(start_time: float, /) -> float: + return round(number=(time.perf_counter() - start_time) * 1000, ndigits=2) diff --git a/tests/server/auth/providers/test_azure.py b/tests/server/auth/providers/test_azure.py index 2c08df8d2..ec360403a 100644 --- a/tests/server/auth/providers/test_azure.py +++ b/tests/server/auth/providers/test_azure.py @@ -2,11 +2,15 @@ import os from unittest.mock import patch -from urllib.parse import urlparse +from urllib.parse import parse_qs, urlparse import pytest +from mcp.server.auth.provider import AuthorizationParams +from mcp.shared.auth import OAuthClientInformationFull +from pydantic import AnyUrl from fastmcp.server.auth.providers.azure import AzureProvider +from fastmcp.server.auth.providers.jwt import JWTVerifier class TestAzureProvider: @@ -95,6 +99,7 @@ class TestAzureProvider: client_id="test_client", client_secret="test_secret", tenant_id="test-tenant", + required_scopes=["User.Read"], ) # Check defaults @@ -109,6 +114,7 @@ class TestAzureProvider: client_secret="test_secret", tenant_id="my-tenant-id", base_url="https://myserver.com", + required_scopes=["User.Read"], ) # Check that endpoints use the correct Azure OAuth2 v2.0 endpoints with tenant @@ -131,6 +137,7 @@ class TestAzureProvider: client_id="test_client", client_secret="test_secret", tenant_id="organizations", + required_scopes=["User.Read"], ) parsed = urlparse(provider1._upstream_authorization_endpoint) assert "/organizations/" in parsed.path @@ -140,6 +147,7 @@ class TestAzureProvider: client_id="test_client", client_secret="test_secret", tenant_id="consumers", + required_scopes=["User.Read"], ) parsed = urlparse(provider2._upstream_authorization_endpoint) assert "/consumers/" in parsed.path @@ -162,3 +170,107 @@ class TestAzureProvider: # Provider should initialize successfully with these scopes assert provider is not None + + def test_init_does_not_require_api_client_id_anymore(self): + """API client ID is no longer required; audience is client_id.""" + provider = AzureProvider( + client_id="test_client", + client_secret="test_secret", + tenant_id="test-tenant", + required_scopes=["User.Read"], + ) + assert provider is not None + + def test_init_with_custom_audience_uses_jwt_verifier(self): + """When audience is provided, JWTVerifier is configured with JWKS and issuer.""" + provider = AzureProvider( + client_id="test_client", + client_secret="test_secret", + tenant_id="my-tenant", + identifier_uri="api://my-api", + required_scopes=[".default"], + ) + + assert provider._token_validator is not None + assert isinstance(provider._token_validator, JWTVerifier) + verifier = provider._token_validator + assert verifier.jwks_uri is not None + assert verifier.jwks_uri.startswith( + "https://login.microsoftonline.com/my-tenant/discovery/v2.0/keys" + ) + assert verifier.issuer == "https://login.microsoftonline.com/my-tenant/v2.0" + assert verifier.audience == "test_client" + + @pytest.mark.asyncio + async def test_authorize_filters_resource_and_prefixes_scopes_with_audience(self): + """authorize() should drop resource and prefix non-openid scopes with audience.""" + provider = AzureProvider( + client_id="test_client", + client_secret="test_secret", + tenant_id="common", + identifier_uri="api://my-api", + required_scopes=["read", "write"], + base_url="https://srv.example", + ) + + client = OAuthClientInformationFull( + client_id="dummy", + client_secret="secret", + redirect_uris=[AnyUrl("http://localhost:12345/callback")], + ) + + params = AuthorizationParams( + redirect_uri=AnyUrl("http://localhost:12345/callback"), + redirect_uri_provided_explicitly=True, + scopes=["read", "profile"], + state="abc", + code_challenge="xyz", + resource="https://should.be.ignored", + ) + + url = await provider.authorize(client, params) + + parsed = urlparse(url) + qs = parse_qs(parsed.query) + assert "resource" not in qs + scope_value = qs.get("scope", [""])[0] + scope_parts = scope_value.split(" ") if scope_value else [] + assert "api://my-api/read" in scope_parts + assert "api://my-api/profile" in scope_parts + + @pytest.mark.asyncio + async def test_authorize_appends_unprefixed_additional_scopes(self): + """authorize() should append additional_authorize_scopes without prefixing them.""" + provider = AzureProvider( + client_id="test_client", + client_secret="test_secret", + tenant_id="common", + identifier_uri="api://my-api", + required_scopes=["read"], + base_url="https://srv.example", + additional_authorize_scopes=["Mail.Read", "User.Read"], + ) + + client = OAuthClientInformationFull( + client_id="dummy", + client_secret="secret", + redirect_uris=[AnyUrl("http://localhost:12345/callback")], + ) + + params = AuthorizationParams( + redirect_uri=AnyUrl("http://localhost:12345/callback"), + redirect_uri_provided_explicitly=True, + scopes=["read"], + state="abc", + code_challenge="xyz", + ) + + url = await provider.authorize(client, params) + + parsed = urlparse(url) + qs = parse_qs(parsed.query) + scope_value = qs.get("scope", [""])[0] + scope_parts = scope_value.split(" ") if scope_value else [] + assert "api://my-api/read" in scope_parts + assert "Mail.Read" in scope_parts + assert "User.Read" in scope_parts diff --git a/tests/server/middleware/test_logging.py b/tests/server/middleware/test_logging.py index 2bbeda9fa..f63165a66 100644 --- a/tests/server/middleware/test_logging.py +++ b/tests/server/middleware/test_logging.py @@ -1,11 +1,10 @@ """Tests for logging middleware.""" import datetime -import json import logging -import re +from collections.abc import Generator from typing import Any, Literal, TypeVar -from unittest.mock import AsyncMock, MagicMock +from unittest.mock import AsyncMock, MagicMock, patch import mcp import mcp.types @@ -28,15 +27,15 @@ FIXED_DATE = datetime.datetime(2023, 1, 1, tzinfo=datetime.timezone.utc) T = TypeVar("T") -def remove_line_numbers(logs: str) -> str: - """Remove line numbers from log messages.""" - trimmed_logs = "" - lines = logs.split("\n") - for line in lines: - # Match only the first `:\d+ ` - line = re.sub(pattern=r":\d+ ", repl=":LINE_NUMBER ", string=line, count=1) - trimmed_logs += line + "\n" - return trimmed_logs +def get_log_lines( + caplog: pytest.LogCaptureFixture, module: str | None = None +) -> list[str]: + """Get log lines from a caplog fixture.""" + return [ + record.message + for record in caplog.records + if (module or "logging") in record.name + ] def new_mock_context( @@ -55,6 +54,17 @@ def new_mock_context( return context +@pytest.fixture(autouse=True) +def mock_duration_ms() -> Generator[float, None]: + """Mock duration_ms.""" + patched = patch( + "fastmcp.server.middleware.logging._get_duration_ms", return_value=0.02 + ) + patched.start() + yield + patched.stop() + + @pytest.fixture def mock_context(): """Create a mock middleware context.""" @@ -81,15 +91,14 @@ class TestStructuredLoggingMiddleware: def test_init_default(self): """Test default initialization.""" - middleware = LoggingMiddleware() + middleware = StructuredLoggingMiddleware() - assert middleware.logger.name == "fastmcp.requests" + assert middleware.logger.name == "fastmcp.middleware.structured_logging" assert middleware.log_level == logging.INFO assert middleware.include_payloads is False - assert middleware.max_payload_length == 1000 assert middleware.include_payload_length is False assert middleware.estimate_payload_tokens is False - assert middleware.structured_logging is False + assert middleware.structured_logging is True def test_init_custom(self): """Test custom initialization.""" @@ -112,14 +121,12 @@ class TestStructuredLoggingMiddleware: """Test message formatting without payloads.""" middleware = StructuredLoggingMiddleware() - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) assert message == snapshot( { - "event": "test_event", - "timestamp": "2023-01-01T00:00:00+00:00", + "event": "request_start", "source": "client", - "type": "request", "method": "test_method", } ) @@ -130,14 +137,12 @@ class TestStructuredLoggingMiddleware: """Test message formatting with payloads.""" middleware = StructuredLoggingMiddleware(include_payloads=True) - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) assert message == snapshot( { - "event": "test_event", - "timestamp": "2023-01-01T00:00:00+00:00", + "event": "request_start", "source": "client", - "type": "request", "method": "test_method", "payload": '{"method":"tools/call","params":{"_meta":null,"name":"test_method","arguments":{"param":"value"}}}', "payload_type": "CallToolRequest", @@ -147,14 +152,12 @@ class TestStructuredLoggingMiddleware: def test_calculate_response_size(self, mock_context: MiddlewareContext[Any]): """Test response size calculation.""" middleware = StructuredLoggingMiddleware(include_payload_length=True) - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) assert message == snapshot( { - "event": "test_event", - "timestamp": "2023-01-01T00:00:00+00:00", + "event": "request_start", "source": "client", - "type": "request", "method": "test_method", "payload_length": 98, } @@ -167,14 +170,12 @@ class TestStructuredLoggingMiddleware: middleware = StructuredLoggingMiddleware( include_payload_length=True, estimate_payload_tokens=True ) - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) assert message == snapshot( { - "event": "test_event", - "timestamp": "2023-01-01T00:00:00+00:00", + "event": "request_start", "source": "client", - "type": "request", "method": "test_method", "payload_tokens": 24, "payload_length": 98, @@ -195,11 +196,13 @@ class TestStructuredLoggingMiddleware: assert result == "test_result" assert mock_call_next.called - assert remove_line_numbers(caplog.text) == snapshot("""\ -INFO fastmcp.structured:logging.py:LINE_NUMBER Processing message: {"event": "request_start", "timestamp": "2023-01-01T00:00:00+00:00", "method": "test_method", "type": "request", "source": "client"} -INFO fastmcp.structured:logging.py:LINE_NUMBER Completed message: {"event": "request_success", "timestamp": "2023-01-01T00:00:00+00:00", "method": "test_method", "type": "request", "source": "client"} -""") + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client"}', + '{"event": "request_success", "method": "test_method", "source": "client", "duration_ms": 0.02}', + ] + ) async def test_on_message_failure( self, mock_context: MiddlewareContext[Any], caplog: pytest.LogCaptureFixture @@ -212,8 +215,12 @@ INFO fastmcp.structured:logging.py:LINE_NUMBER Completed message: {"event": with pytest.raises(ValueError): await middleware.on_message(mock_context, mock_call_next) - assert "Processing message:" in caplog.text - assert "Failed message: test_method - test error" in caplog.text + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client"}', + '{"event": "request_error", "method": "test_method", "source": "client", "duration_ms": 0.02, "error": "test error"}', + ] + ) class TestLoggingMiddleware: @@ -222,7 +229,7 @@ class TestLoggingMiddleware: def test_init_default(self): """Test default initialization.""" middleware = LoggingMiddleware() - assert middleware.logger.name == "fastmcp.requests" + assert middleware.logger.name == "fastmcp.middleware.logging" assert middleware.log_level == logging.INFO assert middleware.include_payloads is False assert middleware.include_payload_length is False @@ -231,11 +238,11 @@ class TestLoggingMiddleware: def test_format_message(self, mock_context: MiddlewareContext[Any]): """Test message formatting.""" middleware = LoggingMiddleware() - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) formatted = middleware._format_message(message) assert formatted == snapshot( - "event=test_event timestamp=2023-01-01T00:00:00+00:00 method=test_method type=request source=client" + "event=request_start method=test_method source=client" ) def test_create_before_message_long_payload( @@ -244,12 +251,13 @@ class TestLoggingMiddleware: """Test message formatting with long payload truncation.""" middleware = LoggingMiddleware(include_payloads=True, max_payload_length=10) - message = middleware._create_before_message(mock_context, "test_event") + message = middleware._create_before_message(mock_context) formatted = middleware._format_message(message) - assert "payload=" in formatted - assert "..." in formatted + assert formatted == snapshot( + 'event=request_start method=test_method source=client payload={"method":... payload_type=CallToolRequest' + ) async def test_on_message_failure( self, mock_context: MiddlewareContext[Any], caplog: pytest.LogCaptureFixture @@ -263,18 +271,12 @@ class TestLoggingMiddleware: 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] + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client"}', + '{"event": "request_error", "method": "test_method", "source": "client", "duration_ms": 0.02, "error": "test error"}', + ] + ) async def test_on_message_with_pydantic_types_in_payload( self, @@ -299,37 +301,11 @@ class TestLoggingMiddleware: 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", - } + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client", "payload": "{\\"method\\":\\"resources/read\\",\\"params\\":{\\"_meta\\":null,\\"uri\\":\\"test://example/1\\"}}", "payload_type": "ReadResourceRequest"}', + '{"event": "request_success", "method": "test_method", "source": "client", "duration_ms": 0.02}', + ] ) async def test_on_message_with_resource_template_in_payload( @@ -354,23 +330,11 @@ class TestLoggingMiddleware: 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", - } + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client", "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"}', + '{"event": "request_success", "method": "test_method", "source": "client", "duration_ms": 0.02}', + ] ) async def test_on_message_with_nonserializable_payload_falls_back_to_str( @@ -399,23 +363,11 @@ class TestLoggingMiddleware: 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", - } + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client", "payload": "{\\"method\\":\\"tools/call\\",\\"params\\":{\\"_meta\\":null,\\"name\\":\\"test_method\\",\\"arguments\\":{\\"obj\\":\\"NON_SERIALIZABLE\\"}}}", "payload_type": "CallToolRequest"}', + '{"event": "request_success", "method": "test_method", "source": "client", "duration_ms": 0.02}', + ] ) async def test_on_message_with_custom_serializer_applied( @@ -446,23 +398,11 @@ class TestLoggingMiddleware: 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", - } + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "test_method", "source": "client", "payload": "CUSTOM_PAYLOAD", "payload_type": "CallToolRequest"}', + '{"event": "request_success", "method": "test_method", "source": "client", "duration_ms": 0.02}', + ] ) @@ -545,9 +485,6 @@ class TestLoggingMiddlewareIntegration: ): """Test that logging middleware captures successful operations.""" logging_middleware = LoggingMiddleware(methods=["tools/call"]) - logging_middleware._get_timestamp_from_context = ( # ty: ignore[invalid-assignment] - lambda _: FIXED_DATE.isoformat() - ) logging_server.add_middleware(logging_middleware) @@ -563,16 +500,14 @@ class TestLoggingMiddlewareIntegration: ) # Should have processing and completion logs for both operations - assert remove_line_numbers(caplog.text) == snapshot("""\ -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type CallToolRequest -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 -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 -INFO mcp.server.lowlevel.server:server.py:LINE_NUMBER Processing request of type CallToolRequest -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 -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 - -""") + assert get_log_lines(caplog) == snapshot( + [ + "event=request_start method=tools/call source=client", + "event=request_success method=tools/call source=client duration_ms=0.02", + "event=request_start method=tools/call source=client", + "event=request_success method=tools/call source=client duration_ms=0.02", + ] + ) async def test_logging_middleware_logs_failures( self, logging_server: FastMCP, caplog: pytest.LogCaptureFixture @@ -591,8 +526,9 @@ INFO fastmcp.requests:logging.py:LINE_NUMBER Completed message: event=reques log_text = caplog.text # Should have processing and failure logs - assert "Processing message:" in log_text - assert "Failed message: tools/call" in log_text + assert log_text.splitlines()[-1] == snapshot( + "ERROR fastmcp.middleware.logging:logging.py:122 event=request_error method=tools/call source=client duration_ms=0.02 error=Error calling tool 'operation_with_error': Operation failed intentionally" + ) async def test_logging_middleware_with_payloads( self, logging_server: FastMCP, caplog: pytest.LogCaptureFixture @@ -602,32 +538,18 @@ INFO fastmcp.requests:logging.py:LINE_NUMBER Completed message: event=reques middleware = LoggingMiddleware( include_payloads=True, max_payload_length=500, methods=["tools/call"] ) - middleware._get_timestamp_from_context = ( # ty: ignore[invalid-assignment] - lambda _: FIXED_DATE.isoformat() - ) logging_server.add_middleware(middleware) 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("""\ -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 -DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools - -""") + assert get_log_lines(caplog) == snapshot( + [ + 'event=request_start method=tools/call source=client payload={"_meta":null,"name":"simple_operation","arguments":{"data":"payload_test"}} payload_type=CallToolRequestParams', + "event=request_success method=tools/call source=client duration_ms=0.02", + ] + ) async def test_structured_logging_middleware_produces_json( self, logging_server: FastMCP, caplog: pytest.LogCaptureFixture @@ -637,9 +559,6 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] logging_middleware = StructuredLoggingMiddleware( include_payloads=True, methods=["tools/call"] ) - logging_middleware._get_timestamp_from_context = ( # ty: ignore[invalid-assignment] - lambda _: FIXED_DATE.isoformat() - ) logging_server.add_middleware(logging_middleware) @@ -649,30 +568,12 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] name="simple_operation", arguments={"data": "json_test"} ) - # Extract JSON log entries - log_lines = [ - record.message - for record in caplog.records - if record.name == "fastmcp.structured" - ] - - assert len(log_lines) >= 2 # Should have start and success entries - - # 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"} -DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] Handler called: list_tools - -""") + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "tools/call", "source": "client", "payload": "{\\"_meta\\":null,\\"name\\":\\"simple_operation\\",\\"arguments\\":{\\"data\\":\\"json_test\\"}}", "payload_type": "CallToolRequestParams"}', + '{"event": "request_success", "method": "tools/call", "source": "client", "duration_ms": 0.02}', + ] + ) async def test_structured_logging_middleware_handles_errors( self, logging_server: FastMCP, caplog: pytest.LogCaptureFixture @@ -680,9 +581,6 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] """Test structured logging of errors with JSON format.""" logging_middleware = StructuredLoggingMiddleware(methods=["tools/call"]) - logging_middleware._get_timestamp_from_context = ( # ty: ignore[invalid-assignment] - lambda _: FIXED_DATE.isoformat() - ) logging_server.add_middleware(logging_middleware) @@ -694,19 +592,13 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] "operation_with_error", {"should_fail": True} ) - # 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, + assert get_log_lines(caplog) == snapshot( + [ + '{"event": "request_start", "method": "tools/call", "source": "client"}', + '{"event": "request_error", "method": "tools/call", "source": "client", "duration_ms": 0.02, "error": "Error calling tool \'operation_with_error\': Operation failed intentionally"}', + ] ) - # 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 ): @@ -731,16 +623,18 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] await client.get_prompt("test_prompt") await client.list_resources() - log_text = caplog.text - - # Should have logs for all different operation types - # Note: Different operations may have different method names - processing_count = log_text.count("Processing message:") - completion_count = log_text.count("Completed message:") - - # Should have processed all 4 operations - assert processing_count == 4 - assert completion_count == 4 + assert get_log_lines(caplog) == snapshot( + [ + "event=request_start method=tools/call source=client", + "event=request_success method=tools/call source=client duration_ms=0.02", + "event=request_start method=resources/read source=client", + "event=request_success method=resources/read source=client duration_ms=0.02", + "event=request_start method=prompts/get source=client", + "event=request_success method=prompts/get source=client duration_ms=0.02", + "event=request_start method=resources/list source=client", + "event=request_success method=resources/list source=client duration_ms=0.02", + ] + ) async def test_logging_middleware_custom_configuration( self, logging_server: FastMCP @@ -770,5 +664,7 @@ DEBUG fastmcp.fastmcp.server.server:server.py:LINE_NUMBER [LoggingTestServer] # Check that our custom logger captured the logs log_output = log_buffer.getvalue() - assert "Processing message:" in log_output - assert "payload=" in log_output + assert log_output == snapshot("""\ +event=request_start method=tools/call source=client payload={"_meta":null,"name":"simple_operation","arguments":{"data":"custom_test"}} payload_type=CallToolRequestParams +event=request_success method=tools/call source=client duration_ms=0.02 +""")