grpc / grpc/grpc

RPC timeout set via service config is off by ~1s

Open
#34,547 18 comments 0 reactions 4 assignees Claimed by @aadikapur View on GitHub
disposition/help wanted kind/bug lang/Python priority/P2
Dominant language
C++
Stars
45.3k
Forks
11.4k
Avg merge
2d 12h
Merged PRs (30d)
47

Description

### What version of gRPC and what language are you using?
grpcio==1.54.2

### What operating system (Linux, Windows,...) and version?
OSX Ventura 13.6

### What runtime / compiler are you using (e.g. python version or version of gcc)
Python 3.11.4

### What did you do?
tl;dr I find that setting an RPC via service config needs ~1 full second higher than the client/server will actually take. Happens across a variety of timings, and ONLY applies to the service config and NOT to setting a timeout at the actual RPC call.

Started a simple gRPC server that sleeps for a small time. Then perform a client call with a `timeout` in the service config for 1 second more than the configured sleep, which fails unexpectedly and in a shorter time than the timeout.

The below example should sleep for .2s, should timeout in 1.2s, but the client returns a DEADLINE_EXCEEDED in less than .2s.

#### Server
```python
from concurrent import futures
import time

import grpc
import greeting_pb2
import greeting_pb2_grpc

class Greeter(greeting_pb2_grpc.GreeterServicer):
def greet(self, request, context):
print("Got request " + str(request))
time.sleep(0.2)
return greeting_pb2.ServerOutput(message="{0} {1}!".format(request.greeting, request.name))

def server():
server = grpc.server(futures.ThreadPoolExecutor(max_workers=2))
greeting_pb2_grpc.add_GreeterServicer_to_server(Greeter(), server)
server.add_insecure_port("[::]:50051")
print("gRPC starting")
server.start()
server.wait_for_termination()

server()
```

#### Client
```python
import time
import grpc
import greeting_pb2
import greeting_pb2_grpc

options = [("grpc.service_config", '{"methodConfig": [{"timeout": "1.2s", "name": [{}]}] }')]

channel = grpc.insecure_channel(
target="dns:///localhost:50051",
options=options,
)

stub = greeting_pb2_grpc.GreeterStub(channel)
start = time.perf_counter()
try:
response = stub.greet(greeting_pb2.ClientInput(name="Me", greeting="Yo"))
except Exception as e:
response = e
print(response, " in ", time.perf_counter() - start)
```

### What did you expect to see?
I expect this RPC to succeed.

### What did you see instead?
This RPC fails in a shorter time than the timeout. For the example above it fails at 0.14ish seconds rather than 1.2ish seconds.

```
<_InactiveRpcError of RPC that terminated with:
status = StatusCode.DEADLINE_EXCEEDED
details = "Deadline Exceeded"
debug_error_string = "UNKNOWN:Deadline Exceeded {grpc_status:4, created_time:"2023-09-29T11:00:52.966757-05:00"}"
> in 0.14907191699603572
```

This will then succeed if I change the timeout to 1.3 seconds, and this pattern is repeatable for higher values. e.g. a server that sleeps for 3 seconds needs a `serviceConfig` timeout of ~4.1 seconds to succeed.

However, using the timeout in the RPC call instead seems fine. It doesn't seem to have the same off-by-one issue that I find in the service config.

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