From a38d8ccb3e98f45a63430593d49cc55621456ab6 Mon Sep 17 00:00:00 2001 From: Victor Chudnovsky Date: Mon, 2 Dec 2024 14:26:56 -0800 Subject: [PATCH 1/3] wip(not tested): initial approach for testing retries --- google/api_core/retry/retry_unary.py | 47 ++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) diff --git a/google/api_core/retry/retry_unary.py b/google/api_core/retry/retry_unary.py index ab1b4030b..72bd6b008 100644 --- a/google/api_core/retry/retry_unary.py +++ b/google/api_core/retry/retry_unary.py @@ -57,6 +57,7 @@ def check_if_exists(): from __future__ import annotations import functools +import logging import sys import time import inspect @@ -81,6 +82,7 @@ def check_if_exists(): _ASYNC_RETRY_WARNING = "Using the synchronous google.api_core.retry.Retry with asynchronous calls may lead to unexpected results. Please use google.api_core.retry_async.AsyncRetry instead." +_LOGGER = logging.getLogger(__name__) def retry_target( target: Callable[_P, _R], @@ -138,17 +140,62 @@ def retry_target( deadline = time.monotonic() + timeout if timeout is not None else None error_list: list[Exception] = [] + attempt = 0 + rpc_call_id = None for sleep in sleep_generator: try: + if logging.isEnabledFor(logging.DEBUG): + # Is there an easy way of getting the fields of interest at this level in the call? + # + # Otherwise, maybe we compute the request ID in the client and pass it in to the retry logic as a parameter + # client: + # response = Library.listBooks(..., requestID=582) # the 582 would be a unique ID computed on the fly + # api_core: + # loggingDebug(f"Calling {rpc_call_id}:{attempt} for request {requestID}") + # Logging output: + # TIME1: client: Initiating RPC ListBooks (requestID=582, details=....) + # TIME2: google_api_core: Call 582:0 STARTED + # TIME3: google_api_core: Call 582:0 FAILED + # TIME4: google_api_core: Call 582:1 STARTED + # TIME5: google_api_core: Call 582:1 SUCCEEDED + # + # Note that this means we have two uses of IDs: one + # for the high-level call at the client level + # (request_id), and one for each individual RPC retry + # call (call_id); the latter is the concatenation of + # the request_id and the retry-attempt. I think that + # makes sense for logging purposes. + # + # Anyway, the following code does NOT assume the above. + + rpc_call_id = rpc_call_id or hash(target) + logging.debug(f"Call {rpc_call_id}:{attempt} STARTED.", + extra={ + "rpcCallId": rpc_call_id, + "retryAttempt": attempt, + "rpcCallStatus": "START"}) + attempt += 1 result = target() if inspect.isawaitable(result): warnings.warn(_ASYNC_RETRY_WARNING) + if logging.isEnabledFor(logging.DEBUG): + logging.debug(f"Call {rpc_call_id}:{attempt}. SUCCEEDED.", + extra={ + "rpcCallId": rpc_call_id, + "retryAttempt": attempt, + "rpcCallStatus": "SUCCESS"}) return result # pylint: disable=broad-except # This function explicitly must deal with broad exceptions. except Exception as exc: + if logging.isEnabledFor(logging.DEBUG): + logging.debug(f"Call {rpc_call_id}:{attempt}. FAILED.", + extra={ + "rpcCallId": rpc_call_id, + "retryAttempt": attempt, + "rpcCallStatus": "FAILURE"}) # defer to shared logic for handling errors _retry_error_helper( exc, From 36ee7c46971dae6f6538747fd0d336871fc3d027 Mon Sep 17 00:00:00 2001 From: Victor Chudnovsky Date: Mon, 2 Dec 2024 14:44:36 -0800 Subject: [PATCH 2/3] Clarify comment example --- google/api_core/retry/retry_unary.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/google/api_core/retry/retry_unary.py b/google/api_core/retry/retry_unary.py index 72bd6b008..b68fb097c 100644 --- a/google/api_core/retry/retry_unary.py +++ b/google/api_core/retry/retry_unary.py @@ -152,7 +152,7 @@ def retry_target( # client: # response = Library.listBooks(..., requestID=582) # the 582 would be a unique ID computed on the fly # api_core: - # loggingDebug(f"Calling {rpc_call_id}:{attempt} for request {requestID}") + # loggingDebug(f"Calling {requestID}:{attempt} STARTED") # Logging output: # TIME1: client: Initiating RPC ListBooks (requestID=582, details=....) # TIME2: google_api_core: Call 582:0 STARTED From 06835cdf48d4d90f888518ea73725a52f140e927 Mon Sep 17 00:00:00 2001 From: Victor Chudnovsky Date: Mon, 2 Dec 2024 15:51:15 -0800 Subject: [PATCH 3/3] Fix isEnabledFor invocation --- google/api_core/retry/retry_unary.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/google/api_core/retry/retry_unary.py b/google/api_core/retry/retry_unary.py index b68fb097c..5f83335e1 100644 --- a/google/api_core/retry/retry_unary.py +++ b/google/api_core/retry/retry_unary.py @@ -145,7 +145,7 @@ def retry_target( for sleep in sleep_generator: try: - if logging.isEnabledFor(logging.DEBUG): + if _LOGGER.isEnabledFor(logging.DEBUG): # Is there an easy way of getting the fields of interest at this level in the call? # # Otherwise, maybe we compute the request ID in the client and pass it in to the retry logic as a parameter @@ -179,7 +179,7 @@ def retry_target( result = target() if inspect.isawaitable(result): warnings.warn(_ASYNC_RETRY_WARNING) - if logging.isEnabledFor(logging.DEBUG): + if _LOGGER.isEnabledFor(logging.DEBUG): logging.debug(f"Call {rpc_call_id}:{attempt}. SUCCEEDED.", extra={ "rpcCallId": rpc_call_id, @@ -190,7 +190,7 @@ def retry_target( # pylint: disable=broad-except # This function explicitly must deal with broad exceptions. except Exception as exc: - if logging.isEnabledFor(logging.DEBUG): + if _LOGGER.isEnabledFor(logging.DEBUG): logging.debug(f"Call {rpc_call_id}:{attempt}. FAILED.", extra={ "rpcCallId": rpc_call_id,