fix: resolve the issue where rpc timeout of 0 is used when timeout expires #776

parthea · 2025-01-12T14:19:33Z

In PR #462, the deadline argument of google.api_core.retry.Retry was refactored and marked as deprecated. Although the comment below mentions that the deadline argument would override the timeout, this is not the behavior that we see when the deadline argument of default_retry is set as part of the wrapped method as is the case in this line, similar to the bug report in #654.

python-api-core/google/api_core/retry/retry_unary.py

Lines 194 to 200 in b1fae31

    
               Unfortunately, in the past this class (and the api-core library as a whole) has not 
        
               been properly distinguishing the concepts of "timeout" and "deadline", and the 
        
               ``deadline`` parameter has meant ``timeout``. That is why 
        
               ``deadline`` has been deprecated and ``timeout`` should be used instead. If the 
        
               ``deadline`` parameter is set, it will override the ``timeout`` parameter. 
        
               In other words, ``retry.deadline`` should be treated as just a deprecated alias for 
        
               ``retry.timeout``.

We actually have 2 separate values deadline and timeout which behave in a different manner. The deadline argument of default_retry is an overall invocation timeout, while timeout is the rpc timeout. The client will send requests (respecting the configured backoff) during the specified timeout allowed. Once the timeout is up, the rpc timeout ends up being 0, but the requests keep going out because the deadline hasn't expired.

A simple fix is to have a reasonableness check on the rpc timeout to avoid sending requests with rpc timeout of 0.

A longer term fix is being considered where we have separate timeouts for overall timeout and rpc timeout. Currently, we just have a single timeout defined in pubsub_grpc_service_config.json does not provide flexibility to configure both an overall timeout or rpc timeout.

Initial testing shows that this should fix #654

Output of test log. Previously I would see gRPC timeout:0 seconds as reported in #654

Running pytest with args: ['-p', 'vscode_pytest', '--rootdir=/usr/local/google/home/partheniou/git/gapic-generator-python', '--capture=no', '/usr/local/google/home/partheniou/git/gapic-generator-python/tests/system/test_retry.py::test_lro[grpc]']
============================= test session starts ==============================
platform linux -- Python 3.9.16, pytest-7.4.0, pluggy-1.5.0
rootdir: /usr/local/google/home/partheniou/git/gapic-generator-python
plugins: localserver-0.8.1, cov-5.0.0, asyncio-0.23.5
asyncio: mode=strict
collected 1 item

tests/system/test_retry.py 
{"timestamp": "2025-01-12 13:11:39,035", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.client", "message": "Created client `google.showcase_v1beta1.EchoClient`.", "serviceName": "google.showcase.v1beta1.Echo", "credentialsType": "builtins.NoneType", "universeDomain": ""}
gRPC timeout: 60.0 seconds
{"timestamp": "2025-01-12 13:11:39,042", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:12:39,048", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 0.0s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:12:39,084", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:13:39,088", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 0.0s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:13:39,114", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:14:39,118", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 11.0s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:14:50,085", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:15:50,089", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 20.4s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:16:10,474", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:17:10,477", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 27.2s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:17:37,729", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:18:37,733", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 5.6s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:18:43,345", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:19:43,349", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 1.5s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:19:44,817", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}
{"timestamp": "2025-01-12 13:20:44,821", "severity": "DEBUG", "name": "google.api_core.retry", "message": "Retrying due to 504 Deadline Exceeded, sleeping 39.8s ..."}
gRPC timeout: 60 seconds
{"timestamp": "2025-01-12 13:21:24,597", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc", "message": "Sending request for /google.showcase.v1beta1.Echo/Block", "rpcName": "/google.showcase.v1beta1.Echo/Block", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"responseDelay\": \"60s\"\n}", "requestMethod": "grpc", "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}, "metadata": {"x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.0 gapic/0.0.0"}}

Fixes #654
Fixes b/387530669

…pires

ohmayr · 2025-01-16T20:48:10Z

google/api_core/timeout.py

@@ -102,8 +102,7 @@ def __call__(self, func):
        def func_with_timeout(*args, **kwargs):
            """Wrapped function that adds timeout."""

-            remaining_timeout = self._timeout
-            if remaining_timeout is not None:
+            if self._timeout is not None:


I think this self._timeout is meant to be treated as the total timeout and not a timeout for each retry.

There is some clean up that needs to happen as part of a longer term fix (Googlers see b/388247478) but for now I'd recommend to keep the definitions unchanged.

vchudnov-g · 2025-01-16T22:22:58Z

google/api_core/timeout.py

+                # it is still possible for the `deadline` argument in
+                # `google.api_core.retry.Retry` to be larger than the `timeout`.


This does not explain how the deadline value enters here since there's no deadline in this function. It's confusing. Please clarify.

The deadline enters via wrap_method linked below, and is used in the calculation for an overall timeout. The fact that there is a separate deadline that can be confirmed is unexpected behavior which will be addressed in a follow up PR.

python-api-core/google/api_core/gapic_v1/method.py

Line 134 in b1fae31

def wrap_method(

vchudnov-g · 2025-01-16T22:23:00Z

google/api_core/timeout.py

+                if remaining_timeout < 1:
+                    remaining_timeout = self._timeout


I don't understand this. This seems to be saying that if the next server-RPC timeout is ~0, we should reset it to be the GAPIC-surface level timeout, which seems wrong. I assume we're checking the GAPIC-surface level timeout elsewhere? Where?

If we are indeed checking it elsewhere, clarify that here, and explain how the scenario leading up to this situation means it should be reset to self._timeout instead of, say, 5.

You're right @vchudnov-g , there is existing incorrect behavior and this simply avoids the specific failure of sending requests with an rpc timeout of 0, which fail immediately. More clarity is needed to document the current incorrect behavior and the workaround in this PR, as well as the recommended long term fix. As per offline discussion, we'll merge this as is and follow up with another PR to update the comments to provide more clarity.

fix: resolve the issue where rpc timeout of 0 is used when timeout ex…

95cde20

…pires

product-auto-label bot added the size: s Pull request size is small. label Jan 12, 2025

parthea changed the title ~~[WIP] fix: resolve the issue where rpc timeout of 0 is used when timeout expires~~ fix: resolve the issue where rpc timeout of 0 is used when timeout expires Jan 14, 2025

Merge branch 'main' into fix-incorrect-rpc-timeout

b7ea26e

parthea marked this pull request as ready for review January 14, 2025 02:03

parthea requested review from a team as code owners January 14, 2025 02:03

blunderbuss-gcf bot assigned ohmayr Jan 14, 2025

parthea assigned vchudnov-g Jan 14, 2025

parthea added 3 commits January 16, 2025 20:07

address offline feedback

5b9a2e8

formatting

30ce320

update comment

03b27f0

ohmayr reviewed Jan 16, 2025

View reviewed changes

ohmayr approved these changes Jan 16, 2025

View reviewed changes

vchudnov-g reviewed Jan 16, 2025

View reviewed changes

parthea merged commit a5604a5 into main Jan 16, 2025
42 checks passed

parthea deleted the fix-incorrect-rpc-timeout branch January 16, 2025 23:50

release-please bot mentioned this pull request Jan 16, 2025

chore(main): release 2.24.1 #778

Merged

This was referenced Jan 17, 2025

chore(main): Release candidate v2.24.1rc0 #779

Closed

chore: Release candidate v2.24.1rc1 #782

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: resolve the issue where rpc timeout of 0 is used when timeout expires #776

fix: resolve the issue where rpc timeout of 0 is used when timeout expires #776

parthea commented Jan 12, 2025 •

edited

Loading

ohmayr Jan 16, 2025

parthea Jan 16, 2025

vchudnov-g Jan 16, 2025

parthea Jan 16, 2025

vchudnov-g Jan 16, 2025

parthea Jan 16, 2025

	Unfortunately, in the past this class (and the api-core library as a whole) has not
	been properly distinguishing the concepts of "timeout" and "deadline", and the
	``deadline`` parameter has meant ``timeout``. That is why
	``deadline`` has been deprecated and ``timeout`` should be used instead. If the
	``deadline`` parameter is set, it will override the ``timeout`` parameter.
	In other words, ``retry.deadline`` should be treated as just a deprecated alias for
	``retry.timeout``.

		# it is still possible for the `deadline` argument in
		# `google.api_core.retry.Retry` to be larger than the `timeout`.

fix: resolve the issue where rpc timeout of 0 is used when timeout expires #776

fix: resolve the issue where rpc timeout of 0 is used when timeout expires #776

Conversation

parthea commented Jan 12, 2025 • edited Loading

ohmayr Jan 16, 2025

Choose a reason for hiding this comment

parthea Jan 16, 2025

Choose a reason for hiding this comment

vchudnov-g Jan 16, 2025

Choose a reason for hiding this comment

parthea Jan 16, 2025

Choose a reason for hiding this comment

vchudnov-g Jan 16, 2025

Choose a reason for hiding this comment

parthea Jan 16, 2025

Choose a reason for hiding this comment

parthea commented Jan 12, 2025 •

edited

Loading