Add request duration to logging middleware

[strawgate]

Enhancement

We have timing middleware but the logging middleware logs the request name and args, having it log duration on completion of the request would be very nice

[marvin-context-protocol]

Claude finished @strawgate's task —— View job

---

Analysis Complete

I've thoroughly investigated issue #1973 regarding adding request duration to the logging middleware. Here are my findings and recommendations.

---

Current State

Timing Middleware (src/fastmcp/server/middleware/timing.py:10-58):

• Uses time.perf_counter() to measure request duration
• Logs timing information as: "Request {method} completed in {duration_ms:.2f}ms"
• Operates on the on_request() hook (only for request messages, not notifications)
• Provides timing for both successful requests and failures

Logging Middleware (src/fastmcp/server/middleware/logging.py:143-196):

• Logs comprehensive request/response information
• Currently logs: event, timestamp, method, type, source, and optionally payloads
• Uses on_message() hook (handles all messages including notifications)
• Logs two events: request_start and request_success (or error)
• Does NOT currently track duration

Key Architectural Difference:

• TimingMiddleware uses on_request() (requests only)
• LoggingMiddleware uses on_message() (all messages including notifications)

---

Related Work

PR #1974 (Draft, Open):

• Already implements duration tracking in LoggingMiddleware
• Author (@strawgate) noted: "We should probably also remove the timestamp (or make it optional)"
• This PR addresses the exact enhancement requested in issue Add request duration to logging middleware #1973

---

Recommendation

The enhancement has already been implemented in PR #1974, which adds request duration tracking to the logging middleware following the same pattern as TimingMiddleware.

Suggested Improvements to PR #1974:

Based on the codebase patterns and @strawgate's comment, I recommend:

1. Add include_duration parameter (default True) to LoggingMiddleware.__init__() and StructuredLoggingMiddleware.__init__()

   • Provides consistency with other include_* parameters
   • Allows users to disable if they only want timing from TimingMiddleware

2. Consider making timestamp optional (as @strawgate suggested)

   • Add include_timestamp parameter (default True for backward compatibility)
   • Reduces log verbosity when using both LoggingMiddleware + TimingMiddleware

3. Add duration to both success and error cases

   • Current implementation should handle both paths
   • Mirrors TimingMiddleware behavior (lines 43-57)

4. Update tests to verify:

   • Duration is logged in request_success events
   • Duration format matches TimingMiddleware (.2f precision)
   • Duration is present even when request fails
   • New include_duration parameter works correctly

5. Update documentation:

   • Add example showing LoggingMiddleware with duration
   • Clarify difference between LoggingMiddleware (comprehensive logging with duration) vs TimingMiddleware (timing-focused, requests only)

---

Implementation Pattern

The implementation should follow this pattern (based on TimingMiddleware:43-57):

async def on_message(
    self, context: MiddlewareContext[Any], call_next: CallNext[Any, Any]
) -> Any:
    if self.methods and context.method not in self.methods:
        return await call_next(context)

    start_time = time.perf_counter()  # Capture start time
    
    request_start_log_message = self._create_before_message(context, "request_start")
    # ... log start message ...

    try:
        result = await call_next(context)
        duration_ms = (time.perf_counter() - start_time) * 1000  # Calculate duration
        
        request_success_log_message = self._create_after_message(context, "request_success")
        if self.include_duration:  # Make it configurable
            request_success_log_message["duration_ms"] = f"{duration_ms:.2f}"
        
        # ... log success message ...
        return result
    except Exception as e:
        duration_ms = (time.perf_counter() - start_time) * 1000
        # ... log error with duration ...
        raise

---

Related Issues and Pull Requests

Repository	Issue or PR	Relevance
jlowin/fastmcp	PR #1974: Add request duration to logging middleware	Directly implements the requested feature
jlowin/fastmcp	PR #1805: Refactor Logging and Structured Logging Middleware	Recent refactoring that consolidated logging middleware, merged Sep 14

---

Related Files

Repository	File	Relevance	Key Sections
jlowin/fastmcp	src/fastmcp/server/middleware/timing.py	Reference implementation for duration tracking	43-57
jlowin/fastmcp	src/fastmcp/server/middleware/logging.py	Target file for enhancement	110-141
jlowin/fastmcp	tests/server/middleware/test_timing.py	Reference for timing tests	47-69
jlowin/fastmcp	tests/server/middleware/test_logging.py	Target tests for enhancement	79-100

---

Conclusion

PR #1974 already implements the requested feature. The PR should be reviewed, potentially enhanced with the suggestions above, and merged. The key remaining work is:

1. Review and test PR Updates to Logging Middleware #1974
2. Consider adding include_duration and include_timestamp configuration options
3. Ensure tests cover both structured and non-structured logging paths
4. Update documentation to clarify when to use LoggingMiddleware vs TimingMiddleware

---