diff --git a/src/Kestrel.Core/Internal/Infrastructure/TimeoutControl.cs b/src/Kestrel.Core/Internal/Infrastructure/TimeoutControl.cs index 5a54b0db07..af1aff9cc1 100644 --- a/src/Kestrel.Core/Internal/Infrastructure/TimeoutControl.cs +++ b/src/Kestrel.Core/Internal/Infrastructure/TimeoutControl.cs @@ -96,7 +96,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure return; } - _readTimingElapsedTicks += timestamp - _lastTimestamp; + // Assume overly long tick intervals are the result of server resource starvation. + // Don't count extra time between ticks against the rate limit. + _readTimingElapsedTicks += Math.Min(timestamp - _lastTimestamp, Heartbeat.Interval.Ticks); if (_minReadRate.BytesPerSecond > 0 && _readTimingElapsedTicks > _minReadRate.GracePeriod.Ticks) { @@ -124,6 +126,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure { lock (_writeTimingLock) { + // Assume overly long tick intervals are the result of server resource starvation. + // Don't count extra time between ticks against the rate limit. + var extraTimeForTick = timestamp - _lastTimestamp - Heartbeat.Interval.Ticks; + + if (extraTimeForTick > 0) + { + _writeTimingTimeoutTimestamp += extraTimeForTick; + } + if (_concurrentAwaitingWrites > 0 && timestamp > _writeTimingTimeoutTimestamp && !Debugger.IsAttached) { _timeoutHandler.OnTimeout(TimeoutReason.WriteDataRate); diff --git a/test/Kestrel.Core.Tests/TimeoutControlTests.cs b/test/Kestrel.Core.Tests/TimeoutControlTests.cs index fbe76de813..d23f8156de 100644 --- a/test/Kestrel.Core.Tests/TimeoutControlTests.cs +++ b/test/Kestrel.Core.Tests/TimeoutControlTests.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.FlowControl; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; using Moq; @@ -13,11 +14,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { private readonly Mock _mockTimeoutHandler; private readonly TimeoutControl _timeoutControl; + private readonly MockSystemClock _systemClock; public TimeoutControlTests() { _mockTimeoutHandler = new Mock(); _timeoutControl = new TimeoutControl(_mockTimeoutHandler.Object); + _systemClock = new MockSystemClock(); } [Fact] @@ -28,7 +31,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.Debugger = mockDebugger.Object; var now = DateTimeOffset.Now; - _timeoutControl.Tick(now); + _timeoutControl.Initialize(now); _timeoutControl.SetTimeout(1, TimeoutReason.RequestHeaders); _timeoutControl.Tick(now.AddTicks(2).Add(Heartbeat.Interval)); @@ -64,7 +67,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Initialize timestamp var now = DateTimeOffset.UtcNow; - _timeoutControl.Tick(now); + _timeoutControl.Initialize(now); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); @@ -78,7 +81,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Tick after grace period w/ low data rate - now += TimeSpan.FromSeconds(2); + now += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(now); + now += TimeSpan.FromSeconds(1); _timeoutControl.BytesRead(10); _timeoutControl.Tick(now); @@ -94,13 +99,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Initialize timestamp var now = DateTimeOffset.UtcNow; - _timeoutControl.Tick(now); + _timeoutControl.Initialize(now); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); // Set base data rate to 200 bytes/second - now += gracePeriod; + now += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(now); + now += TimeSpan.FromSeconds(1); _timeoutControl.BytesRead(400); _timeoutControl.Tick(now); @@ -149,49 +156,54 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Fact] public void RequestBodyDataRateNotComputedOnPausedTime() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); // Initialize timestamp - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Initialize(_systemClock.UtcNow); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); // Tick at 3s, expected counted time is 3s, expected data rate is 200 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(3); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); _timeoutControl.BytesRead(600); - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Tick(_systemClock.UtcNow); // Pause at 3.5s - systemClock.UtcNow += TimeSpan.FromSeconds(0.5); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.5); _timeoutControl.StopTimingRead(); // Tick at 4s, expected counted time is 4s (first tick after pause goes through), expected data rate is 150 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(0.5); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.5); + _timeoutControl.Tick(_systemClock.UtcNow); // Tick at 6s, expected counted time is 4s, expected data rate is 150 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(2); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(2); + _timeoutControl.Tick(_systemClock.UtcNow); // Not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Resume at 6.5s - systemClock.UtcNow += TimeSpan.FromSeconds(0.5); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.5); _timeoutControl.StartTimingRead(); // Tick at 9s, expected counted time is 6s, expected data rate is 100 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(1.5); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1.0); + _timeoutControl.Tick(_systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(.5); + _timeoutControl.Tick(_systemClock.UtcNow); // Not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Tick at 10s, expected counted time is 7s, expected data rate drops below 100 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); // Timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -200,42 +212,43 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Fact] public void ReadTimingNotPausedWhenResumeCalledBeforeNextTick() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); // Initialize timestamp - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Initialize(_systemClock.UtcNow); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); // Tick at 2s, expected counted time is 2s, expected data rate is 100 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(2); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); _timeoutControl.BytesRead(200); - _timeoutControl.Tick(systemClock.UtcNow); // Not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Pause at 2.25s - systemClock.UtcNow += TimeSpan.FromSeconds(0.25); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.25); _timeoutControl.StopTimingRead(); // Resume at 2.5s - systemClock.UtcNow += TimeSpan.FromSeconds(0.25); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.25); _timeoutControl.StartTimingRead(); // Tick at 3s, expected counted time is 3s, expected data rate is 100 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(0.5); + _systemClock.UtcNow += TimeSpan.FromSeconds(0.5); _timeoutControl.BytesRead(100); - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Tick(_systemClock.UtcNow); // Not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Tick at 4s, expected counted time is 4s, expected data rate drops below 100 bytes/second - systemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(_systemClock.UtcNow); // Timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -244,14 +257,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Fact] public void ReadTimingNotEnforcedWhenTimeoutIsSet() { - var systemClock = new MockSystemClock(); var timeout = TimeSpan.FromSeconds(5); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); - var startTime = systemClock.UtcNow; + var startTime = _systemClock.UtcNow; // Initialize timestamp - _timeoutControl.Tick(startTime); + _timeoutControl.Initialize(startTime); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); @@ -259,37 +271,122 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.SetTimeout(timeout.Ticks, TimeoutReason.RequestBodyDrain); // Tick beyond grace period with low data rate - systemClock.UtcNow += TimeSpan.FromSeconds(3); + _systemClock.UtcNow += TimeSpan.FromSeconds(3); _timeoutControl.BytesRead(1); - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Tick(_systemClock.UtcNow); // Not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Tick just past timeout period, adjusted by Heartbeat.Interval - systemClock.UtcNow = startTime + timeout + Heartbeat.Interval + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow = startTime + timeout + Heartbeat.Interval + TimeSpan.FromTicks(1); + _timeoutControl.Tick(_systemClock.UtcNow); // Timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.RequestBodyDrain), Times.Once); } [Fact] - public void WriteTimingAbortsConnectionWhenWriteDoesNotCompleteWithMinimumDataRate() + public void ReadTimingNotEnforcedWhenLowConnectionInputFlowControlAvailability() + { + var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); + + var flowControl = new InputFlowControl(initialWindowSize: 2, minWindowSizeIncrement: 1); + + // Initialize timestamp + var now = DateTimeOffset.UtcNow; + _timeoutControl.Initialize(now); + _timeoutControl.InitializeHttp2(flowControl); + + _timeoutControl.StartRequestBody(minRate); + _timeoutControl.StartTimingRead(); + + // Tick past grace period + now += TimeSpan.FromSeconds(1); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + now += TimeSpan.FromSeconds(1); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + + // Induce low flow control availability + flowControl.TryAdvance(2); + + // Read 0 bytes in 1 second + now += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(now); + + // Not timed out + _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); + + // Relieve low flow control availability + flowControl.TryUpdateWindow(2, out _); + _timeoutControl.Tick(now); + + // Still not timed out + _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); + + // Read 0 bytes in 1 second + now += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(now);; + + // Timed out + _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); + } + + [Fact] + public void ReadTimingOnlyCountsUpToOneHeartbeatIntervalPerTick() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); // Initialize timestamp - _timeoutControl.Tick(systemClock.UtcNow); + var now = DateTimeOffset.UtcNow; + _timeoutControl.Initialize(now); + + _timeoutControl.StartRequestBody(minRate); + _timeoutControl.StartTimingRead(); + + // Tick past grace period + now += TimeSpan.FromSeconds(1); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + now += TimeSpan.FromSeconds(1); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + + // Read 100 bytes in 2 seconds with a single tick + now += TimeSpan.FromSeconds(2); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + + // Not timed out + _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); + + // Read 100 bytes in 2 seconds in two ticks + now += TimeSpan.FromSeconds(1); + _timeoutControl.BytesRead(100); + _timeoutControl.Tick(now); + now += TimeSpan.FromSeconds(1); + _timeoutControl.Tick(now); + + // Timed out + _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); + } + + [Fact] + public void WriteTimingAbortsConnectionWhenWriteDoesNotCompleteWithMinimumDataRate() + { + var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); + + // Initialize timestamp + _timeoutControl.Initialize(_systemClock.UtcNow); // Should complete within 4 seconds, but the timeout is adjusted by adding Heartbeat.Interval _timeoutControl.BytesWrittenToBuffer(minRate, 400); _timeoutControl.StartTimingWrite(); // Tick just past 4s plus Heartbeat.Interval - systemClock.UtcNow += TimeSpan.FromSeconds(4) + Heartbeat.Interval + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(4) + Heartbeat.Interval + TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); } @@ -297,40 +394,35 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Fact] public void WriteTimingAbortsConnectionWhenSmallWriteDoesNotCompleteWithinGracePeriod() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(5)); // Initialize timestamp - var startTime = systemClock.UtcNow; - _timeoutControl.Tick(startTime); + var startTime = _systemClock.UtcNow; + _timeoutControl.Initialize(startTime); // Should complete within 1 second, but the timeout is adjusted by adding Heartbeat.Interval _timeoutControl.BytesWrittenToBuffer(minRate, 100); _timeoutControl.StartTimingWrite(); // Tick just past 1s plus Heartbeat.Interval - systemClock.UtcNow += TimeSpan.FromSeconds(1) + Heartbeat.Interval + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1) + Heartbeat.Interval + TimeSpan.FromTicks(1)); // Still within grace period, not timed out _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // Tick just past grace period (adjusted by Heartbeat.Interval) - systemClock.UtcNow = startTime + minRate.GracePeriod + Heartbeat.Interval + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(minRate.GracePeriod - TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); } - [Fact] public void WriteTimingTimeoutPushedOnConcurrentWrite() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); // Initialize timestamp - _timeoutControl.Tick(systemClock.UtcNow); + _timeoutControl.Initialize(_systemClock.UtcNow); // Should complete within 5 seconds, but the timeout is adjusted by adding Heartbeat.Interval _timeoutControl.BytesWrittenToBuffer(minRate, 500); @@ -341,8 +433,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.StartTimingWrite(); // Tick just past 5s plus Heartbeat.Interval, when the first write should have completed - systemClock.UtcNow += TimeSpan.FromSeconds(5) + Heartbeat.Interval + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(5) + Heartbeat.Interval + TimeSpan.FromTicks(1)); // Not timed out because the timeout was pushed by the second write _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); @@ -351,8 +442,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.StopTimingWrite(); // Tick just past +3s, when the second write should have completed - systemClock.UtcNow += TimeSpan.FromSeconds(3) + TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(3)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); } @@ -360,14 +450,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Fact] public void WriteTimingAbortsConnectionWhenRepeatedSmallWritesDoNotCompleteWithMinimumDataRate() { - var systemClock = new MockSystemClock(); var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(5)); var numWrites = 5; var writeSize = 100; // Initialize timestamp - var startTime = systemClock.UtcNow; - _timeoutControl.Tick(startTime); + var startTime = _systemClock.UtcNow; + _timeoutControl.Initialize(startTime); // 5 consecutive 100 byte writes. for (var i = 0; i < numWrites - 1; i++) @@ -381,14 +470,37 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Move the clock forward Heartbeat.Interval + MinDataRate.GracePeriod + 4 seconds. // The grace period should only be added for the first write. The subsequent 4 100 byte writes should add 1 second each to the timeout given the 100 byte/s min rate. - systemClock.UtcNow += Heartbeat.Interval + minRate.GracePeriod + TimeSpan.FromSeconds((numWrites - 1) * writeSize / minRate.BytesPerSecond); - _timeoutControl.Tick(systemClock.UtcNow); + AdvanceClock(Heartbeat.Interval + minRate.GracePeriod + TimeSpan.FromSeconds((numWrites - 1) * writeSize / minRate.BytesPerSecond)); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); // On more tick forward triggers the timeout. - systemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(systemClock.UtcNow); + _systemClock.UtcNow += TimeSpan.FromTicks(1); + _timeoutControl.Tick(_systemClock.UtcNow); + + _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); + } + + [Fact] + public void WriteTimingOnlyCountsUpToOneHeartbeatIntervalPerTick() + { + var minRate = new MinDataRate(bytesPerSecond: 100, gracePeriod: TimeSpan.FromSeconds(2)); + + // Initialize timestamp + _timeoutControl.Initialize(_systemClock.UtcNow); + + // Should complete within 4 seconds, but the timeout is adjusted by adding Heartbeat.Interval + _timeoutControl.BytesWrittenToBuffer(minRate, 400); + _timeoutControl.StartTimingWrite(); + + // Tick just past 4s plus Heartbeat.Interval at once + _systemClock.UtcNow += TimeSpan.FromSeconds(4) + Heartbeat.Interval + TimeSpan.FromTicks(1); + _timeoutControl.Tick(_systemClock.UtcNow); + + _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Never); + + // The last Tick only accounted for one heartbeat interval. Try again with a tick per interval. + AdvanceClock(TimeSpan.FromSeconds(4) + TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); } @@ -400,16 +512,31 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var minRate = new MinDataRate(bytesPerSecond, gracePeriod); // Initialize timestamp - var now = DateTimeOffset.UtcNow; - _timeoutControl.Tick(now); + _timeoutControl.Initialize(_systemClock.UtcNow); _timeoutControl.StartRequestBody(minRate); _timeoutControl.StartTimingRead(); + AdvanceClock(gracePeriod); + // Tick after grace period w/ low data rate - now += gracePeriod + TimeSpan.FromSeconds(1); + _systemClock.UtcNow += TimeSpan.FromSeconds(1); _timeoutControl.BytesRead(1); - _timeoutControl.Tick(now); + _timeoutControl.Tick(_systemClock.UtcNow); + } + + private void AdvanceClock(TimeSpan timeSpan) + { + var endTime = _systemClock.UtcNow + timeSpan; + + while (_systemClock.UtcNow + Heartbeat.Interval < endTime) + { + _systemClock.UtcNow += Heartbeat.Interval; + _timeoutControl.Tick(_systemClock.UtcNow); + } + + _systemClock.UtcNow = endTime; + _timeoutControl.Tick(_systemClock.UtcNow); } } } diff --git a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs index 681c577d8f..a160f70436 100644 --- a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs +++ b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs @@ -1160,6 +1160,21 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests } } + protected void AdvanceClock(TimeSpan timeSpan) + { + var clock = _serviceContext.MockSystemClock; + var endTime = clock.UtcNow + timeSpan; + + while (clock.UtcNow + Heartbeat.Interval < endTime) + { + clock.UtcNow += Heartbeat.Interval; + _timeoutControl.Tick(clock.UtcNow); + } + + clock.UtcNow = endTime; + _timeoutControl.Tick(clock.UtcNow); + } + public class Http2FrameWithPayload : Http2Frame { public Http2FrameWithPayload() : base() diff --git a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs index eeccef7208..2ded1c404a 100644 --- a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs +++ b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs @@ -30,13 +30,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _connectionTask = _connection.ProcessRequestsAsync(new DummyApplication(_noopApplication)); - mockSystemClock.UtcNow += limits.KeepAliveTimeout + Heartbeat.Interval; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.KeepAliveTimeout + Heartbeat.Interval); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.KeepAlive), Times.Once); @@ -55,13 +53,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await InitializeConnectionAsync(_noopApplication); - mockSystemClock.UtcNow += limits.KeepAliveTimeout + Heartbeat.Interval; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.KeepAliveTimeout + Heartbeat.Interval); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.KeepAlive), Times.Once); @@ -80,8 +76,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await InitializeConnectionAsync(_noopApplication); - mockSystemClock.UtcNow += limits.KeepAliveTimeout + Heartbeat.Interval; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.KeepAliveTimeout + Heartbeat.Interval); // keep-alive timeout set but not fired. _mockTimeoutControl.Verify(c => c.SetTimeout(It.IsAny(), TimeoutReason.KeepAlive), Times.Once); @@ -113,13 +108,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await setTimeoutTcs.Task.DefaultTimeout(); - mockSystemClock.UtcNow += limits.KeepAliveTimeout + Heartbeat.Interval; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.KeepAliveTimeout + Heartbeat.Interval); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.KeepAlive), Times.Once); @@ -142,15 +135,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await SendEmptyContinuationFrameAsync(1, Http2ContinuationFrameFlags.NONE); - mockSystemClock.UtcNow += limits.RequestHeadersTimeout + Heartbeat.Interval; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.RequestHeadersTimeout + Heartbeat.Interval); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); await SendEmptyContinuationFrameAsync(1, Http2ContinuationFrameFlags.NONE); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.RequestHeaders), Times.Once); @@ -181,17 +172,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForConnectionStopAsync(expectedLastStreamId: 0, ignoreNonGoAwayFrames: false); - mockSystemClock.UtcNow += - TimeSpan.FromSeconds(_bytesReceived / limits.MinResponseDataRate.BytesPerSecond) + - limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); - - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(_bytesReceived / limits.MinResponseDataRate.BytesPerSecond) + + limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5)); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); _mockConnectionContext.Verify(c => c.Abort(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -285,16 +272,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.Tick(mockSystemClock.UtcNow); // Don't read data frame to induce "socket" backpressure. - mockSystemClock.UtcNow += - TimeSpan.FromSeconds((_bytesReceived + _helloWorldBytes.Length) / limits.MinResponseDataRate.BytesPerSecond) + - limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); - - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds((_bytesReceived + _helloWorldBytes.Length) / limits.MinResponseDataRate.BytesPerSecond) + + limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5)); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -348,13 +331,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); // Don't read data frame to induce "socket" backpressure. - mockSystemClock.UtcNow += timeToWriteMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToWriteMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -409,16 +390,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _timeoutControl.Tick(mockSystemClock.UtcNow); // Don't send WINDOW_UPDATE to induce flow-control backpressure - mockSystemClock.UtcNow += - TimeSpan.FromSeconds(_bytesReceived / limits.MinResponseDataRate.BytesPerSecond) + - limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); - - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(_bytesReceived / limits.MinResponseDataRate.BytesPerSecond) + + limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5)); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -470,13 +447,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); // Don't send WINDOW_UPDATE to induce flow-control backpressure - mockSystemClock.UtcNow += timeToWriteMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToWriteMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -540,14 +515,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests limits.MinResponseDataRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); // Don't send WINDOW_UPDATE to induce flow-control backpressure - mockSystemClock.UtcNow += timeToWriteMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToWriteMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - //mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.WriteDataRate), Times.Once); @@ -592,13 +564,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests withStreamId: 1); // Don't send any more data and advance just to and then past the grace period. - mockSystemClock.UtcNow += limits.MinRequestBodyDataRate.GracePeriod; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.MinRequestBodyDataRate.GracePeriod); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -647,13 +617,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var timeToReadMaxData = TimeSpan.FromSeconds(_maxData.Length / limits.MinRequestBodyDataRate.BytesPerSecond) - TimeSpan.FromSeconds(.5); // Don't send any more data and advance just to and then past the rate timeout. - mockSystemClock.UtcNow += timeToReadMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToReadMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -718,13 +686,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests timeToReadMaxData -= TimeSpan.FromSeconds(.5); // Don't send any more data and advance just to and then past the rate timeout. - mockSystemClock.UtcNow += timeToReadMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToReadMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -790,13 +756,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var timeToReadMaxData = TimeSpan.FromSeconds(_maxData.Length / limits.MinRequestBodyDataRate.BytesPerSecond) - TimeSpan.FromSeconds(.5); // Don't send any more data and advance just to and then past the rate timeout. - mockSystemClock.UtcNow += timeToReadMaxData; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(timeToReadMaxData); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromSeconds(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromSeconds(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); @@ -863,8 +827,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests withStreamId: 3); // No matter how much time elapses there is no read timeout because the connection window is too small. - mockSystemClock.UtcNow += TimeSpan.FromDays(365); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromDays(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); @@ -885,13 +848,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests withFlags: (byte)Http2DataFrameFlags.NONE, withStreamId: 0); - mockSystemClock.UtcNow += limits.MinRequestBodyDataRate.GracePeriod; - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(limits.MinRequestBodyDataRate.GracePeriod); _mockTimeoutHandler.Verify(h => h.OnTimeout(It.IsAny()), Times.Never); - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - _timeoutControl.Tick(mockSystemClock.UtcNow); + AdvanceClock(TimeSpan.FromTicks(1)); _mockTimeoutHandler.Verify(h => h.OnTimeout(TimeoutReason.ReadDataRate), Times.Once); diff --git a/test/Kestrel.InMemory.FunctionalTests/RequestBodyTimeoutTests.cs b/test/Kestrel.InMemory.FunctionalTests/RequestBodyTimeoutTests.cs index 75d55da8fb..a26141b93b 100644 --- a/test/Kestrel.InMemory.FunctionalTests/RequestBodyTimeoutTests.cs +++ b/test/Kestrel.InMemory.FunctionalTests/RequestBodyTimeoutTests.cs @@ -71,8 +71,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests await appRunningEvent.Task.DefaultTimeout(); - serviceContext.MockSystemClock.UtcNow += gracePeriod + TimeSpan.FromSeconds(1); - heartbeatManager.OnHeartbeat(serviceContext.SystemClock.UtcNow); + // Advance the clock gracePeriod + TimeSpan.FromSeconds(1) + for (var i = 0; i < 6; i++) + { + serviceContext.MockSystemClock.UtcNow += TimeSpan.FromSeconds(1); + heartbeatManager.OnHeartbeat(serviceContext.SystemClock.UtcNow); + } await connection.Receive( "HTTP/1.1 408 Request Timeout", @@ -184,8 +188,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests await appRunningTcs.Task.DefaultTimeout(); - serviceContext.MockSystemClock.UtcNow += gracePeriod + TimeSpan.FromSeconds(1); - heartbeatManager.OnHeartbeat(serviceContext.SystemClock.UtcNow); + // Advance the clock gracePeriod + TimeSpan.FromSeconds(1) + for (var i = 0; i < 6; i++) + { + serviceContext.MockSystemClock.UtcNow += TimeSpan.FromSeconds(1); + heartbeatManager.OnHeartbeat(serviceContext.SystemClock.UtcNow); + } await exceptionSwallowedTcs.Task.DefaultTimeout(); diff --git a/test/Kestrel.InMemory.FunctionalTests/ResponseDrainingTests.cs b/test/Kestrel.InMemory.FunctionalTests/ResponseDrainingTests.cs index d4ebbbb596..9cd37003c0 100644 --- a/test/Kestrel.InMemory.FunctionalTests/ResponseDrainingTests.cs +++ b/test/Kestrel.InMemory.FunctionalTests/ResponseDrainingTests.cs @@ -59,7 +59,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Wait for the drain timeout to be set. await outputBufferedTcs.Task.DefaultTimeout(); - testContext.MockSystemClock.UtcNow += minRate.GracePeriod + Heartbeat.Interval - TimeSpan.FromSeconds(.5); + // Advance the clock to the grace period + for (var i = 0; i < 2; i++) + { + testContext.MockSystemClock.UtcNow += TimeSpan.FromSeconds(1); + heartbeatManager.OnHeartbeat(testContext.SystemClock.UtcNow); + } + + testContext.MockSystemClock.UtcNow += Heartbeat.Interval - TimeSpan.FromSeconds(.5); heartbeatManager.OnHeartbeat(testContext.SystemClock.UtcNow); Assert.Null(transportConnection.AbortReason);