Add duration logging to LogRequestHandlerException and consolidate timing in HandleMessageAsync

Co-authored-by: stephentoub <[email protected]>

Author: Copilot

src/ModelContextProtocol.Core/McpSessionHandler.cs

@@ -179,8 +179,6 @@ ex is OperationCanceledException &&
 
                         if (!isUserCancellation && message is JsonRpcRequest request)
                         {
-                            LogRequestHandlerException(EndpointName, request.Method, ex);
-
                             JsonRpcErrorDetail detail = ex switch
                             {
                                 UrlElicitationRequiredException urlException => new()
@@ -282,8 +280,18 @@ private async Task HandleMessageAsync(JsonRpcMessage message, CancellationToken
             switch (message)
             {
                 case JsonRpcRequest request:
-                    var result = await HandleRequest(request, cancellationToken).ConfigureAwait(false);
-                    AddResponseTags(ref tags, activity, result, 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:
@@ -355,9 +363,7 @@ private void HandleMessageWithId(JsonRpcMessage message, JsonRpcMessageWithId me
         }
 
         LogRequestHandlerCalled(EndpointName, request.Method);
-        long startingTimestamp = Stopwatch.GetTimestamp();
         JsonNode? result = await handler(request, cancellationToken).ConfigureAwait(false);
-        LogRequestHandlerCompleted(EndpointName, request.Method, GetElapsed(startingTimestamp).TotalMilliseconds);
 
         await SendMessageAsync(new JsonRpcResponse
         {
@@ -886,8 +892,8 @@ private static McpProtocolException CreateRemoteProtocolException(JsonRpcError e
     [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);