Prior to this change, HTTP/2 read rate limit tests would fail when the stalled read started after the test started advancing the clock. Example:
Failed DATA_Received_TooSlowlyOnSecondStream_AbortsConnectionAfterNonAdditiveRateTimeout
Error Message:
Moq.MockException :
Expected invocation on the mock once, but was 0 times: h => h.OnTimeout(TimeoutReason.ReadDataRate)
Configured setups:
ITimeoutHandler h => h.OnTimeout(It.IsAny<TimeoutReason>())
No invocations performed.
Stack Trace:
at Moq.Mock.VerifyCalls(Mock targetMock, InvocationShape expectation, LambdaExpression expression, Times times, String failMessage)
at Moq.Mock.Verify[T](Mock`1 mock, Expression`1 expression, Times times, String failMessage)
at Moq.Mock`1.Verify(Expression`1 expression, Times times)
at Moq.Mock`1.Verify(Expression`1 expression, Func`1 times)
at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TimeoutTests.<DATA_Received_TooSlowlyOnSecondStream_AbortsConnectionAfterNonAdditiveRateTimeout>d__14.MoveNext() in C:\dev\aspnet\KestrelHttpServer\test\Kestrel.InMemory.FunctionalTests\Http2\Http2TimeoutTests.cs:line 781
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
Standard Output Messages:
| [0.001s] TestLifetime Information: Starting test DATA_Received_TooSlowlyOnSecondStream_AbortsConnectionAfterNonAdditiveRateTimeout at 2018-11-09T20:20:47
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" received SETTINGS frame for stream ID 0 with length 0 and flags NONE
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" received HEADERS frame for stream ID 1 with length 318 and flags END_HEADERS
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" received DATA frame for stream ID 1 with length 16384 and flags END_STREAM
| [0.005s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "(null)", Request id ":00000001": started reading request body.
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending HEADERS frame for stream ID 1 with length 37 and flags END_HEADERS
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending DATA frame for stream ID 1 with length 16384 and flags NONE
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "(null)", Request id ":00000001": done reading request body.
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending DATA frame for stream ID 1 with length 0 and flags END_STREAM
| [0.006s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" received HEADERS frame for stream ID 3 with length 318 and flags END_HEADERS
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" received DATA frame for stream ID 3 with length 16384 and flags NONE
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "(null)", Request id ":00000003": started reading request body.
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending HEADERS frame for stream ID 3 with length 37 and flags END_HEADERS
| [0.007s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending DATA frame for stream ID 3 with length 16384 and flags NONE
| [0.024s] Microsoft.AspNetCore.Server.Kestrel Trace: Connection id "(null)" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0
| [0.024s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "(null)" is closed. The last processed stream ID was 3.
| [0.025s] Microsoft.AspNetCore.Server.Kestrel Error: Connection id "(null)", Request id ":00000003": An unhandled exception was thrown by the application.
| System.IO.IOException: The request stream was aborted. ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
| --- End of inner exception stack trace ---
| at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
| at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
| at System.IO.Pipelines.Pipe.GetReadAsyncResult()
| at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
| at System.Runtime.CompilerServices.ValueTaskAwaiter`1.GetResult()
| at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.<ReadAsync>d__27.MoveNext() in C:\dev\aspnet\KestrelHttpServer\src\Kestrel.Core\Internal\Http\MessageBody.cs:line 54
| --- End of stack trace from previous location where exception was thrown ---
| at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
| at System.Runtime.CompilerServices.ValueTaskAwaiter`1.GetResult()
| at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.<ReadAsyncInternal>d__21.MoveNext() in C:\dev\aspnet\KestrelHttpServer\src\Kestrel.Core\Internal\Http\HttpRequestStream.cs:line 130
| --- End of stack trace from previous location where exception was thrown ---
| at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
| at Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase.<>c.<<-ctor>b__49_10>d.MoveNext() in C:\dev\aspnet\KestrelHttpServer\test\Kestrel.InMemory.FunctionalTests\Http2\Http2TestBase.cs:line 218
| --- End of stack trace from previous location where exception was thrown ---
| at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
| at Microsoft.AspNetCore.Testing.DummyApplication.<ProcessRequestAsync>d__7.MoveNext() in C:\dev\aspnet\KestrelHttpServer\test\shared\DummyApplication.cs:line 45
| --- End of stack trace from previous location where exception was thrown ---
| at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
| at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
| at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequests>d__185`1.MoveNext() in C:\dev\aspnet\KestrelHttpServer\src\Kestrel.Core\Internal\Http\HttpProtocol.cs:line 545
| [0.026s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "(null)", Request id ":00000003": done reading request body.
| [0.026s] Microsoft.AspNetCore.Server.Kestrel Information: Connection id "(null)", Request id ":00000003": the application completed without reading the entire request body.
| [0.026s] TestLifetime Information: Finished test DATA_Received_TooSlowlyOnSecondStream_AbortsConnectionAfterNonAdditiveRateTimeout in 0.025
Prior to this change, HTTP/2 read rate limit tests would fail when the stalled read started after the test started advancing the clock. Example: