grpc / grpc/grpc-dotnet

Grpc client has DeadlineExceeded error on waiting for a new picker

Open
#2,297 1 comment 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

### 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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.