search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.19k stars 9.93k forks source link

Quarantine OutputFlowControl_ConnectionAndRequestAborted_NoException #44415

Open halter73 opened 1 year ago

halter73 commented 1 year ago

Failing Test(s)

Error Message

Helix just reports "The Helix Work Item failed. Often this is due to a test crash. Please see the 'Artifacts' tab above for additional logs." for the InMemory.FunctionalTests--net7.0 Work Item.

This is a deadlock with two relevant stack traces collected from the hangdump using clrstack -all.

After a quick look at that stack traces, I'm convince this is a test-only issue that's only possible because we use AllowSynchronousContinuations = true on the Http2FrameWriter channel in Kestrel's in-memory tests. I tried setting AllowSynchronousContinuations = false to see how many tests failed, and I saw these 11 test failures immediately. There could more than that that would become flaky with this change.

Test failures without AllowSynchronousContinuations ``` Test Class Duration Error Message Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.StreamPool_MultipleStreamsInSequence_PooledStreamReused Failed Http2ConnectionTests 4 ms Assert.Equal() Failure Expected: 1 Actual: 0 Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.StreamPool_SingleStream_ReturnedToPool Failed Http2ConnectionTests 4 ms Assert.Equal() Failure Expected: 1 Actual: 0 Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.AbortAfterCompleteAsync_GETWithResponseBodyAndTrailers_ResetsAfterResponse Failed Http2StreamTests 4 ms Assert.True() Failure Expected: True Actual: False Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.AbortAfterCompleteAsync_POSTWithResponseBodyAndTrailers_RequestBodyThrows Failed Http2StreamTests 9 ms Assert.Equal() Failure Expected: INTERNAL_ERROR Actual: NO_ERROR Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.BodyWriterWriteAsync_OnCanceledPendingFlush_ReturnsResultWithIsCanceled Failed Http2StreamTests 4 ms Assert.Equal() Failure Expected: 6 Actual: 12 Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.CompleteAsync_AfterBodyStarted_WithTrailers_SendsBodyAndTrailersWithEndStream Failed Http2StreamTests 3 ms Assert.True() Failure Expected: True Actual: False Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.CompleteAsync_AfterPipeWrite_WithTrailers_SendsBodyAndTrailersWithEndStream Failed Http2StreamTests 4 ms Assert.True() Failure Expected: True Actual: False Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.CompleteAsync_BeforeBodyStarted_WithTrailers_SendsHeadersAndTrailersWithEndStream Failed Http2StreamTests 3 ms Assert.True() Failure Expected: True Actual: False Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.ResetAfterCompleteAsync_GETWithResponseBodyAndTrailers_ResetsAfterResponse Failed Http2StreamTests 5 sec System.TimeoutException : The operation has timed out. Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2StreamTests.ResetAfterCompleteAsync_POSTWithResponseBodyAndTrailers_RequestBodyThrows Failed Http2StreamTests 8 ms Assert.Contains() Failure Not found: (filter expression) In value: ConcurrentQueue [LogMessage { EventId = Http2FrameSending, Exception = null, LogLevel = Trace, Message = "Connection id \"TestConnectionId\" sending SETTING"... }, LogMessage { EventId = Http2FrameSending, Exception = null, LogLevel = Trace, Message = "Connection id \"TestConnectionId\" sending WINDOW_"... }, LogMessage { EventId = Http2FrameReceived, Exception = null, LogLevel = Trace, Message = "Connection id \"TestConnectionId\" received SETTIN"... }, LogMessage { EventId = Http2FrameSending, Exception = null, LogLevel = Trace, Message = "Connection id \"TestConnectionId\" sending SETTING"... }, LogMessage { EventId = Http2FrameReceived, Exception = null, LogLevel = Trace, Message = "Connection id \"TestConnectionId\" received HEADER"... }, ...] Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TimeoutTests.HEADERS_NotReceivedAfterFirstRequest_WithinKeepAliveTimeout_ClosesConnection Failed Http2TimeoutTests 5.2 sec System.TimeoutException : The operation has timed out. ```

I'm not sure, but I think this could be the root cause for other Http2Connection tests timeouts like the one described in #41172. It seems possible that deadlocks might happen on only on background threads in cases where we see Task timeouts instead of the entire helix work item hanging.

Stacktrace

Stack Trace 1 ```text OS Thread Id: 0x7337 Child SP IP Call Site 00007EF54291E490 00007f369e13d376 [HelperMethodFrame_1OBJ: 00007ef54291e490] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef) 00007EF54291E5E0 00007F3626277DDB Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.Stop() 00007EF54291E610 00007F3626060F40 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.AbortConnectionFlowControl() 00007EF54291E680 00007F3626060CD2 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.Complete() 00007EF54291E6B0 00007F362627758D Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.Abort(Microsoft.AspNetCore.Connections.ConnectionAbortedException) 00007EF54291E6F0 00007F36262774D9 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.Abort(Microsoft.AspNetCore.Connections.ConnectionAbortedException) 00007EF54291E740 00007F362635F9E7 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.HandleReadDataRateTimeout() 00007EF54291E780 00007F3626D4075A Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests+d__48.MoveNext() 00007EF54291E880 00007F3626D43563 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests+d__48, InMemory.FunctionalTests]].ExecutionContextCallback(System.Object) 00007EF54291E8A0 00007F3626215589 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF54291E8F0 00007F3626D4341F System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests+d__48, InMemory.FunctionalTests]].MoveNext(System.Threading.Thread) 00007EF54291E940 00007F3626D4331A System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests+d__48, InMemory.FunctionalTests]].MoveNext() 00007EF54291E960 00007F361E787073 System.Runtime.CompilerServices.TaskAwaiter+<>c.b__12_0(System.Action, System.Threading.Tasks.Task) 00007EF54291EA50 00007F3625E60879 Xunit.Sdk.AsyncTestSyncContext+<>c__DisplayClass7_0.b__0() [/_/src/xunit.execution/Sdk/AsyncTestSyncContext.cs @ 58] 00007EF54291EA90 00007F36217589C3 Xunit.Sdk.XunitWorkerThread+<>c.b__5_0(System.Object) [/_/src/common/XunitWorkerThread.cs @ 37] 00007EF54291EAD0 00007F3626215589 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF54291EB20 00007F3626240BCC System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) 00007EF54291ECF0 00007f369d8c4e57 [DebuggerU2MCatchHandlerFrame: 00007ef54291ecf0] ```
Stack Trace 2 ```text OS Thread Id: 0x559e Child SP IP Call Site 00007EF53AFEF550 00007f369e13d376 [HelperMethodFrame_1OBJ: 00007ef53afef550] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef) 00007EF53AFEF6A0 00007F362607DCC5 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.CheckConnectionWindow(Int64) 00007EF53AFEF6E0 00007F3625EADDDE Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter+d__28.MoveNext() 00007EF53AFEF9F0 00007F36260623A3 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter+d__28, Microsoft.AspNetCore.Server.Kestrel.Core]].ExecutionContextCallback(System.Object)00007EF53AFEFA10 00007F3626215589 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF53AFEFA60 00007F362606221F System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter+d__28, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext(System.Threading.Thread) 00007EF53AFEFAB0 00007F3626061F9A System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter+d__28, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext() 00007EF53AFEFAD0 00007F36254C3562 System.Threading.Channels.ChannelUtilities.WakeUpWaiters(System.Threading.Channels.AsyncOperation`1 ByRef, Boolean, System.Exception) 00007EF53AFEFB10 00007F36254C7B52 System.Threading.Channels.BoundedChannel`1+BoundedChannelWriter[[System.__Canon, System.Private.CoreLib]].TryWrite(System.__Canon) 00007EF53AFEFB70 00007F362607D7AC Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.Schedule(Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer) 00007EF53AFEFBB0 00007F362607D48B Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.Schedule() 00007EF53AFEFBE0 00007F3626277E23 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.Stop() 00007EF53AFEFC10 00007F3626277D2B Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.AbortCore(System.Exception) 00007EF53AFEFC40 00007F3626277CE5 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.Abort(System.IO.IOException) 00007EF53AFEFC70 00007F3625EA7C7D Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__83`1[[System.__Canon, System.Private.CoreLib]].MoveNext() 00007EF53AFF0290 00007F3626035D31 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__83`1[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Server.Kestrel.Core]].ExecutionContextCallback(System.Object) 00007EF53AFF02D0 00007F3626215589 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF53AFF0320 00007F36260358B7 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__83`1[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext(System.Threading.Thread) 00007EF53AFF03C0 00007F36260354EA System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__83`1[[System.__Canon, System.Private.CoreLib]], Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext() 00007EF53AFF03E0 00007F3626032119 System.IO.Pipelines.InlineScheduler.UnsafeSchedule(System.Action`1, System.Object) 00007EF53AFF0410 00007F3625E9003E System.IO.Pipelines.Pipe.CompleteWriter(System.Exception) 00007EF53AFF0490 00007F3625E8FF06 System.IO.Pipelines.Pipe+DefaultPipeWriter.Complete(System.Exception) 00007EF53AFF04B0 00007F362603DDB9 System.IO.Pipelines.PipeWriter.CompleteAsync(System.Exception) 00007EF53AFF0510 00007F3625EA5437 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__130.MoveNext() 00007EF53AFF0790 00007F3626032453 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__130, Microsoft.AspNetCore.Server.Kestrel.Core]].ExecutionContextCallback(System.Object) 00007EF53AFF07B0 00007F3626215589 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF53AFF0800 00007F362603230F System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__130, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext(System.Threading.Thread) 00007EF53AFF0850 00007F362603215A System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection+d__130, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext() 00007EF53AFF0870 00007F3626032119 System.IO.Pipelines.InlineScheduler.UnsafeSchedule(System.Action`1, System.Object) 00007EF53AFF08A0 00007F3625E9003E System.IO.Pipelines.Pipe.CompleteWriter(System.Exception) 00007EF53AFF0920 00007F3625E8FF06 System.IO.Pipelines.Pipe+DefaultPipeWriter.Complete(System.Exception) 00007EF53AFF0940 00007F362628F969 Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2TestBase+<>c__DisplayClass52_0.<.ctor>b__17() 00007EF53AFF09A0 00007F362624C093 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 00007EF53AFF09E0 00007F3626240BAF System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) 00007EF53AFF0A60 00007F361E72A075 System.Threading.ThreadPoolWorkQueue.Dispatch() 00007EF53AFF0AD0 00007F361E732D42 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() 00007EF53AFF0CF0 00007f369d8c4e57 [DebuggerU2MCatchHandlerFrame: 00007ef53aff0cf0] ```

Logs

```text [0.001s] [TestLifetime] [Information] Starting test OutputFlowControl_ConnectionAndRequestAborted_NoException at 2022-10-06T23:48:40 [0.026s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 24 and flags NONE. [0.026s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0. [0.026s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received SETTINGS frame for stream ID 0 with length 12 and flags NONE. [0.026s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK. [0.038s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" received HEADERS frame for stream ID 1 with length 310 and flags END_STREAM, END_HEADERS. [0.039s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending HEADERS frame for stream ID 1 with length 32 and flags END_HEADERS. [0.039s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 16384 and flags NONE. [0.039s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 16384 and flags NONE. [0.039s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 16384 and flags NONE. [0.039s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending DATA frame for stream ID 1 with length 16383 and flags NONE. [0.040s] [Microsoft.AspNetCore.Server.Kestrel.BadRequests] [Debug] Connection id "TestConnectionId", Request id "null": the request timed out because it was not sent by the client at a minimum of 240 bytes/second. [0.040s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Debug] Connection id "TestConnectionId" is closed. The last processed stream ID was 1. [0.040s] [Microsoft.AspNetCore.Server.Kestrel.Http2] [Verbose] Connection id "TestConnectionId" sending GOAWAY frame for stream ID 0 with length 8 and flags 0x0. [0.040s] [Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests] [Information] ConnectionContext.Abort() was called. Completing _pair.Application.Output. Microsoft.AspNetCore.Connections.ConnectionAbortedException: Reading the request body timed out due to data arriving too slowly. See MinRequestBodyDataRate. [0.041s] [Microsoft.AspNetCore.Server.Kestrel.BadRequests] [Debug] Connection id "TestConnectionId" request processing ended abnormally. Microsoft.AspNetCore.Connections.ConnectionAbortedException: Reading the request body timed out due to data arriving too slowly. See MinRequestBodyDataRate. at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result) at System.IO.Pipelines.Pipe.GetReadAsyncResult() at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.CopyPipeAsync(PipeReader reader, PipeWriter writer) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs:line 1686 at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result) at System.IO.Pipelines.Pipe.GetReadAsyncResult() at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application) in /_/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs:line 234 ```

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=43548&view=results https://dev.azure.com/dnceng-public/public/_build/results?buildId=43548&view=ms.vss-test-web.build-test-results-tab&runId=885050&resultId=122079&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

amcasey commented 3 weeks ago

This test hasn't failed in the last 30 days.

amcasey commented 3 weeks ago

@BrennanConroy would this have been fixed by https://github.com/dotnet/aspnetcore/pull/55738?

BrennanConroy commented 2 weeks ago

Unlikely, like Stephen said:

I'm convince this is a test-only issue that's only possible because we use AllowSynchronousContinuations = true on the Http2FrameWriter channel in Kestrel's in-memory tests