[HTTP/3] Reading the request headers timed out.

[ManickaP]

While investigating HTTP/3 stress (dotnet/runtime#56310), sometimes operations with slow content sending PUT Slow and/or POST Duplex Slow, which use ByteAtATimeNoLengthContent content, will end with connection aborted by peer or stream aborted by peer.

This time, I was able to catch one with logs:

2021-09-17 20:13:35.596 +02:00 [DBG] Stream id "0HMBQ0NFCM879:0001D00C" type "Bidirectional" accepted.
2021-09-17 20:13:35.596 +02:00 [INF] Request starting HTTP/3 POST https://localhost:5001/duplexSlow - -
2021-09-17 20:13:35.596 +02:00 [DBG] 1 candidate(s) found for the request path '/duplexSlow'
2021-09-17 20:13:35.596 +02:00 [DBG] Request matched endpoint '/duplexSlow HTTP: POST'
2021-09-17 20:13:35.596 +02:00 [INF] Executing endpoint '/duplexSlow HTTP: POST'
2021-09-17 20:13:35.596 +02:00 [DBG] Connection id "0HMBQ0NFCM879", Request id "0HMBQ0NFCM879:0001D00C": started reading request body.
2021-09-17 20:13:35.596 +02:00 [DBG] Trace id "0HMBQ0NFCM879:0001D00C": HTTP/3 stream error "H3_REQUEST_REJECTED". An abort is being sent to the stream.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: Reading the request headers timed out.
2021-09-17 20:13:35.596 +02:00 [DBG] Stream id "0HMBQ0NFCM879:0001D00C" aborted by application with error code 267 because: "Reading the request headers timed out.".
2021-09-17 20:13:35.597 +02:00 [DBG] Stream id "0HMBQ0NFCM879:0001D00C" shutting down writes because: "Reading the request headers timed out.".
2021-09-17 20:13:35.597 +02:00 [INF] Executed endpoint '/duplexSlow HTTP: POST'
2021-09-17 20:13:35.597 +02:00 [ERR] Connection id "0HMBQ0NFCM879", Request id "0HMBQ0NFCM879:0001D00C": An unhandled exception was thrown by the application.
System.Threading.Tasks.TaskCanceledException: The request was aborted
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: Reading the request headers timed out.
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3Stream.ProcessRequestAsync[TContext](IHttpApplication`1 application)
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3MessageBody.ReadAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken)
   at HttpStress.StressServer.<>c.<<MapRoutes>b__6_8>d.MoveNext() in /home/manicka/repositories/runtime.2/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressServer.cs:line 291
--- End of stack trace from previous location ---
   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)
2021-09-17 20:13:35.611 +02:00 [INF] Request finished HTTP/3 POST https://localhost:5001/duplexSlow - - - 200 - - 15.7498ms
2021-09-17 20:13:35.612 +02:00 [DBG] Connection id "0HMBQ0NFCM879", Request id "0HMBQ0NFCM879:0001D00C": done reading request body.
2021-09-17 20:13:35.612 +02:00 [INF] Connection id "0HMBQ0NFCM879", Request id "0HMBQ0NFCM879:0001D00C": the application completed without reading the entire request body.
2021-09-17 20:13:35.612 +02:00 [DBG] Stream id "0HMBQ0NFCM879:0001D00C" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".

Client exception:

System.Net.Http.HttpRequestException: Error while copying content to a stream.
 ---> System.IO.IOException: An error occurred while sending the request.
 ---> System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.Net.Quic.QuicStreamAbortedException: Stream aborted by peer (267).
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEventPeerSendAborted(State state, StreamEvent& evt)
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEvent(State state, StreamEvent& evt)
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.NativeCallbackHandler(IntPtr stream, IntPtr context, StreamEvent& streamEvent)
--- End of stack trace from previous location ---
   at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.GetResult(Int16 token)
   at System.Net.Http.Http3RequestStream.ReadFrameEnvelopeAsync(CancellationToken cancellationToken)
   at System.Net.Http.Http3RequestStream.ReadNextDataFrameAsync(HttpResponseMessage response, CancellationToken cancellationToken)
   at System.Net.Http.Http3RequestStream.ReadResponseContentAsync(HttpResponseMessage response, Memory`1 buffer, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at System.Net.Http.Http3RequestStream.HandleReadResponseContentException(Exception ex, CancellationToken cancellationToken)
   at System.Net.Http.Http3RequestStream.ReadResponseContentAsync(HttpResponseMessage response, Memory`1 buffer, CancellationToken cancellationToken)
   at System.IO.Stream.<CopyToAsync>g__Core|29_0(Stream source, Stream destination, Int32 bufferSize, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionResponseContent.SerializeToStreamAsync(Stream stream, TransportContext context, CancellationToken cancellationToken)
   at System.Net.Http.HttpContent.LoadIntoBufferAsyncCore(Task serializeToStreamTask, MemoryStream tempBuffer)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpContent.LoadIntoBufferAsyncCore(Task serializeToStreamTask, MemoryStream tempBuffer)
   at System.Net.Http.HttpContent.WaitAndReturnAsync[TState,TResult](Task waitTask, TState state, Func`2 returnFunc)
   at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_8>d.MoveNext() in /home/manicka/repositories/runtime.2/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs:line 408
--- End of stack trace from previous location ---
   at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /home/manicka/repositories/runtime.2/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs:line 204

Versions:

       .NET Core: /usr/share/dotnet/shared/Microsoft.NETCore.App/6.0.0-rc.1.21430.1/System.Private.CoreLib.dll, modified 9/8/2021 6:52:29 PM
    ASP.NET Core: /usr/share/dotnet/shared/Microsoft.AspNetCore.App/6.0.0-rc.1.21430.5/Microsoft.AspNetCore.dll, modified 9/8/2021 6:52:29 PM
 System.Net.Http: /usr/share/dotnet/shared/Microsoft.NETCore.App/6.0.0-rc.1.21430.1/System.Net.Http.dll, modified 9/8/2021 6:52:29 PM

We never see something like this with HTTP/2.

[adityamandaleeka]

Let's make sure the StreamTimeoutTicks is actually cleared between stream reuses.

[adityamandaleeka]

@ManickaP Looks like the timeout in the related issue was later determined to be a bug in msquic. Should we close this issue or is there still something to investigate here?

[ManickaP]

Looks like the timeout in the related issue was later determined to be a bug in msquic.

Was it? I don't remember. Do you have an issue link?

[adityamandaleeka]

I was going by this comment: dotnet/runtime#56310 (comment)

[ManickaP]

Let's close it then. I just checked and I don't see this particular error in our recent runs. We'll re-open in case we see it again. Thanks.