NotificationsYou must be signed in to change notification settings
Fork95
Star144

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to ourterms of service andprivacy statement. We’ll occasionally send you account related emails.

Already on GitHub?Sign in to your account

Jump to bottom

Merged

parthea merged 5 commits intomainfromfix-incorrect-rpc-timeout

Jan 16, 2025

Merged

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

parthea merged 5 commits intomainfromfix-incorrect-rpc-timeout

Jan 16, 2025

Conversation

Copy link

Collaborator

parthea commentedJan 12, 2025•
edited
Loading

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

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

Lines 194 to 200 inb1fae31

	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 valuesdeadline andtimeout which behave in a different manner. Thedeadline argument ofdefault_retry is an overall invocation timeout, whiletimeout is therpc timeout. The client will send requests (respecting the configured backoff) during the specified timeout allowed. Once the timeout is up, therpc timeout ends up being 0, but the requests keep going out because thedeadline hasn't expired.

A simple fix is to have a reasonableness check on therpc timeout to avoid sending requests withrpc timeout of 0.

A longer term fix is being considered where we have separate timeouts foroverall timeout andrpc timeout. Currently, we just have a singletimeout defined inpubsub_grpc_service_config.json does not provide flexibility to configure both anoverall timeout orrpc timeout.

Initial testing shows that this shouldfix#654

Output of test log. Previously I would seegRPC 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.0rootdir: /usr/local/google/home/partheniou/git/gapic-generator-pythonplugins: localserver-0.8.1, cov-5.0.0, asyncio-0.23.5asyncio: mode=strictcollected 1 itemtests/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

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

95cde20

…pires

product-auto-labelbot added the size: sPull 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 froma team ascode owners

January 14, 2025 02:03

blunderbuss-gcfbot assignedohmayr

Jan 14, 2025

parthea assignedvchudnov-g

Jan 14, 2025

parthea added3 commits

January 16, 2025 20:07

address offline feedback

5b9a2e8

formatting

30ce320

update comment

03b27f0

ohmayr reviewed

Jan 16, 2025

View reviewed changes

google/api_core/timeout.py


		remaining_timeout=self._timeout
		ifremaining_timeoutisnotNone:
		ifself._timeoutisnotNone:

Copy link

Contributor

ohmayrJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

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

Copy link

CollaboratorAuthor

partheaJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

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.

ohmayr approved these changes

Jan 16, 2025

View reviewed changes

vchudnov-g reviewed

Jan 16, 2025

View reviewed changes

google/api_core/timeout.py

Comment on lines +120 to +121

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

Copy link

Contributor

vchudnov-gJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

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

Copy link

CollaboratorAuthor

partheaJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

The deadline enters viawrap_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 inb1fae31

defwrap_method(

google/api_core/timeout.py

Comment on lines +125 to +126

		ifremaining_timeout<1:
		remaining_timeout=self._timeout

Copy link

Contributor

vchudnov-gJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

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 toself._timeout instead of, say, 5.

Copy link

CollaboratorAuthor

partheaJan 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others.Learn more.

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.