Flaky Test: ResponseTests.ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseHeaders()

[mikeharder]

Failure

Moq.MockException : 
Expected invocation on the mock once, but was 0 times: t => t.ConnectionStop(It.IsAny<String>())
No setups configured.

Performed invocations:
ILogger.IsEnabled(Critical)
IKestrelTrace.ConnectionStart("0HLDUN0NALRJK")
IKestrelTrace.ConnectionKeepAlive("0HLDUN0NALRJK")
IKestrelTrace.ConnectionKeepAlive("0HLDUN0NALRJK")
IKestrelTrace.ConnectionKeepAlive("0HLDUN0NALRJK")
IKestrelTrace.ConnectionDisconnect("0HLDUN0NALRJK")
   at Moq.Mock.ThrowVerifyException(MethodCall expected, IEnumerable`1 setups, IEnumerable`1 actualCalls, Expression expression, Times times, Int32 callCount)
   at Moq.Mock.VerifyCalls(Interceptor targetInterceptor, MethodCall expected, Expression expression, Times times)
   at Moq.Mock.Verify[T](Mock`1 mock, Expression`1 expression, Times times, String failMessage)
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests.ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseHeaders() in /_/test/Kestrel.FunctionalTests/ResponseTests.cs:line 3218
--- End of stack trace from previous location where exception was thrown ---

http://aspnetci/viewLog.html?buildId=471974&tab=buildResultsDiv&buildTypeId=Lite_KestrelStressTest

History

http://aspnetci/project.html?projectId=XPlat&buildTypeId=&tab=testDetails&testNameId=5530107858173470981&order=TEST_STATUS_DESC&branch_XPlat=__all_branches__&itemsCount=50

[ryanbrandenburg]

A similar error on this failure, possibly related.

[Tratcher]

3 failures on the CI between May 25 and 29, all on Win2012-Kestrel.

[halter73]

More details from one of the more recent failures:

Moq.MockException : 
Expected invocation on the mock once, but was 0 times: t => t.ConnectionStop(It.IsAny<String>())
No setups configured.

Performed invocations:
KestrelTrace.IsEnabled(Critical)
KestrelTrace.BeginScope<ConnectionLogScope>([[ConnectionId, 0HLE2CH9VOTMQ]])
KestrelTrace.ConnectionStart("0HLE2CH9VOTMQ")
KestrelTrace.ConnectionDisconnect("0HLE2CH9VOTMQ")
KestrelTrace.ApplicationError("0HLE2CH9VOTMQ", "0HLE2CH9VOTMQ:00000001", System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.ValidateState(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests.<>c__DisplayClass61_0.<<WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken>b__6>d.MoveNext()
--- 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 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequests>d__186`1.MoveNext()
--- 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 Xunit.Assert.<RecordExceptionAsync>d__79.MoveNext())
   at Moq.Mock.ThrowVerifyException(MethodCall expected, IEnumerable`1 setups, IEnumerable`1 actualCalls, Expression expression, Times times, Int32 callCount)
   at Moq.Mock.VerifyCalls(Interceptor targetInterceptor, MethodCall expected, Expression expression, Times times)
   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 Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests.<WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken>d__61.MoveNext()
--- 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)
------- Stdout: -------
| [0.001s] TestLifetime Information: Starting test WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken-http://127.0.0.1:0 at 2018-05-25T17:24:11
| [0.158s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Hosting starting
| [0.253s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Hosting started
| [0.255s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Loaded hosting startup assembly Libuv.FunctionalTests, Version=2.2.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60
| [0.262s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Connection id "0HLE2CH9VOTMQ" started.
| [0.284s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Information: Request starting HTTP/1.1 POST http:///  32768
| [0.294s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Connection id "0HLE2CH9VOTMQ" paused.
| [0.326s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Connection id "0HLE2CH9VOTMQ" sending FIN.
| [0.327s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Connection id "0HLE2CH9VOTMQ" disconnecting.
| [0.338s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Hosting shutdown
| [0.339s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Error: Connection id "0HLE2CH9VOTMQ", Request id "0HLE2CH9VOTMQ:00000001": An unhandled exception was thrown by the application.
| System.OperationCanceledException: The operation was canceled.
|    at System.Threading.CancellationToken.ThrowOperationCanceledException()
|    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.ValidateState(CancellationToken cancellationToken)
|    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpResponseStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
|    at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests.<>c__DisplayClass61_0.<<WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken>b__6>d.MoveNext()
| --- 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 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequests>d__186`1.MoveNext()
| --- 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 Xunit.Assert.<RecordExceptionAsync>d__79.MoveNext()
| [0.341s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Information: Request finished in 57.136ms 200 
| [0.352s] Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.ResponseTests Debug: Connection id "0HLE2CH9VOTMQ" stopped.
| [0.357s] TestLifetime Information: Finished test WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedToken-http://127.0.0.1:0 in 0.3557993s

It's notable that "Connection id "0HLE2CH9VOTMQ" stopped." was indeed logged, but not before WebHost.Dispose() completed. Given that the ApplicationError on the other hand was logged by the time WebHost.Dispose() completed, I think the most likely cause of this bug is the issue being fixed by #2646.

[mikeharder]

Test failed on my local Ubuntu 18.04 Hyper-V VM with the same callstack as #2595 (comment).

[ryanbrandenburg]

ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLargeResponseHeaders failed with about the same error on 2.2.

This comment was made automatically. If there is a problem contact ryanbrandenburg.