Extra deadline logs, don't write message when deadline exceeded

src/Grpc.AspNetCore.Server/Internal/CallHandlers/ClientStreamingServerCallHandler.cs

@@ -53,6 +53,13 @@ protected override async Task HandleCallAsyncCore(HttpContext httpContext, HttpC
                 throw new RpcException(new Status(StatusCode.Cancelled, "No message returned from method."));
             }
 
+            if (serverCallContext.DeadlineManager != null && serverCallContext.DeadlineManager.CallComplete)
+            {
+                // The deadline has been exceeded and the call has been completed.
+                // There is no point trying to write to the response because it has been finished.
+                return;
+            }
+
             var responseBodyWriter = httpContext.Response.BodyWriter;
             await responseBodyWriter.WriteMessageAsync(response, serverCallContext, MethodInvoker.Method.ResponseMarshaller.ContextualSerializer, canFlush: false);
         }

src/Grpc.AspNetCore.Server/Internal/CallHandlers/UnaryServerCallHandler.cs

@@ -54,6 +54,13 @@ protected override async Task HandleCallAsyncCore(HttpContext httpContext, HttpC
                 throw new RpcException(new Status(StatusCode.Cancelled, "No message returned from method."));
             }
 
+            if (serverCallContext.DeadlineManager != null && serverCallContext.DeadlineManager.CallComplete)
+            {
+                // The deadline has been exceeded and the call has been completed.
+                // There is no point trying to write to the response because it has been finished.
+                return;
+            }
+
             var responseBodyWriter = httpContext.Response.BodyWriter;
             await responseBodyWriter.WriteMessageAsync(response, serverCallContext, MethodInvoker.Method.ResponseMarshaller.ContextualSerializer, canFlush: false);
         }

src/Grpc.AspNetCore.Server/Internal/GrpcServerLog.cs

@@ -99,6 +99,22 @@ internal static class GrpcServerLog
         private static readonly Action<ILogger, TimeSpan, Exception?> _deadlineTimerRescheduled =
             LoggerMessage.Define<TimeSpan>(LogLevel.Trace, new EventId(25, "DeadlineTimerRescheduled"), "Deadline timer triggered but {Remaining} remaining before deadline exceeded. Deadline timer rescheduled.");
 
+        private static readonly Action<ILogger, TimeSpan, Exception?> _deadlineStarted =
+            LoggerMessage.Define<TimeSpan>(LogLevel.Trace, new EventId(26, "DeadlineStarted"), "Request deadline timeout of {Timeout} started.");
+
+        private static readonly Action<ILogger, Exception?> _deadlineStopped =
+            LoggerMessage.Define(LogLevel.Trace, new EventId(27, "DeadlineStopped"), "Request deadline stopped.");
+
+        internal static void DeadlineStopped(ILogger logger)
+        {
+            _deadlineStopped(logger, null);
+        }
+
+        public static void DeadlineStarted(ILogger logger, TimeSpan timeout)
+        {
+            _deadlineStarted(logger, timeout, null);
+        }
+
         public static void DeadlineExceeded(ILogger logger, TimeSpan timeout)
         {
             _deadlineExceeded(logger, timeout, null);

src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs

@@ -163,6 +163,7 @@ private async Task ProcessHandlerErrorAsyncCore(Exception ex, string method)
             {
                 DeadlineManager.Lock.Release();
                 await DeadlineManager.DisposeAsync();
+                GrpcServerLog.DeadlineStopped(Logger);
             }
         }
 
@@ -238,35 +239,15 @@ internal Task EndCallAsync()
                 return Task.CompletedTask;
             }
 
-            var lockTask = DeadlineManager.Lock.WaitAsync();
-            if (lockTask.IsCompletedSuccessfully)
-            {
-                Task disposeTask;
-                try
-                {
-                    EndCallCore();
-                }
-                finally
-                {
-                    DeadlineManager.Lock.Release();
-
-                    // Can't return from a finally
-                    disposeTask = DeadlineManager.DisposeAsync().AsTask();
-                }
-
-                return disposeTask;
-            }
-            else
-            {
-                return EndCallAsyncCore(lockTask);
-            }
+            // There is a deadline so just accept the overhead of a state machine during cleanup
+            return EndCallAsyncCore();
         }
 
-        private async Task EndCallAsyncCore(Task lockTask)
+        private async Task EndCallAsyncCore()
         {
             Debug.Assert(DeadlineManager != null, "Deadline manager should have been created.");
 
-            await lockTask;
+            await DeadlineManager.Lock.WaitAsync();
 
             try
             {
@@ -276,6 +257,7 @@ private async Task EndCallAsyncCore(Task lockTask)
             {
                 DeadlineManager.Lock.Release();
                 await DeadlineManager.DisposeAsync();
+                GrpcServerLog.DeadlineStopped(Logger);
             }
         }
 
@@ -390,6 +372,7 @@ public void Initialize(ISystemClock? clock = null)
             if (timeout != TimeSpan.Zero)
             {
                 DeadlineManager = ServerCallDeadlineManager.Create(this, clock ?? SystemClock.Instance, timeout, HttpContext.RequestAborted);
+                GrpcServerLog.DeadlineStarted(Logger, timeout);
             }
 
             var serviceDefaultCompression = Options.ResponseCompressionAlgorithm;

test/FunctionalTests/Server/DeadlineTests.cs

@@ -28,6 +28,7 @@
 using Grpc.AspNetCore.Server.Internal;
 using Grpc.Core;
 using Grpc.Tests.Shared;
+using Microsoft.Extensions.Logging;
 using NUnit.Framework;
 
 namespace Grpc.AspNetCore.FunctionalTests.Server
@@ -125,6 +126,125 @@ public async Task WriteUntilDeadline_SuccessResponsesStreamed_CoreAsync(ServerSt
             Assert.AreNotEqual(0, messageCount);
 
             response.AssertTrailerStatus(StatusCode.DeadlineExceeded, "Deadline Exceeded");
+
+            Assert.True(HasLog(LogLevel.Debug, "DeadlineExceeded", "Request with timeout of 00:00:00.2000000 has exceeded its deadline."));
+
+            await TestHelpers.AssertIsTrueRetryAsync(
+                () => HasLog(LogLevel.Trace, "DeadlineStopped", "Request deadline stopped."),
+                "Missing deadline stopped log.").DefaultTimeout();
+        }
+
+        [Test]
+        public async Task UnaryMethodErrorWithinDeadline()
+        {
+            static async Task<HelloReply> ThrowErrorWithinDeadline(HelloRequest request, ServerCallContext context)
+            {
+                await Task.Delay(10);
+                throw new InvalidOperationException("An error.");
+            }
+
+            // Arrange
+            SetExpectedErrorsFilter(writeContext =>
+            {
+                if (writeContext.LoggerName == TestConstants.ServerCallHandlerTestName)
+                {
+                    // Deadline happened before write
+                    if (writeContext.EventId.Name == "ErrorExecutingServiceMethod" &&
+                        writeContext.State.ToString() == "Error when executing service method 'ThrowErrorWithinDeadline'." &&
+                        writeContext.Exception!.Message == "An error.")
+                    {
+                        return true;
+                    }
+                }
+
+                return false;
+            });
+
+            var method = Fixture.DynamicGrpc.AddUnaryMethod<HelloRequest, HelloReply>(ThrowErrorWithinDeadline, nameof(ThrowErrorWithinDeadline));
+
+            var requestMessage = new HelloRequest
+            {
+                Name = "World"
+            };
+
+            var requestStream = new MemoryStream();
+            MessageHelpers.WriteMessage(requestStream, requestMessage);
+
+            var httpRequest = GrpcHttpHelper.Create(method.FullName);
+            httpRequest.Headers.Add(GrpcProtocolConstants.TimeoutHeader, "200m");
+            httpRequest.Content = new GrpcStreamContent(requestStream);
+
+            // Act
+            var response = await Fixture.Client.SendAsync(httpRequest, HttpCompletionOption.ResponseHeadersRead).DefaultTimeout();
+
+            // Assert
+            response.AssertIsSuccessfulGrpcRequest();
+            response.AssertTrailerStatus(StatusCode.Unknown, "Exception was thrown by handler. InvalidOperationException: An error.");
+
+            Assert.True(HasLog(LogLevel.Trace, "DeadlineStopped", "Request deadline stopped."));
+        }
+
+        [Test]
+        public async Task UnaryMethodErrorAfterExceedDeadline()
+        {
+            static async Task<HelloReply> ThrowErrorExceedDeadline(HelloRequest request, ServerCallContext context)
+            {
+                while (!context.CancellationToken.IsCancellationRequested)
+                {
+                    await Task.Delay(50);
+                }
+
+                throw new InvalidOperationException("An error.");
+            }
+
+            // Arrange
+            SetExpectedErrorsFilter(writeContext =>
+            {
+                if (writeContext.LoggerName == TestConstants.ServerCallHandlerTestName)
+                {
+                    // Deadline happened before write
+                    if (writeContext.EventId.Name == "ErrorExecutingServiceMethod" &&
+                        writeContext.State.ToString() == "Error when executing service method 'ThrowErrorExceedDeadline'." &&
+                        writeContext.Exception!.Message == "An error.")
+                    {
+                        return true;
+                    }
+                }
+
+                return false;
+            });
+
+            var method = Fixture.DynamicGrpc.AddUnaryMethod<HelloRequest, HelloReply>(ThrowErrorExceedDeadline, nameof(ThrowErrorExceedDeadline));
+
+            var requestMessage = new HelloRequest
+            {
+                Name = "World"
+            };
+
+            var requestStream = new MemoryStream();
+            MessageHelpers.WriteMessage(requestStream, requestMessage);
+
+            var httpRequest = GrpcHttpHelper.Create(method.FullName);
+            httpRequest.Headers.Add(GrpcProtocolConstants.TimeoutHeader, "200m");
+            httpRequest.Content = new GrpcStreamContent(requestStream);
+
+            // Act
+            var response = await Fixture.Client.SendAsync(httpRequest, HttpCompletionOption.ResponseHeadersRead).DefaultTimeout();
+
+            // Assert
+            response.AssertIsSuccessfulGrpcRequest();
+            response.AssertTrailerStatus(StatusCode.DeadlineExceeded, "Deadline Exceeded");
+
+            Assert.True(HasLog(LogLevel.Debug, "DeadlineExceeded", "Request with timeout of 00:00:00.2000000 has exceeded its deadline."));
+
+            // Ensure follow up error is logged.
+            await TestHelpers.AssertIsTrueRetryAsync(
+                () => HasLog(LogLevel.Error, "ErrorExecutingServiceMethod", "Error when executing service method 'ThrowErrorExceedDeadline'."),
+                "Missing follow up error log.").DefaultTimeout();
+
+            await TestHelpers.AssertIsTrueRetryAsync(
+                () => HasLog(LogLevel.Trace, "DeadlineStopped", "Request deadline stopped."),
+                "Missing deadline stopped log.").DefaultTimeout();
         }
 
         [Test]
@@ -184,6 +304,12 @@ static async Task<HelloReply> WaitUntilDeadline(HelloRequest request, ServerCall
             // Assert
             response.AssertIsSuccessfulGrpcRequest();
             response.AssertTrailerStatus(StatusCode.DeadlineExceeded, "Deadline Exceeded");
+
+            Assert.True(HasLog(LogLevel.Debug, "DeadlineExceeded", "Request with timeout of 00:00:00.2000000 has exceeded its deadline."));
+
+            await TestHelpers.AssertIsTrueRetryAsync(
+                () => HasLog(LogLevel.Trace, "DeadlineStopped", "Request deadline stopped."),
+                "Missing deadline stopped log.").DefaultTimeout();
         }
 
         [Test]
@@ -267,14 +393,15 @@ static async Task WriteUntilError(HelloRequest request, IServerStreamWriter<Hell
                         break;
                     }
                 }
-
             });
 
             await readTask.DefaultTimeout();
 
             Assert.AreNotEqual(0, messageCount);
             response.AssertTrailerStatus(StatusCode.DeadlineExceeded, "Deadline Exceeded");
 
+            Assert.True(HasLog(LogLevel.Debug, "DeadlineExceeded", "Request with timeout of 00:00:00.2000000 has exceeded its deadline."));
+
             // The server has completed the response but is still running
             // Allow time for the server to complete
             await TestHelpers.AssertIsTrueRetryAsync(() =>
@@ -286,6 +413,10 @@ await TestHelpers.AssertIsTrueRetryAsync(() =>
 
                 return errorLogged;
             }, "Expected error not thrown.");
+
+            await TestHelpers.AssertIsTrueRetryAsync(
+                () => HasLog(LogLevel.Trace, "DeadlineStopped", "Request deadline stopped."),
+                "Missing deadline stopped log.").DefaultTimeout();
         }
     }
 }

test/Grpc.AspNetCore.Server.Tests/HttpContextServerCallContextTests.cs

@@ -445,7 +445,10 @@ await Task.WhenAll(
             Assert.IsTrue(context.CancellationToken.IsCancellationRequested);
             Assert.IsTrue(httpContext.RequestAborted.IsCancellationRequested);
 
-            var write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineExceeded");
+            var write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineStarted");
+            Assert.AreEqual("Request deadline timeout of 00:00:01 started.", write.State.ToString());
+
+            write = testSink.Writes.Single(w => w.EventId.Name == "DeadlineExceeded");
             Assert.AreEqual("Request with timeout of 00:00:01 has exceeded its deadline.", write.State.ToString());
         }