Fix deadline timer rescheduling because of timer precision (#1201)

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

@@ -20,6 +20,7 @@
 using System.Diagnostics;
 using System.Threading;
 using System.Threading.Tasks;
+using Grpc.Shared;
 
 namespace Grpc.AspNetCore.Server.Internal
 {
@@ -86,7 +87,7 @@ public ServerCallDeadlineManager(HttpContextServerCallContext serverCallContext,
 
             _systemClock = clock;
 
-            var timerMilliseconds = GetTimerDueTime(timeout, maxTimerDueTime);
+            var timerMilliseconds = CommonGrpcProtocolHelpers.GetTimerDueTime(timeout, maxTimerDueTime);
             if (timerMilliseconds == maxTimerDueTime)
             {
                 // Create timer and set to field before setting time.
@@ -129,7 +130,7 @@ private static void DeadlineExceededLongCallback(object? state)
                 // Reschedule DeadlineExceeded again until deadline has been exceeded.
                 GrpcServerLog.DeadlineTimerRescheduled(manager._serverCallContext.Logger, remaining);
 
-                manager._longDeadlineTimer.Change(manager.GetTimerDueTime(remaining, maxTimerDueTime), Timeout.Infinite);
+                manager._longDeadlineTimer.Change(CommonGrpcProtocolHelpers.GetTimerDueTime(remaining, maxTimerDueTime), Timeout.Infinite);
             }
         }
 
@@ -146,18 +147,6 @@ private void RequestAborted()
             _deadlineCts.Cancel();
         }
 
-        private long GetTimerDueTime(TimeSpan timeout, long maxTimerDueTime)
-        {
-            // Timer has a maximum allowed due time.
-            // The called method will rechedule the timer if the deadline time has not passed.
-            var dueTimeMilliseconds = timeout.Ticks / TimeSpan.TicksPerMillisecond;
-            dueTimeMilliseconds = Math.Min(dueTimeMilliseconds, maxTimerDueTime);
-            // Timer can't have a negative due time
-            dueTimeMilliseconds = Math.Max(dueTimeMilliseconds, 0);
-
-            return dueTimeMilliseconds;
-        }
-
         public void SetCallEnded()
         {
             lock (this)

src/Grpc.Net.Client/Internal/GrpcCall.cs

@@ -452,8 +452,18 @@ private async Task RunCall(HttpRequestMessage request, TimeSpan? timeout)
                     }
                     catch (Exception ex)
                     {
-                        GrpcCallLog.ErrorStartingCall(Logger, ex);
-                        throw;
+                        // Don't log OperationCanceledException if deadline has exceeded.
+                        if (ex is OperationCanceledException &&
+                            _callTcs.Task.IsCompletedSuccessfully &&
+                            _callTcs.Task.Result.StatusCode == StatusCode.DeadlineExceeded)
+                        {
+                            throw;
+                        }
+                        else
+                        {
+                            GrpcCallLog.ErrorStartingCall(Logger, ex);
+                            throw;
+                        }
                     }
 
                     status = ValidateHeaders(HttpResponse);
@@ -680,7 +690,7 @@ public Exception CreateFailureStatusException(Status status)
                 {
                     GrpcCallLog.StartingDeadlineTimeout(Logger, timeout.Value);
 
-                    var dueTime = GetTimerDueTime(timeout.Value);
+                    var dueTime = CommonGrpcProtocolHelpers.GetTimerDueTime(timeout.Value, Channel.MaxTimerDueTime);
                     _deadlineTimer = new Timer(DeadlineExceededCallback, null, dueTime, Timeout.Infinite);
                 }
             }
@@ -837,18 +847,6 @@ private HttpRequestMessage CreateHttpRequestMessage(TimeSpan? timeout)
             return message;
         }
 
-        private long GetTimerDueTime(TimeSpan timeout)
-        {
-            // Timer has a maximum allowed due time.
-            // The called method will rechedule the timer if the deadline time has not passed.
-            var dueTimeMilliseconds = timeout.Ticks / TimeSpan.TicksPerMillisecond;
-            dueTimeMilliseconds = Math.Min(dueTimeMilliseconds, Channel.MaxTimerDueTime);
-            // Timer can't have a negative due time
-            dueTimeMilliseconds = Math.Max(dueTimeMilliseconds, 0);
-
-            return dueTimeMilliseconds;
-        }
-
         private TimeSpan? GetTimeout()
         {
             if (_deadline == DateTime.MaxValue)
@@ -889,7 +887,8 @@ private void DeadlineExceededCallback(object? state)
                     // Reschedule DeadlineExceeded again until deadline has been exceeded.
                     GrpcCallLog.DeadlineTimerRescheduled(Logger, remaining);
 
-                    _deadlineTimer!.Change(GetTimerDueTime(remaining), Timeout.Infinite);
+                    var dueTime = CommonGrpcProtocolHelpers.GetTimerDueTime(remaining, Channel.MaxTimerDueTime);
+                    _deadlineTimer!.Change(dueTime, Timeout.Infinite);
                 }
             }
         }

src/Shared/CommonGrpcProtocolHelpers.cs

@@ -23,6 +23,34 @@ namespace Grpc.Shared
 {
     internal static class CommonGrpcProtocolHelpers
     {
+        // Timer and DateTime.UtcNow have a 14ms precision. Add a small delay when scheduling deadline
+        // timer that tests if exceeded or not. This avoids rescheduling the deadline callback multiple
+        // times when timer is triggered before DateTime.UtcNow reports the deadline has been exceeded.
+        // e.g.
+        // - The deadline callback is raised and there is 0.5ms until deadline.
+        // - The timer is rescheduled to run in 0.5ms.
+        // - The deadline callback is raised again and there is now 0.4ms until deadline.
+        // - The timer is rescheduled to run in 0.4ms, etc.
+        private static readonly int TimerEpsilonMilliseconds = 4;
+
+        public static long GetTimerDueTime(TimeSpan timeout, long maxTimerDueTime)
+        {
+            // Timer has a maximum allowed due time.
+            // The called method will rechedule the timer if the deadline time has not passed.
+            var dueTimeMilliseconds = timeout.Ticks / TimeSpan.TicksPerMillisecond;
+
+            // Add epislon to take into account Timer precision.
+            // This will avoid rescheduling the timer multiple times, but means deadline
+            // might run for some extra milliseconds
+            dueTimeMilliseconds += TimerEpsilonMilliseconds;
+
+            dueTimeMilliseconds = Math.Min(dueTimeMilliseconds, maxTimerDueTime);
+            // Timer can't have a negative due time
+            dueTimeMilliseconds = Math.Max(dueTimeMilliseconds, 0);
+
+            return dueTimeMilliseconds;
+        }
+
         public static bool IsContentType(string contentType, string? s)
         {
             if (s == null)

test/FunctionalTests/Client/DeadlineTests.cs

@@ -0,0 +1,62 @@
+#region Copyright notice and license
+
+// Copyright 2019 The gRPC Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#endregion
+
+using System;
+using System.Linq;
+using System.Threading.Tasks;
+using Grpc.AspNetCore.FunctionalTests.Infrastructure;
+using Grpc.Core;
+using Grpc.Tests.Shared;
+using NUnit.Framework;
+using Streaming;
+
+namespace Grpc.AspNetCore.FunctionalTests.Client
+{
+    [TestFixture]
+    public class DeadlineTests : FunctionalTestBase
+    {
+        [Test]
+        public async Task Unary_SmallDeadline_ExceededWithoutReschedule()
+        {
+            var tcs = new TaskCompletionSource<DataMessage>(TaskCreationOptions.RunContinuationsAsynchronously);
+            Task<DataMessage> UnaryTimeout(DataMessage request, ServerCallContext context)
+            {
+                return tcs.Task;
+            }
+
+            // Arrange
+            var method = Fixture.DynamicGrpc.AddUnaryMethod<DataMessage, DataMessage>(UnaryTimeout);
+
+            var channel = CreateChannel();
+
+            var client = TestClientFactory.Create(channel, method);
+
+            // Act
+            var call = client.UnaryCall(new DataMessage(), new CallOptions(deadline: DateTime.UtcNow.AddMilliseconds(200)));
+
+            // Assert
+            var ex = await ExceptionAssert.ThrowsAsync<RpcException>(() => call.ResponseAsync).DefaultTimeout();
+            Assert.AreEqual(StatusCode.DeadlineExceeded, ex.StatusCode);
+            Assert.AreEqual(StatusCode.DeadlineExceeded, call.GetStatus().StatusCode);
+
+            Assert.IsFalse(Logs.Any(l => l.EventId.Name == "DeadlineTimerRescheduled"));
+
+            tcs.SetResult(new DataMessage());
+        }
+    }
+}

test/FunctionalTests/Server/DeadlineTests.cs

@@ -17,6 +17,7 @@
 #endregion
 
 using System;
+using System.Collections.Generic;
 using System.IO;
 using System.IO.Pipelines;
 using System.Linq;
@@ -336,12 +337,18 @@ static async Task WriteUntilError(HelloRequest request, IServerStreamWriter<Hell
 
             // The server has completed the response but is still running
             // Allow time for the server to complete
+            var expectedErrorMessages = new List<string>
+            {
+                "Can't write the message because the request is complete.",
+                "Writing is not allowed after writer was completed.",
+                "Invalid ordering of calling StartAsync or CompleteAsync and Advance."
+            };
             await TestHelpers.AssertIsTrueRetryAsync(() =>
             {
                 var errorLogged = Logs.Any(r =>
                     r.EventId.Name == "ErrorExecutingServiceMethod" &&
                     r.State.ToString() == "Error when executing service method 'WriteUntilError'." &&
-                    (r.Exception!.Message == "Can't write the message because the request is complete." || r.Exception!.Message == "Writing is not allowed after writer was completed."));
+                    expectedErrorMessages.Contains(r.Exception!.Message));
 
                 return errorLogged;
             }, "Expected error not thrown.").DefaultTimeout();

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

@@ -84,6 +84,7 @@ public void CreateAuthContext_CertWithCommonName_UseCommonNameAsPeerIdentity()
         [TestCase("1m", 10000, true)]
         [TestCase("1u", 10, true)]
         [TestCase("100n", 1, true)]
+        [TestCase("1n", 0, true)]
         [TestCase("0S", 0, true)]
         [TestCase("", 0, false)]
         [TestCase("5", 0, false)]

test/Grpc.Net.Client.Tests/DeadlineTests.cs

@@ -141,7 +141,7 @@ public async Task AsyncUnaryCall_SetVeryLargeDeadline_MaximumDeadlineTimeoutSent
             var invoker = HttpClientCallInvokerFactory.Create(httpClient, loggerFactory: testLoggerFactory, systemClock: testSystemClock);
 
             // Act
-            await invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(deadline: deadline), new HelloRequest());
+            await invoker.AsyncUnaryCall<HelloRequest, HelloReply>(ClientTestHelpers.ServiceMethod, string.Empty, new CallOptions(deadline: deadline), new HelloRequest()).ResponseAsync.DefaultTimeout();
 
             // Assert
             Assert.IsNotNull(httpRequestMessage);