Grpc client has DeadlineExceeded error on waiting for a new picker
- Dominant language
- C#
- Stars
- 4.5k
- Forks
- 836
- Avg merge
- 6d 3h
- Merged PRs (30d)
- 7
Description
### What version of gRPC and what language are you using?
grpc-dotnet version 2.57.0
### What operating system (Linux, Windows,...) and version?
Linux
### What runtime / compiler are you using (e.g. .NET Core SDK version `dotnet --info`)
net 6.0
### What did you do?
The request is an AsyncUnary call with a deadline of 3 seconds which usually completes in under 300 ms
### What did you expect to see?
Successful grpc call within the expected deadline
### What did you see instead?
We observe a DeadlineExceeded error on the grpc client for about 1% of requests. The issue is not consistently reproducible.
What we have tried, and doesn't work:
1. Increase the timeout to 10 seconds
2. Polly retries for 3 times on such failures
With the trace logs enabled, we could see that the request is stuck on the client side "waiting for a new picker" (line #7)
```
1 16/10/2023 8:44:28.479 PM +1100 Verbose Grpc.Net.Client.Internal.RetryCall Stopping retry worker.
2 16/10/2023 8:44:28.479 PM +1100 Debug Grpc.Net.Client.Internal.RetryCall Call commited. Reason: {CommitReason}
3 16/10/2023 8:44:28.478 PM +1100 Debug Grpc.Net.Client.Internal.GrpcCall Finished gRPC call.
4 16/10/2023 8:44:28.478 PM +1100 Information Grpc.Net.Client.Internal.GrpcCall Call failed with gRPC error status. Status code: '{StatusCode}', Message: '{StatusMessage}'.
5 16/10/2023 8:44:28.478 PM +1100 Debug Grpc.Net.Client.Internal.GrpcCall gRPC call canceled.
6 16/10/2023 8:44:28.478 PM +1100 Warning Grpc.Net.Client.Internal.GrpcCall gRPC call deadline exceeded.
7 16/10/2023 8:44:25.464 PM +1100 Verbose Grpc.Net.Client.Balancer.Internal.ConnectionManager Waiting for a new picker.
8 16/10/2023 8:44:25.464 PM +1100 Debug Grpc.Net.Client.Balancer.Internal.ConnectionManager Picked queued.
9 16/10/2023 8:44:25.464 PM +1100 Verbose Grpc.Net.Client.Balancer.Internal.ConnectionManager Pick started.
10 16/10/2023 8:44:25.464 PM +1100 Verbose Grpc.Net.Client.Internal.GrpcCall Starting deadline timeout. Duration: {DeadlineTimeout}.
11 16/10/2023 8:44:25.464 PM +1100 Debug Grpc.Net.Client.Internal.GrpcCall Starting gRPC call. Method type: '{MethodType}', URI: '{Uri}'.
12 16/10/2023 8:44:25.464 PM +1100 Debug Grpc.Net.Client.Internal.RetryCall Starting attempt {AttemptCount}.
13 16/10/2023 8:44:25.464 PM +1100 Verbose Grpc.Net.Client.Internal.RetryCall Starting retry worker.
```
### Anything else we should know about your project / environment?
Contributor guide
Assessment
This issue has not been assessed yet.