diff --git a/google/api_core/retry/retry_unary.py b/google/api_core/retry/retry_unary.py index ab1b4030b..5f83335e1 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 _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 + # client: + # response = Library.listBooks(..., requestID=582) # the 582 would be a unique ID computed on the fly + # api_core: + # loggingDebug(f"Calling {requestID}:{attempt} STARTED") + # 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 _LOGGER.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 _LOGGER.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,