Aspnetcore: Pipeline exceptions while stressing HTTP/2

Created on 2 Jul 2019 · 17Comments · Source: dotnet/aspnetcore

While running the simple HttpClient stress tests in , as described in https://github.com/dotnet/corefx/issues/38911#issuecomment-507722749, I'm seeing a variety of pipeline-related exceptions on the server.

warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Connection processing ended abnormally.
System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values.
   at System.IO.Pipelines.BufferSegment.set_End(Int32 value)
   at System.IO.Pipelines.Pipe.AllocateWriteHeadSynchronized(Int32 sizeHint)
   at System.IO.Pipelines.Pipe.GetSpan(Int32 sizeHint)
   at System.IO.Pipelines.Pipe.DefaultPipeWriter.GetSpan(Int32 sizeHint)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteHeader(Http2Frame frame, PipeWriter output)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteHeaderUnsynchronized()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteRstStreamAsync(Int32 streamId, Http2ErrorCode errorCode)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.WriteRstStreamAsync(Http2ErrorCode error)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.ResetAndAbort(ConnectionAbortedException abortReason, Http2ErrorCode error)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.OnErrorAfterResponseStarted()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProduceEnd()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application)

It also sometimes shows up like this:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HLNV04RDIO5I", Request id "0HLNV04RDIO5I:00000703": An unhandled exception was thrown by the application.
System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values.
   at System.IO.Pipelines.BufferSegment.set_End(Int32 value)
   at System.IO.Pipelines.Pipe.AllocateWriteHeadSynchronized(Int32 sizeHint)
   at System.IO.Pipelines.Pipe.GetSpan(Int32 sizeHint)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteHeader(Http2Frame frame, PipeWriter output)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteHeaderUnsynchronized()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.FinishWritingHeaders(Int32 streamId, Int32 payloadLength, Boolean done)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteResponseHeaders(Int32 streamId, Int32 statusCode, Http2HeadersFrameFlags headerFrameFlags, IHeaderDictionary headers)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.WriteResponseHeaders(Int32 statusCode, String ReasonPhrase, HttpResponseHeaders responseHeaders, Boolean autoChunk, Boolean appCompleted)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProduceStart(Boolean appCompleted)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.InitializeResponseAsync(Int32 firstWriteByteCount)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.Microsoft.AspNetCore.Http.Features.IHttpResponseStartFeature.StartAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Http.DefaultHttpResponse.StartAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Http.HttpResponseWritingExtensions.WriteAsync(HttpResponse response, String text, Encoding encoding, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Http.HttpResponseWritingExtensions.WriteAsync(HttpResponse response, String text, CancellationToken cancellationToken)
   at Program.<>c__DisplayClass1_0.<<Run>b__19>d.MoveNext() in d:\repos\corefx\src\System.Net.Http\tests\StressTests\HttpStress\Program.cs:line 295
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

and sometimes like this:

crit: Microsoft.AspNetCore.Server.Kestrel[0]
      Http2OutpuProducer.ProcessDataWrites() observed an unexpected exception.
System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values.
   at System.IO.Pipelines.BufferSegment.set_End(Int32 value)
   at System.IO.Pipelines.Pipe.CommitUnsynchronized()
   at System.IO.Pipelines.Pipe.PrepareFlush(CompletionData& completionData, ValueTask`1& result, CancellationToken cancellationToken)
   at System.IO.Pipelines.Pipe.FlushAsync(CancellationToken cancellationToken)
   at System.IO.Pipelines.Pipe.DefaultPipeWriter.FlushAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.TimeFlushAsync(MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()

area-servers bug servers-kestrel

Source

stephentoub

Most helpful comment

This is stressing me out so it's definitely stress.

davidfowl on 3 Jul 2019

😄4

All 17 comments

Just got a NullReferenceException, too:

crit: Microsoft.AspNetCore.Server.Kestrel[0]
      Http2OutpuProducer.ProcessDataWrites() observed an unexpected exception.
System.NullReferenceException: Object reference not set to an instance of an object.
   at System.IO.Pipelines.Pipe.CommitUnsynchronized()
   at System.IO.Pipelines.Pipe.PrepareFlush(CompletionData& completionData, ValueTask`1& result, CancellationToken cancellationToken)
   at System.IO.Pipelines.Pipe.FlushAsync(CancellationToken cancellationToken)
   at System.IO.Pipelines.Pipe.DefaultPipeWriter.FlushAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.TimeFlushAsync(MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2OutputProducer.ProcessDataWrites()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2FrameWriter.WriteDataAsync(Int32 streamId, StreamOutputFlowControl flowControl, ReadOnlySequence`1 data, Int64 dataLength, Boolean endStream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.TimingPipeFlusher.AwaitLastFlushAndTimeFlushAsync(ValueTask`1 lastFlushTask, MinDataRate minRate, Int64 count, IHttpOutputAborter outputAborter, CancellationToken cancellationToken)

stephentoub on 2 Jul 2019

And an error about reading already being in progress:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HLNV3A6E6CN6", Request id "0HLNV3A6E6CN6:00000C61": 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.
 ---> System.IO.IOException: The read operation failed, see inner exception.
 ---> System.InvalidOperationException: Reading is already in progress.
   at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_AlreadyReading()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.ReadAsync(CancellationToken token)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.<FillBufferAsync>g__InternalFillBufferAsync|215_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)
   at System.Net.Security.SslStream.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   at System.IO.Pipelines.StreamPipeReader.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
   --- End of inner exception stack trace ---
   --- 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 Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.CopyToAsyncInternal(Stream destination, CancellationToken cancellationToken)
   at Program.<>c.<<Run>b__1_20>d.MoveNext() in d:\repos\corefx\src\System.Net.Http\tests\StressTests\HttpStress\Program.cs:line 303
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

stephentoub on 2 Jul 2019

Apps https://github.com/dotnet/corefx/issues/38911#issuecomment-507810676

benaadams on 2 Jul 2019

I can almost repro this at will. On my machine it generally happens within a second or so of running:

d:\repos\corefx\src\System.Net.Http\tests\StressTests\HttpStress>dotnet run -c Release -n 100 -aspnetlog -ops 1

so I'm not sure it can even be considered "stress" :wink:

cc: @davidfowl, @halter73

stephentoub on 3 Jul 2019

This is stressing me out so it's definitely stress.

davidfowl on 3 Jul 2019

😄4

@davidfowl Do you want me to investigate the "Reading is already in progress" failure?

halter73 on 3 Jul 2019

Yes please.

davidfowl on 3 Jul 2019

@stephentoub I'm trying to reproduce the issue by running the following for your comment on the other thread, but I'm not seeing the "Reading is already in progress" anywhere in the ~70KB log after a couple minutes. This is on Win 10 using the current corefx master branch. Is there something else I need to do to force the repro?

C:\dev\dotnet\corefx\src\System.Net.Http\tests\StressTests\HttpStress [master ≡ +3 ~0 -0 !]> dotnet run -c Release -ops 0 1 4 5 6 7 -aspnetlog 2>&1 | tee stress.out
     .NET Core: 3.0.0-preview7-27902-19
  ASP.NET Core: 3.0.0-preview7.19352.5
       Tracing: False
   ASP.NET Log: True
   Concurrency: 12
Content Length: 1000
  HTTP Version: 2.0
    Operations: GET, GET Headers, POST, POST Duplex, POST ExpectContinue, POST Cancellation

Starting server.
Starting 12 client workers.
Error from iteration 18 (GET) in task 11 with 54 successes / 4 fails:
System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: The request was aborted.
 ---> System.Net.Http.Http2ProtocolException: The HTTP/2 request failed with protocol error 'STREAM_CLOSED' (0x5).
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.Http2Stream.TryEnsureHeaders()
...

halter73 on 4 Jul 2019

-ops 0 1 4 5 6 7

7 wasn't supposed to be in that list; copy/paste error on my part. That's going to issue a bunch of cancellations, cause connections to be torn down, and likely shadow any other issues.

Can you try it again without the 7?

stephentoub on 4 Jul 2019

Can you try it again without the 7?

That did the trick. I'm taking a look right now.

halter73 on 4 Jul 2019

This is a regression caused by replacing the DefaultPipeReader with the StreamPipeReader.

@Tratcher pointed out this is likely caused by Kestrel's Http2Connection calling PipeReader.CancelPendingRead() every second in order to update some state and check various timeouts on the main Http2Connection frame reading loop. I tested this theory by removing the call to CancelPendingRead() in Http2Connection.Tick() and sure enough, there were no more errors.

Using CancelPendingRead() mid-stream worked quite well when we were using the DefaultPipeReader, but StreamPipeReader implements CancelPendingRead() by passing a canceled token into Stream.ReadAsync(). StreamPipeReader does wait for the Stream.ReadAsync() call to complete before completing its PipeReader.ReadAsync() call, but SslStream apparently (and understandably) doesn't always recover well from canceled reads.

halter73 on 4 Jul 2019

likely caused by Kestrel's Http2Connection calling PipeReader.CancelPendingRead() every second in order to update some state

Does that mean for Http2 its throwing a new exception every second per connection? 😢

By design? 😕

benaadams on 4 Jul 2019

👀3

Does that mean for Http2 its throwing a new exception every second per connection? 😢

CancelPendingRead doesn't cause a normal pipe to throw, it returns a cancelled result. However it may be causing SslStream to throw. Fowler's idea to fix this was for the pipe-stream adapter to not cancel the underlying stream read, just unblock the caller. The next pipe read would pick up where it left off.

Tratcher on 5 Jul 2019

Does that mean for Http2 its throwing a new exception every second per connection?

In preview7, Kestrel does use a token for cancellation which eventually causes the raw PipeReader to throw and bubble up through SslStream. We'll change the logic to not involve throwing as part of fixing this issue.

halter73 on 5 Jul 2019

I see in the log above 2 typos from Kestrel:
https://github.com/aspnet/AspNetCore/search?q=Http2OutpuProducer&unscoped_q=Http2OutpuProducer