Skip to content
This repository has been archived by the owner on Dec 18, 2018. It is now read-only.

Wait for reads before advancing clock in Http2TimeoutTests #3090

Merged
merged 2 commits into from
Nov 13, 2018
Merged

Wait for reads before advancing clock in Http2TimeoutTests #3090

merged 2 commits into from
Nov 13, 2018

Conversation

halter73
Copy link
Member

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

JunTaoLuo
JunTaoLuo reviewed Nov 10, 2018
View reviewed changes
test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs Outdated

var stalledReadTask = context.Request.Body.ReadAsync(buffer, 0, buffer.Length);

// Write to the response so the test knows the app started the s
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: the s?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Was meant to be "stalled read." I must have gotten distracted in the middle of writing it.

@halter73 halter73 merged commit 6d375e9 into release/2.2 Nov 13, 2018
@halter73 halter73 deleted the halter73/wait-for-read branch November 13, 2018 19:33
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Reviewers

@JunTaoLuo JunTaoLuo JunTaoLuo approved these changes

@Tratcher Tratcher Awaiting requested review from Tratcher

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@halter73 @JunTaoLuo