runtime: QUIC: QuicStream.WaitForWriteCompletionAsync sometimes doesn't complete

Description

I’ve noticed Kestrel sometimes throws an error when handling a gRPC request. See https://github.com/dotnet/aspnetcore/issues/42289

tldr; the client sent a gRPC request, the server processed it and sent a response, but aborted the connection because the request is hung on WaitForWriteCompletionAsync, and thought the request was still in-progress and exceeded the timeout to drain the request.

I investigated what is going on and it appears that most of the time in my scenario QuicStream.WaitForWriteCompletionAsync never returns. It appears to work reliably if there is a breakpoint before awaiting on a task, but not if there is a breakpoint after awaiting the task.

Reproduction Steps

  1. git clone https://github.com/jamesnk/grpc-dotnet
  2. git checkout jamesnk/net7
  3. dotnet run -c Release --project .\perf\benchmarkapps\GrpcAspNetCoreServer\ -- --LogLevel Trace --protocol h3
  4. dotnet run -c Release --project .\perf\benchmarkapps\GrpcClient\ -- -u https://localhost:5000 -c 1 --streams 1 -s unary -p h3 --grpcClientType grpcnetclient --callCount 1

Expected behavior

Client and server gracefully complete request.

Actual behavior

Half the time the QuicStream.WaitForWriteCompletionAsync task doesn’t complete. The server aborts the request and the connection because they’re unhealthy.

Logs of success and failure are below.

Success logs:

23.0973 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMJ31P1V8BHG:00000002" type Unidirectional accepted.
23.0974 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMJ31P1V8BHG" received SETTINGS frame for stream ID 2 with length 5.
23.1109 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#66993893,NativeCallback,[conn][0x29C45A0F6F0] Connection received event PEER_STREAM_STARTED ->
23.1109 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#14836038,.ctor,MsQuicSafeHandle created ->
23.1109 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,.ctor,[strm][0x29C459C94D0] Inbound bidirectional stream created in connection [conn][0x29C45A0F6F0] with StreamId 0. ->
23.1109 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event RECEIVE ->
23.1109 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,HandleEventReceive,[strm][0x29C459C94D0] Stream received 256 bytes ->
23.1110 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,ReadAsync,[strm][0x29C459C94D0] Stream reading into Memory of '4096' bytes. ->
23.1110 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,ReadAsync,[strm][0x29C459C94D0] Stream reading into Memory of '4096' bytes. ->
23.1114 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMJ31P1V8BHG:00000000" type Bidirectional accepted.
23.1117 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMJ31P1V8BHG" received HEADERS frame for stream ID 0 with length 251.
23.1117 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event RECEIVE ->
23.1117 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,HandleEventReceive,[strm][0x29C459C94D0] Stream received 7 bytes ->
23.1119 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,ReadAsync,[strm][0x29C459C94D0] Stream reading into Memory of '4096' bytes. ->
23.1119 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMJ31P1V8BHG" received DATA frame for stream ID 0 with length 7.
23.1121 info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc -
23.1121 trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[2]
      All hosts are allowed.
23.1121 dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      1 candidate(s) found for the request path '/grpc.testing.BenchmarkService/UnaryCall'
23.1121 dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
23.1121 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
23.1122 dbug: Grpc.AspNetCore.Server.ServerCallHandler[10]
      Reading message.
23.1122 dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMJ31P1V8BHG", Request id "0HMJ31P1V8BHG:00000000": started reading request body.
23.1122 trce: Grpc.AspNetCore.Server.ServerCallHandler[12]
      Deserializing 2 byte message to 'Grpc.Testing.SimpleRequest'.
23.1122 trce: Grpc.AspNetCore.Server.ServerCallHandler[13]
      Received message.
23.1129 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event RECEIVE ->
23.1129 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,HandleEventReceive,[strm][0x29C459C94D0] Stream received 0 bytes with FIN flag ->
23.1129 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event PEER_SEND_SHUTDOWN ->
23.1129 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,HandleEventPeerSendShutdown,[strm][0x29C459C94D0] Stream completing resettable event source. ->
23.1129 dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMJ31P1V8BHG", Request id "0HMJ31P1V8BHG:00000000": done reading request body.
23.1130 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHG" sending HEADERS frame for stream ID 0 with length 76.
23.1130 dbug: Grpc.AspNetCore.Server.ServerCallHandler[15]
      Sending message.
23.1130 trce: Grpc.AspNetCore.Server.ServerCallHandler[18]
      Serialized 'Grpc.Testing.SimpleResponse' to 2 byte message.
23.1130 trce: Grpc.AspNetCore.Server.ServerCallHandler[16]
      Message sent.
23.1130 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
23.1130 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHG" sending DATA frame for stream ID 0 with length 7.
23.1131 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event SEND_COMPLETE ->
23.1132 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHG" sending HEADERS frame for stream ID 0 with length 17.
23.1132 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event SEND_COMPLETE ->
23.1133 info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc - - 200 - application/grpc 1.2488ms
23.1134 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMJ31P1V8BHG:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
23.1401 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event SEND_SHUTDOWN_COMPLETE ->
23.1401 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,NativeCallback,[strm][0x29C459C94D0] Stream received event SHUTDOWN_COMPLETE ->
23.1401 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,HandleEventShutdownComplete,[strm][0x29C459C94D0] Stream completing resettable event source. ->
23.1402 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,Dispose,[strm][0x29C459C94D0] Stream disposing True ->
23.1403 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,Cleanup,[strm][0x29C459C94D0] releasing handles. ->
23.1403 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#14836038,ReleaseHandle,MsQuicSafeHandle released ->
23.1403 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#29809623,Dispose,[strm][0x29C459C94D0] Stream disposed ->

Failure logs:

43.0608 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMJ31P1V8BHF:00000000" type Bidirectional accepted.
43.0610 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMJ31P1V8BHF" received HEADERS frame for stream ID 0 with length 251.
43.0611 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,NativeCallback,[strm][0x29C459C9A70] Stream received event RECEIVE ->
43.0612 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,HandleEventReceive,[strm][0x29C459C9A70] Stream received 7 bytes ->
43.0613 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,ReadAsync,[strm][0x29C459C9A70] Stream reading into Memory of '4096' bytes. ->
43.0613 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMJ31P1V8BHF" received DATA frame for stream ID 0 with length 7.
43.0614 info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc -
43.0614 trce: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[2]
      All hosts are allowed.
43.0615 dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
      1 candidate(s) found for the request path '/grpc.testing.BenchmarkService/UnaryCall'
43.0615 dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
      Request matched endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
43.0615 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
43.0615 dbug: Grpc.AspNetCore.Server.ServerCallHandler[10]
      Reading message.
43.0615 dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMJ31P1V8BHF", Request id "0HMJ31P1V8BHF:00000000": started reading request body.
43.0615 trce: Grpc.AspNetCore.Server.ServerCallHandler[12]
      Deserializing 2 byte message to 'Grpc.Testing.SimpleRequest'.
43.0615 trce: Grpc.AspNetCore.Server.ServerCallHandler[13]
      Received message.
43.0624 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,NativeCallback,[strm][0x29C459C9A70] Stream received event RECEIVE ->
43.0624 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,HandleEventReceive,[strm][0x29C459C9A70] Stream received 0 bytes with FIN flag ->
43.0624 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,NativeCallback,[strm][0x29C459C9A70] Stream received event PEER_SEND_SHUTDOWN ->
43.0624 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,HandleEventPeerSendShutdown,[strm][0x29C459C9A70] Stream completing resettable event source. ->
43.0625 dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMJ31P1V8BHF", Request id "0HMJ31P1V8BHF:00000000": done reading request body.
43.0625 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHF" sending HEADERS frame for stream ID 0 with length 76.
43.0625 dbug: Grpc.AspNetCore.Server.ServerCallHandler[15]
      Sending message.
43.0626 trce: Grpc.AspNetCore.Server.ServerCallHandler[18]
      Serialized 'Grpc.Testing.SimpleResponse' to 2 byte message.
43.0626 trce: Grpc.AspNetCore.Server.ServerCallHandler[16]
      Message sent.
43.0626 info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'gRPC - /grpc.testing.BenchmarkService/UnaryCall'
43.0626 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHF" sending DATA frame for stream ID 0 with length 7.
43.0627 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,NativeCallback,[strm][0x29C459C9A70] Stream received event SEND_COMPLETE ->
43.0627 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ31P1V8BHF" sending HEADERS frame for stream ID 0 with length 17.
43.0628 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#3891103,NativeCallback,[strm][0x29C459C9A70] Stream received event SEND_COMPLETE ->
43.0628 info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 POST https://localhost:5000/grpc.testing.BenchmarkService/UnaryCall application/grpc - - 200 - application/grpc 1.3970ms
43.0629 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMJ31P1V8BHF:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".

The request then hangs, waiting on the task that doesn’t complete. After 5 seconds Kestrel aborts the connection which calls QuicConnection.CloseAsync which unsticks WaitForWriteCompletionAsync and the task completes.

Logs after abort:

02.0392 dbug: Microsoft.AspNetCore.Server.Kestrel.BadRequests[28]
      Connection id "0HMJ330OH884L", Request id "0HMJ330OH884L:00000000": the connection was closed because the response was not read by the client at the specified minimum data rate.
06.7638 dbug: Microsoft.AspNetCore.Server.Kestrel.Http3[53]
      Connection id "0HMJ330OH884L": GOAWAY stream ID 4.
06.7638 trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMJ330OH884L" sending GOAWAY frame for stream ID 3 with length 1.
06.7639 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16104161,NativeCallback,[strm][0x294D85D0760] Stream received event SEND_COMPLETE ->
06.7639 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[6]
      Connection id "0HMJ330OH884L" aborted by application with error code 258 because: "The connection was timed out by the server because the response was not read by the client at the specified minimum data rate.".
06.7640 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,NativeCallback,[strm][0x294D85D1840] Stream received event SEND_SHUTDOWN_COMPLETE ->
06.7640 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,NativeCallback,[strm][0x294D85D1840] Stream received event SHUTDOWN_COMPLETE ->
06.7640 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,HandleEventConnectionClose,[strm][0x294D85D1840] Stream handling connection [conn][0x294D8698DD0] close ->
06.7647 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31139921,NativeCallback,[strm][0x294D85D0A30] Stream received event SHUTDOWN_COMPLETE ->
06.7647 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31139921,HandleEventConnectionClose,[strm][0x294D85D0A30] Stream handling connection [conn][0x294D8698DD0] close ->
06.7657 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16104161,NativeCallback,[strm][0x294D85D0760] Stream received event SEND_SHUTDOWN_COMPLETE ->
06.7657 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16104161,NativeCallback,[strm][0x294D85D0760] Stream received event SHUTDOWN_COMPLETE ->
06.7657 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#16104161,HandleEventConnectionClose,[strm][0x294D85D0760] Stream handling connection [conn][0x294D8698DD0] close ->
06.7822 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,Dispose,[strm][0x294D85D1840] Stream disposing True ->
06.7822 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,Cleanup,[strm][0x294D85D1840] releasing handles. ->
06.7822 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeMsQuicStreamHandle#6849668,ReleaseHandle,MsQuicSafeHandle released ->
06.7822 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#33397131,Dispose,[strm][0x294D85D1840] Stream disposed ->
06.7995 dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMJ330OH884L:00000003" shutting down writes because: "Operation aborted.".
07.0183 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#45133484,NativeCallback,[conn][0x294D8698DD0] Connection received event SHUTDOWN_COMPLETE ->
07.0741 dbug: Microsoft.AspNetCore.Server.Kestrel.BadRequests[20]
      Connection id "0HMJ330OH884L" request processing ended abnormally.
      Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was timed out by the server because the response was not read by the client at the specified minimum data rate.
         at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
07.0743 dbug: Microsoft.AspNetCore.Server.Kestrel.Http3[44]
      Connection id "0HMJ330OH884L" is closed. The last processed stream ID was 0.
07.0744 dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[2]
      Connection id "0HMJ330OH884L" stopped.
07.0744 dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#45133484,Dispose,[conn][0x294D8698DD0] Connection disposing True ->

Regression?

Unknown

Known Workarounds

No response

Configuration

Latest .NET 7 daily build

Other information

No response

About this issue

  • Original URL
  • State: open
  • Created 2 years ago
  • Comments: 29 (22 by maintainers)

Most upvoted comments

Created https://github.com/microsoft/msquic/issues/3842

+2
CarnaViire on Sep 7, 2023

Triage: we need to create an issue in MsQuic repo and link the PR https://github.com/microsoft/msquic/pull/2904 there + mention that in order for it to work, the code should be in Close, not Shutdown (see comment above).

+1
CarnaViire on Nov 21, 2022
Read more comments on GitHub
← runtime: Quic exception in the guts of making an http request
runtime: Quic Support Check Throws Exception Breaking ASP.NET core →