grpc / grpc/grpc-dotnet

Error starting gRPC call when using client side load balancing

Open
#2,343 9 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
C#
Stars
4.5k
Forks
836
Avg merge
6d 3h
Merged PRs (30d)
7

Description

Hi, I can break sockets (maybe they break either way) somehow by turning load balancing on. After a short idle client loses the ability to communicate. There is a visible continuation of some communication in Wireshark. Some ICMP redirect packets and probably heartbeat. Any idea for a fix or workaround better than flooding the server with requests?

### What version of gRPC and what language are you using?
Grpc.Net.Client `2.60.0-pre1` (same behavior in older versions)

Not sure what's on the server currently. Probably `2.59.0`. The server is in my reach and could be updated if needed.

### What operating system (Linux, Windows,...) and version?
OS: `win10`

### What runtime / compiler are you using (e.g. .NET Core SDK version `dotnet --info`)
`.NET SDK version: 8.0.100`

### What did you do?
I added load balancing to the GRPC client app. This app was working fine. Adding `RoundRobinConfig` option into:

```csharp
.ConfigureChannel(o =>
{
o.Credentials = credentials;
...
o.ServiceConfig = new ServiceConfig
{
LoadBalancingConfigs = { new RoundRobinConfig() },
};
});
```

makes the app unusable after a while. This happens only when the app is idle for a minute. Increasing the request rate with the request period configured to 3 seconds (60 default) workaround this issue.

### What did you expect to see?
No error.

### What did you see instead?

The app works fine for a few minutes and then it throws [exception](https://github.com/dotnet/runtime/blob/v8.0.1/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs#L457):

```plaintext
Error starting gRPC call. HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.
```

Logs in the moment when the app breaks
// service working
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: ActiveStream"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: ActiveStream"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: ActiveStream"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: ActiveStream"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: ActiveStream"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
// service not working
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Sending message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Idle. Detail: 'Disconnected.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Connecting."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Connecting. Detail: 'Connection requested.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport","message":"Subchannel id '2-1' connected to socket REDACTED_URL:443."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Ready. Detail: 'Successfully connected to socket.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Ready."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: InitialSocket"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: InitialSocket"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Error starting gRPC call."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Error starting gRPC call."}
{"level":"INFO","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.'.","exception":"System.Net.Http.HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.\r\n at System.Net.Http.HttpConnectionPool.ThrowGetVersionException(HttpRequestMessage request, Int32 desiredVersion, Exception inner)\r\n at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\r\n at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\r\n at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)\r\n at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)\r\n at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"INFO","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.'.","exception":"System.Net.Http.HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.\r\n at System.Net.Http.HttpConnectionPool.ThrowGetVersionException(HttpRequestMessage request, Int32 desiredVersion, Exception inner)\r\n at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\r\n at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)\r\n at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)\r\n at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)\r\n at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"gRPC call canceled."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Finished gRPC call."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"gRPC call canceled."}
{"level":"INFO","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Error status code 'Internal' with detail 'Error starting gRPC call. HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.' raised."}
{"level":"INFO","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Error status code 'Internal' with detail 'Error starting gRPC call. HttpRequestException: Requesting HTTP version 2.0 with version policy RequestVersionOrHigher while unable to establish HTTP/2 connection.' raised."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Idle. Detail: 'Disconnected.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Connecting."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Connecting. Detail: 'Connection requested.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport","message":"Subchannel id '2-1' connected to socket REDACTED_URL:443."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Ready. Detail: 'Successfully connected to socket.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Ready."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport","message":"Subchannel id '2-1' socket REDACTED_URL:443 is in a bad state and can't be used."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport","message":"Subchannel id '2-1' socket REDACTED_URL:443 is being closed because it can't be used. Socket lifetime of 00:00:35.0610584. The socket either can't receive data or it has received unexpected data."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Idle. Detail: 'Lost connection to socket.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Connecting."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Connecting. Detail: 'Connection requested.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport","message":"Subchannel id '2-1' connected to socket REDACTED_URL:443."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Subchannel","message":"Subchannel id '2-1' state changed to Ready. Detail: 'Successfully connected to socket.'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel state updated to Ready."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Channel picker updated."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.AspNetCore.Server.ServerCallHandler","message":"Reading message."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Starting gRPC call. Method type: 'Unary', URI: 'https://our-cluster-backend.whatever/dataservice/GetData'."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: InitialSocket"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Balancer.Internal.ConnectionManager","message":"Successfully picked subchannel id '2-1' with address REDACTED_URL:443. Transport status: InitialSocket"}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Error starting gRPC call."}
{"level":"DEBUG","logger":"Grpc.Net.Client.Internal.GrpcCall","message":"Error starting gRPC call."}

### Anything else we should know about your project / environment?

This happens only when requests are sent to one of the Kubernetes(Openshift) clusters. I have not seen this error on the local network yet. It is probably a combination of latency, network errors, and idle time.

Seen in the app that periodically fetches some data.

#### Server side cfg

The issue was only seen when running against the OpenShift cluster backend. There is probably HAProxy on the way to the gRPC server pod.

EDIT: The `ROUTER_DEFAULT_CLIENT_TIMEOUT` or `ROUTER_DEFAULT_SERVER_TIMEOUT` seems to be cause of this issue.

```json
{
"Kestrel": {
"Endpoints": {
"Http": {
"Protocols": "Http2",
"Url": "http://+:50050"
},
"Https": {
"Certificate": {
"Path": "/https/tls-cert.pfx"
},
"Protocols": "Http2",
"Url": "https://+:50051"
}
}
}
}
```

#### Client side

~~Any Windows OS where our app was tested. I am using Win10 while debugging this issue.~~ Replicated with C# greeter example app on the linux base OS too.

Contributor guide

Open the contributing guide

Research direction

Start with the reported path through Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler, ConnectionManager, Subchannel, and SocketConnectivitySubchannelTransport, then compare it with the linked .NET HttpConnectionPool code. Reproduce the idle-period failure using Grpc.Net.Client 2.60.0-pre1, RoundRobinConfig, Windows 10, and .NET SDK 8.0.100; done means the client can resume HTTP/2 calls after idling without the reported exception.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp, grpc
Domain
networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.