Kestrel occasionally losing zero-size GRPC responses

[pjc50]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

After upgrading from dotnet 6 to dotnet 8, we started observing intermittent failures. Trying dotnet 7 also has the same failures.

Unfortunately this bug is extremely intermittent. We have not been able to create a minimal reproduction case. So far it has only been observed on Mac systems with Java GRPC clients. I've not been able to even trigger it on my desktop, only on CI systems. It is also very timing-sensitive; adding logging to either client or server tends to slow it down just enough for the bug not to manifest. Sorry.

There is only one client, with a thread making requests, a thread making healthcheck calls, and a thread processing a long-lived stream of events structured as an infinite stream of GRPC streaming responses. The failure is roughly four minutes in, and roughly at stream 256 (but not exactly! and it varies).

Once the response is lost the RPC that made it times out 30 seconds later with DEADLINE_EXCEEDED. However, in the meantime, healthcheck calls from the other thread work just fine.

By setting the log level to Trace I was able to obtain this:

Connection id "0HN12DQ56A4EB" received HEADERS frame for stream ID 243 with length 25 and flags END_HEADERS, PRIORITY.
Connection id "0HN12DQ56A4EB" received DATA frame for stream ID 243 with length 108 and flags END_STREAM.
Request starting HTTP/2 POST http://127.0.0.1:9091/StudioLinkProtocol.StudioLinkService/SetDeviceDescription - application/grpc -
All hosts are allowed.
3 candidate(s) found for the request path '/StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Endpoint 'gRPC - /StudioLinkProtocol.StudioLinkService/SetDeviceDescription' with route pattern '/StudioLinkProtocol.StudioLinkService/SetDeviceDescription' is valid for the request path '/StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Endpoint 'gRPC - Unimplemented method for StudioLinkProtocol.StudioLinkService' with route pattern 'StudioLinkProtocol.StudioLinkService/{unimplementedMethod:grpcunimplemented}' is valid for the request path '/StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Endpoint 'gRPC - Unimplemented service' with route pattern '{unimplementedService}/{unimplementedMethod:grpcunimplemented}' is valid for the request path '/StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Request matched endpoint 'gRPC - /StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
The endpoint does not specify the IRequestSizeLimitMetadata.
Executing endpoint 'gRPC - /StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Request deadline timeout of 00:00:29.9999450 started.
Reading message.
Connection id "0HN12DQ56A4EB", Request id "0HN12DQ56A4EB:000000F3": started reading request body.
Connection id "0HN12DQ56A4EB", Request id "0HN12DQ56A4EB:000000F3": done reading request body.
Deserializing 103 byte message to 'StudioLinkProtocol.SetDeviceDescriptionFile'.
Received message.
Sending message.
Serialized 'StudioLinkProtocol.OperationResult' to 0 byte message.
Message sent.
Request deadline stopped.
Executed endpoint 'gRPC - /StudioLinkProtocol.StudioLinkService/SetDeviceDescription'
Request finished HTTP/2 POST http://127.0.0.1:9091/StudioLinkProtocol.StudioLinkService/SetDeviceDescription - 200 - application/grpc 50.2121ms

Expected Behavior

After that I would expect to see

Connection id "0HN12DQ56A4EB" sending HEADERS frame for stream ID 243 with length 4 and flags END_HEADERS.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 243 with length 5 and flags NONE.
Connection id "0HN12DQ56A4EB" sending HEADERS frame for stream ID 243 with length 1 and flags END_STREAM, END_HEADERS.

However there are no such messages, and eventually the client gives up and sends

Connection id "0HN12DQ56A4EB" received RST_STREAM frame for stream ID 243 with length 4 and flags 0x0.

Steps To Reproduce

We do not have a minimal reproduction case for this.

Exceptions (if any)

No response

.NET Version

8.0.101

Anything else?

Grpc.AspNetCore 2.59.0
MacOS 13.6.3 BuildVersion: 22G436 (Ventura)

[pjc50]

It is possible that the preceding request is relevant, which transfers a large amount of data including a couple of window updates, settings, and ping frames.

Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 9510 and flags NONE.
Connection id "0HN12DQ56A4EB" received PING frame for stream ID 0 with length 8 and flags NONE.
Connection id "0HN12DQ56A4EB" sending PING frame for stream ID 0 with length 8 and flags ACK.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 241 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" received SETTINGS frame for stream ID 0 with length 6 and flags NONE.
Connection id "0HN12DQ56A4EB" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
(repeated many times)
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 9510 and flags NONE.
Connection id "0HN12DQ56A4EB" received PING frame for stream ID 0 with length 8 and flags NONE.
Connection id "0HN12DQ56A4EB" sending PING frame for stream ID 0 with length 8 and flags ACK.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 241 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" received WINDOW_UPDATE frame for stream ID 241 with length 4 and flags 0x0.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 16384 and flags NONE.
Connection id "0HN12DQ56A4EB" sending DATA frame for stream ID 241 with length 5732 and flags NONE.
Connection id "0HN12DQ56A4EB" sending HEADERS frame for stream ID 241 with length 1 and flags END_STREAM, END_HEADERS.
Connection id "0HN12DQ56A4EB" received SETTINGS frame for stream ID 0 with length 6 and flags NONE.
Connection id "0HN12DQ56A4EB" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
Connection id "0HN12DQ56A4EB" received PING frame for stream ID 0 with length 8 and flags NONE.
Connection id "0HN12DQ56A4EB" sending PING frame for stream ID 0 with length 8 and flags ACK.

[Tratcher]

Receiving repeated SETTINGS frames is suspicious. Any chance you can get a trace of those? The connection logging middleware would help, or wireshark if it's decrypted.
https://learn.microsoft.com/en-us/aspnet/core/fundamentals/servers/kestrel/connection-middleware?view=aspnetcore-8.0#connection-logging

[pjc50]

I think that's possible, will see on Monday.

[pjc50]

Wireshark output for the last SETTINGS before the failure and its ack:

Frame 30651: 71 bytes on wire (568 bits), 71 bytes captured (568 bits) on interface lo0, id 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 61800, Dst Port: 9091, Seq: 9766, Ack: 2903349, Len: 15
HyperText Transfer Protocol 2
Stream: SETTINGS, Stream ID: 0, Length 6
Length: 6
Type: SETTINGS (4)
Flags: 0x00
0... .... .... .... .... .... .... .... = Reserved: 0x0
.000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0
Settings - Initial Windows size : 1559026
Settings Identifier: Initial Windows size (4)
Initial Window Size: 1559026

Frame 30658: 65 bytes on wire (520 bits), 65 bytes captured (520 bits) on interface lo0, id 0
Null/Loopback
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1

Transmission Control Protocol, Src Port: 9091, Dst Port: 61800, Seq: 2974777, Ack: 9781, Len: 9
HyperText Transfer Protocol 2
Stream: SETTINGS, Stream ID: 0, Length 0
Length: 0
Type: SETTINGS (4)
Flags: 0x01, ACK
0... .... .... .... .... .... .... .... = Reserved: 0x0
.000 0000 0000 0000 0000 0000 0000 0000 = Stream Identifier: 0

Selected packets dotnet issue.zip

[pjc50]

Settings packets only.zip
All 72 SETTINGS packets from that TCP stream.

[Tratcher]

Weird, the client keeps sending settings frames with increasing Initial Windows Size on the same connection. It starts at 1048576 and gets as high as 5093722. That's not illegal, just highly unusual. The server ack's so it should be fine. It should also only affect new requests, not ongoing streams. I wonder if a buffer gets dropped/replaced somewhere?