Open
Description
Failing Test(s)
Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http2ConnectionTests.OutputFlowControl_ConnectionAndRequestAborted_NoException
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> [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
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+<OutputFlowControl_ConnectionAndRequestAborted_NoException>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+<OutputFlowControl_ConnectionAndRequestAborted_NoException>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+<OutputFlowControl_ConnectionAndRequestAborted_NoException>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+<OutputFlowControl_ConnectionAndRequestAborted_NoException>d__48, InMemory.FunctionalTests]].MoveNext()
00007EF54291E960 00007F361E787073 System.Runtime.CompilerServices.TaskAwaiter+<>c.<OutputWaitEtwEvents>b__12_0(System.Action, System.Threading.Tasks.Task)
00007EF54291EA50 00007F3625E60879 Xunit.Sdk.AsyncTestSyncContext+<>c__DisplayClass7_0.<Post>b__0() [/_/src/xunit.execution/Sdk/AsyncTestSyncContext.cs @ 58]
00007EF54291EA90 00007F36217589C3 Xunit.Sdk.XunitWorkerThread+<>c.<QueueUserWorkItem>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
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+<WriteToOutputPipe>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+<WriteToOutputPipe>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+<WriteToOutputPipe>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+<WriteToOutputPipe>d__28, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext()
00007EF53AFEFAD0 00007F36254C3562 System.Threading.Channels.ChannelUtilities.WakeUpWaiters(System.Threading.Channels.AsyncOperation`1<Boolean> 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+<ProcessRequestsAsync>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+<ProcessRequestsAsync>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+<ProcessRequestsAsync>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+<ProcessRequestsAsync>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>, 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+<CopyPipeAsync>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+<CopyPipeAsync>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+<CopyPipeAsync>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+<CopyPipeAsync>d__130, Microsoft.AspNetCore.Server.Kestrel.Core]].MoveNext()
00007EF53AFF0870 00007F3626032119 System.IO.Pipelines.InlineScheduler.UnsafeSchedule(System.Action`1<System.Object>, 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
[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