[HTTP/2] Race between reading response and reset?

[JamesNK]

The server is completing the response stream and then sending RST_STREAM frame.

The client should be able to read the response to the end without error. Instead, they are getting an error.

This is from a flakey test. This is the only time I've seen it fail.

 WriteMessageAfterDeadline
   Source: DeadlineTests.cs line 114
   Duration: 218 ms

  Message: 
System.IO.IOException : The request was aborted.
  ----> System.Net.Http.Http2ConnectionException : The HTTP/2 server sent invalid data on the connection. HTTP/2 error code 'PROTOCOL_ERROR' (0x1).

  Stack Trace: 
Http2Connection.ThrowRequestAborted(Exception innerException)
Http2Stream.CheckResponseBodyState()
Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
StreamPipeReader.<ReadAsync>g__Core|36_0(StreamPipeReader reader, CancellationTokenSource tokenSource, CancellationToken cancellationToken)
PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken) line 268
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 72
MessageHelpers.AssertReadStreamMessageAsync[T](PipeReader pipeReader, String compressionEncoding, List`1 compressionProviders) line 102
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 72
<<WriteMessageAfterDeadline>b__2>d.MoveNext() line 187
--- End of stack trace from previous location ---
TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 96
DeadlineTests.WriteMessageAfterDeadline() line 202
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass1_0.<Execute>b__0()
BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)
--Http2ConnectionException
Http2Connection.ThrowProtocolError(Http2ProtocolErrorCode errorCode)
RttEstimator.OnPingAckReceived(Int64 payload, Http2Connection connection)
Http2Connection.ProcessPingFrame(FrameHeader frameHeader)
Http2Connection.ProcessIncomingFramesAsync()

  Standard Output: 
0.000s GrpcTestContext - Information: Starting DeadlineTests.WriteMessageAfterDeadline
0.001s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Discovering gRPC methods for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.BinderServiceMethodProvider - Debug: Could not find bind method for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Added gRPC method 'WriteUntilError' to service 'DynamicService'. Method type: 'ServerStreaming', route pattern: '/DynamicService/WriteUntilError'.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1REBPPE4G" accepted.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1REBPPE4G" started.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received SETTINGS frame for stream ID 0 with length 12 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received HEADERS frame for stream ID 1 with length 90 and flags END_HEADERS.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received DATA frame for stream ID 1 with length 12 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received DATA frame for stream ID 1 with length 0 and flags END_STREAM.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received SETTINGS frame for stream ID 0 with length 0 and flags ACK.
0.004s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/2 POST http://127.0.0.1:50050/DynamicService/WriteUntilError application/grpc -
0.004s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/WriteUntilError'
0.005s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/WriteUntilError'
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Request deadline timeout of 00:00:00.2000000 started.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.005s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1REBPPE4G", Request id "0HMB1REBPPE4G:00000001": started reading request body.
0.005s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1REBPPE4G", Request id "0HMB1REBPPE4G:00000001": done reading request body.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 7 byte message to 'Greet.HelloRequest'.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 59 and flags END_HEADERS.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Greet.HelloReply' to 22 byte message.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending DATA frame for stream ID 1 with length 27 and flags NONE.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received PING frame for stream ID 0 with length 8 and flags NONE.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending PING frame for stream ID 0 with length 8 and flags ACK.
0.215s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Request with timeout of 00:00:00.2000000 has exceeded its deadline.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 47 and flags END_STREAM, END_HEADERS.
0.216s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMB1REBPPE4G:00000001": 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.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending RST_STREAM frame for stream ID 1 with length 4 and flags 0x0.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets - Debug: Connection id "0HMB1REBPPE4G" reset.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Connection id "0HMB1REBPPE4G" is closed. The last processed stream ID was 1.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets - Debug: Connection id "0HMB1REBPPE4G" sending FIN because: "The client closed the connection."
0.219s GrpcTestContext - Information: Finishing DeadlineTests.WriteMessageAfterDeadline

Important bit:

0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 47 and flags END_STREAM, END_HEADERS.
0.216s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMB1REBPPE4G:00000001": 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.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending RST_STREAM frame for stream ID 1 with length 4 and flags 0x0.

The server is sending END_STREAM flag, then sending RST_STREAM frame.

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21417.11
 Commit:    ca60baef37

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

---

The server is completing the response stream and then sending RST_STREAM frame.

The client should be able to read the response to the end without error. Instead, they are getting an error.

This is from a flakey test. This is the only time I've seen it fail.

 WriteMessageAfterDeadline
   Source: DeadlineTests.cs line 114
   Duration: 218 ms

  Message: 
System.IO.IOException : The request was aborted.
  ----> System.Net.Http.Http2ConnectionException : The HTTP/2 server sent invalid data on the connection. HTTP/2 error code 'PROTOCOL_ERROR' (0x1).

  Stack Trace: 
Http2Connection.ThrowRequestAborted(Exception innerException)
Http2Stream.CheckResponseBodyState()
Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
StreamPipeReader.<ReadAsync>g__Core|36_0(StreamPipeReader reader, CancellationTokenSource tokenSource, CancellationToken cancellationToken)
PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken) line 268
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 72
MessageHelpers.AssertReadStreamMessageAsync[T](PipeReader pipeReader, String compressionEncoding, List`1 compressionProviders) line 102
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 72
<<WriteMessageAfterDeadline>b__2>d.MoveNext() line 187
--- End of stack trace from previous location ---
TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 96
DeadlineTests.WriteMessageAfterDeadline() line 202
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass1_0.<Execute>b__0()
BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)
--Http2ConnectionException
Http2Connection.ThrowProtocolError(Http2ProtocolErrorCode errorCode)
RttEstimator.OnPingAckReceived(Int64 payload, Http2Connection connection)
Http2Connection.ProcessPingFrame(FrameHeader frameHeader)
Http2Connection.ProcessIncomingFramesAsync()

  Standard Output: 
0.000s GrpcTestContext - Information: Starting DeadlineTests.WriteMessageAfterDeadline
0.001s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Discovering gRPC methods for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.BinderServiceMethodProvider - Debug: Could not find bind method for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Added gRPC method 'WriteUntilError' to service 'DynamicService'. Method type: 'ServerStreaming', route pattern: '/DynamicService/WriteUntilError'.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1REBPPE4G" accepted.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1REBPPE4G" started.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received SETTINGS frame for stream ID 0 with length 12 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received HEADERS frame for stream ID 1 with length 90 and flags END_HEADERS.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received DATA frame for stream ID 1 with length 12 and flags NONE.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received DATA frame for stream ID 1 with length 0 and flags END_STREAM.
0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received SETTINGS frame for stream ID 0 with length 0 and flags ACK.
0.004s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/2 POST http://127.0.0.1:50050/DynamicService/WriteUntilError application/grpc -
0.004s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/WriteUntilError'
0.005s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/WriteUntilError'
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Request deadline timeout of 00:00:00.2000000 started.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.005s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1REBPPE4G", Request id "0HMB1REBPPE4G:00000001": started reading request body.
0.005s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1REBPPE4G", Request id "0HMB1REBPPE4G:00000001": done reading request body.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 7 byte message to 'Greet.HelloRequest'.
0.005s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 59 and flags END_HEADERS.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Greet.HelloReply' to 22 byte message.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending DATA frame for stream ID 1 with length 27 and flags NONE.
0.006s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" received PING frame for stream ID 0 with length 8 and flags NONE.
0.006s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending PING frame for stream ID 0 with length 8 and flags ACK.
0.215s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Request with timeout of 00:00:00.2000000 has exceeded its deadline.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 47 and flags END_STREAM, END_HEADERS.
0.216s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMB1REBPPE4G:00000001": 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.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending RST_STREAM frame for stream ID 1 with length 4 and flags 0x0.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets - Debug: Connection id "0HMB1REBPPE4G" reset.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Connection id "0HMB1REBPPE4G" is closed. The last processed stream ID was 1.
0.217s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets - Debug: Connection id "0HMB1REBPPE4G" sending FIN because: "The client closed the connection."
0.219s GrpcTestContext - Information: Finishing DeadlineTests.WriteMessageAfterDeadline

Important bit:

0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending HEADERS frame for stream ID 1 with length 47 and flags END_STREAM, END_HEADERS.
0.216s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Resetting response stream with error code 0.
0.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMB1REBPPE4G:00000001": 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.216s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMB1REBPPE4G" sending RST_STREAM frame for stream ID 1 with length 4 and flags 0x0.

The server is sending END_STREAM flag, then sending RST_STREAM frame.

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21417.11
 Commit:    ca60baef37

Author:	JamesNK
Assignees:	-
Labels:	area-System.Net.Http
Milestone:	-

[geoffkizer]

We have logic to handle this exact case here: https://github.com/dotnet/runtime/blob/main/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs#L904

It sounds like you only see this once in a while? Then it's likely we have a race here. It's possible we've introduced this in 6.0, but it's also possible it's always existed and is just rare to see in practice.

If I'm reading the log above correctly, it looks like there is a small request body (12 bytes) and Kestrel has received the entire request body before sending any response. Correct?

We should investigate for 6.0.

[JamesNK]

It sounds like you only see this once in a while?

It's very rare. I've seen it once in .NET 6 (this time).

If I'm reading the log above correctly, it looks like there is a small request body (12 bytes) and Kestrel has received the entire request body before sending any response. Correct?

Yes. A normal POST then response (with trailers).

The only interesting bit is the server sends RST_STREAM after END_STREAM. The END_STREAM is on the trailers frame.

[geoffkizer]

Looking at the code I linked, this seems funny to me:

When this situation happens (RST_STREAM with NO_ERROR after END_STREAM), we check if the request stream is still being sent. If it is, we will set _requestBodyAbandoned = true, then set requestBodyCancellationSource = _requestBodyCancellationSource, and fall out of the lock statement, at which point we check if requestBodyCancellationSource != null and then cancel the request body.

But if the request body has already completed sending, then we don't do this and we will end up calling Cancel(), which will cancel the response, including discarding any buffered data. That seems bad. We should not call Cancel in this case.

[geoffkizer]

Actually, ignore my comment above. The logic I pointed at seems fine. Since we have already received END_STREAM on the response, we must still be sending the request stream; otherwise the stream would be fully completed and we'd just ignore the RST_STREAM (because the stream would no longer be in our active stream table).

(Edit: We should probably Assert that the request body hasn't completed yet, instead of testing for it; but that's not critical.)

The issue seems to be related to PING handling in the RttEstimator. We are throwing an Http2ConnectionException because we think there's something wrong with the PING ACK that Kestrel has sent -- either we aren't expecting it, or it has the wrong PING value.

@JamesNK Any chance you could add the ping value to the log info here?

@antonfirsov Any ideas?

[JamesNK]

Kestrel doesn't log the content of pings. I could add it to a custom Kestrel build and rerun the test, but I've only ever seen this once so it is unlikely to reproduce.

What I will do is enable capturing event source logging for this test. If I see it again then that info will be available.

[geoffkizer]

@antonfirsov -- we probably should have some log events associated with these failure cases so we can more easily determine what's going on here.

[antonfirsov]

Unfortunately, we are not logging the received ping content either (only sends), so it's very hard to reason about the error with the information we can get with our existing logging.

I assume this happened on the CI. @JamesNK any chance you can try running the test in a loop or do some other trick to get a local repro? If we could somehow get a deterministic repro, we could experiment with extended logging and hunt down the bug.

@geoffkizer I think we should improve our logging for RC2 (or even RC1 if still possible), so if we get similar reports we would be able to react easier. Will it be hard to get it through the backports?

[karelz]

Triage: If there is really issue, it is bad -- it may be in client or on server. So far it happened only once. Without repro we cannot take action :(
We need more logs -- we should add logging and try to get it to 6.0 to have at least chance to root cause it next time it happens somewhere (e.g. in customer production).