Skip to content

HTTP/2: Possible race when receiving HEADERS and RST_STREAM together #68373

New issue
New issue
Closed
#72932
Closed
HTTP/2: Possible race when receiving HEADERS and RST_STREAM together#68373
#72932
Assignees
rzikm
Labels
area-System.Net.Httpbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)
Milestone
7.0.0
@JamesNK

Description

@JamesNK
JamesNK
opened on Apr 22, 2022

Description

Kestrel has recently updated how HTTP/2 is written. One of the changes is to what happens if a request is ended and then the request is immediately reset. At a frame-level, Kestrel is writing a HEADERS frame with an END_HEADERS flag, then writing a RST_STREAM. Before, Kestrel would pause after writing HEADERS, as the bytes are flushed to the client. After the update, Kestrel would write and send the two frames together.

In HttpClient, before, SendAsync would always return HttpResponseMessage. With the new server behavior, SendAsync continues to return HttpResponseMessage (about 90% of the time). Other times it throws an error:

System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: The request was aborted.
 ---> System.Net.Http.Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0).
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryEnsureHeaders()
   at System.Net.Http.Http2Connection.Http2Stream.ReadResponseHeadersAsync(CancellationToken cancellationToken)
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 443

The HEADERS frame and RST_STREAM frame are always written in the right order. There appears to be a race between how they're processed.

If response headers are returned then SendAsync should always return HttpResponseMessage, regardless of the fact it is followed by RST_STREAM.

Reproduction Steps

HttpInvoker + SocketsHttpHandler + h2c makes call to server.
The server writes response headers with HEADERS frame and END_STREAM flag, together with RST_STREAM (NO_ERROR).The server

Expected behavior

HttpResponseMessage is always returned.

Actual behavior

HttpInvoker.SendAsync fails 10% of the time with an error.

Regression?

Probably not. Kestrel has changed in .NET 7, but I believe the timing of how it sends frames has exposed a race that has been in the client's HTTP/2 processing.

Known Workarounds

No response

Configuration

.NET SDK 7.0.100-preview.5.22221.9

Other information

Logs below. Truncated to just show the end of the request.

Logging of success (HttpResponseMessage returned):

0.523s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Request with timeout of 00:00:00.5000000 has exceeded its deadline.
0.523s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMH40UT8UKOA:000000C9": HTTP/2 stream error "NO_ERROR". A Reset is being sent to the stream.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 stream was reset by the application with error code NO_ERROR.
0.523s HttpEventSourceListener - Debug: <- Event Grpc.Net.Client - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMH40UT8UKOA" sending HEADERS frame for stream ID 201 with length 40 and flags END_HEADERS.
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMH40UT8UKOA" sending RST_STREAM frame for stream ID 201 with length 4 and flags 0x0.
0.523s HttpEventSourceListener - Debug: <- Event Grpc.Net.Client - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.Net.Client - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.Net.Client - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReadFrameAsync,initialFrame=False ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessIncomingFramesAsync,Frame 231: StreamId=201; Type=Headers; Flags=EndHeaders; PayloadLength=40. ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessHeadersFrame,StreamId=201; Type=Headers; Flags=EndHeaders; PayloadLength=40 ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnStatus,Status code is 200 ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,Content-Type: application/grpc ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,Date: Fri, 22 Apr 2022 02:29:01 GMT ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,Server: Kestrel ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,Content-Length: 0 ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,grpc-status: 4 ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnHeader,grpc-message: Deadline Exceeded ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReadFrameAsync,initialFrame=False ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessIncomingFramesAsync,Frame 232: StreamId=201; Type=RstStream; Flags=None; PayloadLength=4. ->
0.523s HttpEventSourceListener - Debug: <- Event System.Net.Http - ResponseHeadersStop :  ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,ProcessRstStreamFrame,protocolError=NoError ->
0.523s HttpEventSourceListener - Debug: <- Event Grpc.AspNetCore.Server - EventCounters : System.Diagnostics.Tracing.EventPayload ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,ReadResponseHeadersAsync,Received response: StatusCode: 200, ReasonPhrase: 'OK', Version: 2.0, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Date: Fri, 22 Apr 2022 02:29:01 GMT
  Server: Kestrel
  grpc-status: 4
  grpc-message: Deadline Exceeded
  Content-Type: application/grpc
  Content-Length: 0
} ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,OnReset,resetException=System.Net.Http.Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0)., resetStreamErrorCode=NoError ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,Cancel, ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,SendReset,Stream reset. Request=Completed, Response=Failed. ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,Complete,Stream complete. Request=Completed, Response=Failed. ->
0.523s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStop :  ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,201,RemoveStream, ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReleaseStream,_streamsInUse=1 ->
0.523s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,SignalAvailableStreamsWaiter,result=True, _availableStreamsWaiter?=False ->
0.523s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.523s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'DeadlineExceeded', Message: 'Deadline Exceeded'.
0.523s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.

Failure (error thrown):

0.523s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Request with timeout of 00:00:00.5000000 has exceeded its deadline.
0.523s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMH40UT8UKOA:0000003B": HTTP/2 stream error "NO_ERROR". A Reset is being sent to the stream.
Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 stream was reset by the application with error code NO_ERROR.
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMH40UT8UKOA" sending HEADERS frame for stream ID 59 with length 40 and flags END_HEADERS.
0.523s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMH40UT8UKOA" sending RST_STREAM frame for stream ID 59 with length 4 and flags 0x0.
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReadFrameAsync,initialFrame=False ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessIncomingFramesAsync,Frame 71: StreamId=59; Type=Headers; Flags=EndHeaders; PayloadLength=40. ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessHeadersFrame,StreamId=59; Type=Headers; Flags=EndHeaders; PayloadLength=40 ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnStatus,Status code is 200 ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,Content-Type: application/grpc ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,Date: Fri, 22 Apr 2022 02:28:20 GMT ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,Server: Kestrel ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,Content-Length: 0 ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,grpc-status: 4 ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnHeader,grpc-message: Deadline Exceeded ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReadFrameAsync,initialFrame=False ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ProcessIncomingFramesAsync,Frame 72: StreamId=59; Type=RstStream; Flags=None; PayloadLength=4. ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,ProcessRstStreamFrame,protocolError=NoError ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,OnReset,resetException=System.Net.Http.Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0)., resetStreamErrorCode=NoError ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,Cancel, ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,SendReset,Stream reset. Request=Completed, Response=Failed. ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,Complete,Stream complete. Request=Completed, Response=Failed. ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,RemoveStream, ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,ReleaseStream,_streamsInUse=1 ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,0,SignalAvailableStreamsWaiter,result=True, _availableStreamsWaiter?=False ->
0.524s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 17968358,64923656,59,Cancel, ->
0.524s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestFailed :  ->
0.525s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : HttpClient#57263895,HandleFailure,System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: The request was aborted.
 ---> System.Net.Http.Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0).
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryEnsureHeaders()
   at System.Net.Http.Http2Connection.Http2Stream.ReadResponseHeadersAsync(CancellationToken cancellationToken)
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) ->
0.525s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStop :  ->
0.525s Grpc.Net.Client.Internal.GrpcCall - Error: Error starting gRPC call.
System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: The request was aborted.
 ---> System.Net.Http.Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0).
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryEnsureHeaders()
   at System.Net.Http.Http2Connection.Http2Stream.ReadResponseHeadersAsync(CancellationToken cancellationToken)
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Internal\GrpcCall.cs:line 443
0.526s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error starting gRPC call. HttpRequestException: An error occurred while sending the request. IOException: The request was aborted. Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'NO_ERROR' (0x0).'.
0.526s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.526s Grpc.Net.Client.Internal.GrpcCall - Debug: gRPC call canceled.

Metadata

Metadata

Assignees

Labels

area-System.Net.Httpbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions