Log server cancellation errors at info level (#2527)

grpc · Sep 7, 2024 · 3ed9fb9 · 3ed9fb9
1 parent 5322d6b
commit 3ed9fb9
Show file tree

Hide file tree

Showing 3 changed files with 20 additions and 3 deletions.
diff --git a/src/Grpc.AspNetCore.Server/Internal/GrpcServerLog.cs b/src/Grpc.AspNetCore.Server/Internal/GrpcServerLog.cs
@@ -1,4 +1,4 @@
-#region Copyright notice and license
+#region Copyright notice and license
 
 // Copyright 2019 The gRPC Authors
 //
@@ -104,6 +104,9 @@ internal static class GrpcServerLog
     private static readonly Action<ILogger, Exception?> _deadlineStopped =
         LoggerMessage.Define(LogLevel.Trace, new EventId(27, "DeadlineStopped"), "Request deadline stopped.");
 
+    private static readonly Action<ILogger, string, Exception?> _serviceMethodCanceled =
+        LoggerMessage.Define<string>(LogLevel.Information, new EventId(28, "ServiceMethodCanceled"), "Service method '{ServiceMethod}' canceled.");
+
     internal static void DeadlineStopped(ILogger logger)
     {
         _deadlineStopped(logger, null);
@@ -238,4 +241,9 @@ public static void DeadlineTimerRescheduled(ILogger logger, TimeSpan remaining)
     {
         _deadlineTimerRescheduled(logger, remaining, null);
     }
+
+    public static void ServiceMethodCanceled(ILogger logger, string serviceMethod, Exception ex)
+    {
+        _serviceMethodCanceled(logger, serviceMethod, ex);
+    }
 }
diff --git a/src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs b/src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs
@@ -193,7 +193,16 @@ private void ProcessHandlerError(Exception ex, string method)
         }
         else
         {
-            GrpcServerLog.ErrorExecutingServiceMethod(Logger, method, ex);
+            if (ex is OperationCanceledException or IOException && CancellationTokenCore.IsCancellationRequested)
+            {
+                // Request cancellation can cause OCE and IOException.
+                // When the request has been canceled log these error types at the info-level to avoid creating error-level noise.
+                GrpcServerLog.ServiceMethodCanceled(Logger, method, ex);
+            }
+            else
+            {
+                GrpcServerLog.ErrorExecutingServiceMethod(Logger, method, ex);
+            }
 
             var message = ErrorMessageHelper.BuildErrorMessage("Exception was thrown by handler.", ex, Options.EnableDetailedErrors);
 

diff --git a/test/FunctionalTests/Client/StreamingTests.cs b/test/FunctionalTests/Client/StreamingTests.cs
@@ -429,7 +429,7 @@ async Task<DataComplete> ClientStreamedData(IAsyncStreamReader<DataMessage> requ
         AssertHasLog(LogLevel.Information, "GrpcStatusError", "Call failed with gRPC error status. Status code: 'Cancelled', Message: ''.");
 
         await TestHelpers.AssertIsTrueRetryAsync(
-            () => HasLog(LogLevel.Error, "ErrorExecutingServiceMethod", "Error when executing service method 'ClientStreamedDataTimeout'."),
+            () => HasLog(LogLevel.Information, "ServiceMethodCanceled", "Service method 'ClientStreamedDataTimeout' canceled."),
             "Wait for server error so it doesn't impact other tests.").DefaultTimeout();
     }