xDS interop: custom before_sleep_log only logging primitive returns (#30757)

When we use retryers with `log_level=logging.INFO`, tenacity logs the result value (or an exception) after each unsuccessful retry attempt.
We often retry methods that return objects, resulting in unreadable log messages:

```
I0820 03:16:29.027635 140613877811008 before_sleep.py:45] Retrying framework.xds_k8s_testcase.IsolatedXdsKubernetesTestCase.cleanup in 10.0 seconds as it raised RetryError: RetryError[Attempts: 21, Value: {'api_version': 'v1',
 'kind': 'Namespace',
 'metadata': {'annotations': None,
              'cluster_name': None,
              'creation_timestamp': datetime.datetime(2022, 8, 20, 2, 55, 32, tzinfo=tzlocal()),
              'deletion_grace_period_seconds': None,
              'deletion_timestamp': datetime.datetime(2022, 8, 20, 3, 6, 27, tzinfo=tzlocal()),
              'finalizers': None,
              'generate_name': None,
              'generation': None,
              'labels': {'kubernetes.io/metadata.name': 'psm-interop-server-20220820-0253-yrmam',
                         'name': 'psm-interop-server-20220820-0253-yrmam',
                         'owner': 'xds-k8s-interop-test'},
              'managed_fields': [{'api_version': 'v1',
                                  'fields_type': 'FieldsV1',
                                  'fields_v1': {'f:metadata': {'f:labels': {'.': {},
                                                                            'f:kubernetes.io/metadata.name': {},
... (82 more lines)
```

This PR introduces custom `before_sleep` logger, that only logs the value if it's a primitive: `int, str, bool`.
Otherwise, it logs the type, example:

```
k8s_base_runner.py:311] Waiting for pod psm-grpc-client-5d5648478f-7vsf7 to start
retryers.py:192] Retrying framework.infrastructure.k8s.KubernetesNamespace.get_pod in 1.0 seconds as it returned type <class 'kubernetes.client.models.v1_pod.V1Pod'>.
retryers.py:192] Retrying framework.infrastructure.k8s.KubernetesNamespace.get_pod in 1.0 seconds as it returned type <class 'kubernetes.client.models.v1_pod.V1Pod'>.
```

Note that this only changes the behavior of the unsuccessful retries, and doesn't affect the new feature that prints formatted k8s status field on if the *final* retry attempt failed.
pull/30768/head
Sergii Tkachenko 3 years ago committed by GitHub
parent 1e42fbeb52
commit 1837dae106
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
  1. 39
      tools/run_tests/xds_k8s_test_driver/framework/helpers/retryers.py

@ -26,6 +26,7 @@ from typing import Any, Callable, List, Optional, Tuple, Type
import tenacity import tenacity
from tenacity import _utils as tenacity_utils from tenacity import _utils as tenacity_utils
from tenacity import compat as tenacity_compat
from tenacity import stop from tenacity import stop
from tenacity import wait from tenacity import wait
from tenacity.retry import retry_base from tenacity.retry import retry_base
@ -79,7 +80,7 @@ def exponential_retryer_with_timeout(
wait=wait.wait_exponential(min=wait_min.total_seconds(), wait=wait.wait_exponential(min=wait_min.total_seconds(),
max=wait_max.total_seconds()), max=wait_max.total_seconds()),
stop=stop.stop_after_delay(timeout.total_seconds()), stop=stop.stop_after_delay(timeout.total_seconds()),
before_sleep=tenacity.before_sleep_log(logger, log_level), before_sleep=_before_sleep_log(logger, log_level),
retry_error_callback=retry_error_callback) retry_error_callback=retry_error_callback)
@ -111,7 +112,7 @@ def constant_retryer(*,
return Retrying(retry=tenacity.retry_any(*retry_conditions), return Retrying(retry=tenacity.retry_any(*retry_conditions),
wait=wait.wait_fixed(wait_fixed.total_seconds()), wait=wait.wait_fixed(wait_fixed.total_seconds()),
stop=stop.stop_any(*stops), stop=stop.stop_any(*stops),
before_sleep=tenacity.before_sleep_log(logger, log_level), before_sleep=_before_sleep_log(logger, log_level),
retry_error_callback=retry_error_callback) retry_error_callback=retry_error_callback)
@ -159,6 +160,40 @@ def _safe_check_result(check_result: CheckResultFn,
return _check_result_wrapped return _check_result_wrapped
def _before_sleep_log(logger, log_level, exc_info=False):
"""Same as tenacity.before_sleep_log, but only logs primitive return values.
This is not useful when the return value is a dump of a large object.
"""
def log_it(retry_state):
if retry_state.outcome.failed:
ex = retry_state.outcome.exception()
verb, value = 'raised', '%s: %s' % (type(ex).__name__, ex)
if exc_info:
local_exc_info = tenacity_compat.get_exc_info_from_future(
retry_state.outcome)
else:
local_exc_info = False
else:
local_exc_info = False # exc_info does not apply when no exception
result = retry_state.outcome.result()
if isinstance(result, (int, bool, str)):
verb, value = 'returned', result
else:
verb, value = 'returned type', type(result)
logger.log(log_level,
"Retrying %s in %s seconds as it %s %s.",
tenacity_utils.get_callback_name(retry_state.fn),
getattr(retry_state.next_action, 'sleep'),
verb,
value,
exc_info=local_exc_info)
return log_it
class RetryError(tenacity.RetryError): class RetryError(tenacity.RetryError):
def __init__(self, def __init__(self,

Loading…
Cancel
Save