From 31fcc1eb44707ba0ac4bc472af7dba9dd101b914 Mon Sep 17 00:00:00 2001
From: Copilot <198982749+Copilot@users.noreply.github.com>
Date: Mon, 15 Dec 2025 09:50:52 -0800
Subject: [PATCH] Add request duration to LogRequestHandlerCompleted and
 LogRequestHandlerException log messages (#1092)

Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com>
Co-authored-by: stephentoub <2642209+stephentoub@users.noreply.github.com>
---
 .../McpSessionHandler.cs                      | 27 ++++++++++++-------
 1 file changed, 17 insertions(+), 10 deletions(-)

diff --git a/src/ModelContextProtocol.Core/McpSessionHandler.cs b/src/ModelContextProtocol.Core/McpSessionHandler.cs
index dd68146..0b915c9 100644
--- a/src/ModelContextProtocol.Core/McpSessionHandler.cs
+++ b/src/ModelContextProtocol.Core/McpSessionHandler.cs
@@ -179,8 +179,6 @@ internal sealed partial class McpSessionHandler : IAsyncDisposable
 
                         if (!isUserCancellation && message is JsonRpcRequest request)
                         {
-                            LogRequestHandlerException(EndpointName, request.Method, ex);
-
                             JsonRpcErrorDetail detail = ex switch
                             {
                                 UrlElicitationRequiredException urlException => new()
@@ -282,8 +280,19 @@ internal sealed partial class McpSessionHandler : IAsyncDisposable
             switch (message)
             {
                 case JsonRpcRequest request:
-                    var result = await HandleRequest(request, cancellationToken).ConfigureAwait(false);
-                    AddResponseTags(ref tags, activity, result, method);
+                    LogRequestHandlerCalled(EndpointName, request.Method);
+                    long requestStartingTimestamp = Stopwatch.GetTimestamp();
+                    try
+                    {
+                        var result = await HandleRequest(request, cancellationToken).ConfigureAwait(false);
+                        LogRequestHandlerCompleted(EndpointName, request.Method, GetElapsed(requestStartingTimestamp).TotalMilliseconds);
+                        AddResponseTags(ref tags, activity, result, method);
+                    }
+                    catch (Exception ex)
+                    {
+                        LogRequestHandlerException(EndpointName, request.Method, GetElapsed(requestStartingTimestamp).TotalMilliseconds, ex);
+                        throw;
+                    }
                     break;
 
                 case JsonRpcNotification notification:
@@ -354,9 +363,7 @@ internal sealed partial class McpSessionHandler : IAsyncDisposable
             throw new McpProtocolException($"Method '{request.Method}' is not available.", McpErrorCode.MethodNotFound);
         }
 
-        LogRequestHandlerCalled(EndpointName, request.Method);
         JsonNode? result = await handler(request, cancellationToken).ConfigureAwait(false);
-        LogRequestHandlerCompleted(EndpointName, request.Method);
 
         await SendMessageAsync(new JsonRpcResponse
         {
@@ -882,11 +889,11 @@ internal sealed partial class McpSessionHandler : IAsyncDisposable
     [LoggerMessage(Level = LogLevel.Information, Message = "{EndpointName} method '{Method}' request handler called.")]
     private partial void LogRequestHandlerCalled(string endpointName, string method);
 
-    [LoggerMessage(Level = LogLevel.Information, Message = "{EndpointName} method '{Method}' request handler completed.")]
-    private partial void LogRequestHandlerCompleted(string endpointName, string method);
+    [LoggerMessage(Level = LogLevel.Information, Message = "{EndpointName} method '{Method}' request handler completed in {ElapsedMilliseconds}ms.")]
+    private partial void LogRequestHandlerCompleted(string endpointName, string method, double elapsedMilliseconds);
 
-    [LoggerMessage(Level = LogLevel.Warning, Message = "{EndpointName} method '{Method}' request handler failed.")]
-    private partial void LogRequestHandlerException(string endpointName, string method, Exception exception);
+    [LoggerMessage(Level = LogLevel.Warning, Message = "{EndpointName} method '{Method}' request handler failed in {ElapsedMilliseconds}ms.")]
+    private partial void LogRequestHandlerException(string endpointName, string method, double elapsedMilliseconds, Exception exception);
 
     [LoggerMessage(Level = LogLevel.Information, Message = "{EndpointName} received request for unknown request ID '{RequestId}'.")]
     private partial void LogNoRequestFoundForMessageWithId(string endpointName, RequestId requestId);