diff --git a/requirements.txt b/requirements.txt index 1a3b33cc7..992af69e8 100644 --- a/requirements.txt +++ b/requirements.txt @@ -50,7 +50,10 @@ python-novaclient python-octaviaclient python-swiftclient python-watcherclient -tenacity +# Due to https://github.com/jd/tenacity/pull/479 the strategy for mocking out tenacity +# waits/times/etc no longer works. Pin to 8.4.1 until it is solved. +# Bug in tenacity tracking issue: https://github.com/jd/tenacity/issues/482 +tenacity<8.4.2 paramiko # Documentation requirements diff --git a/unit_tests/utilities/test_utilities.py b/unit_tests/utilities/test_utilities.py index 6af6089b3..2f6dcf6e3 100644 --- a/unit_tests/utilities/test_utilities.py +++ b/unit_tests/utilities/test_utilities.py @@ -113,6 +113,28 @@ def func(self): mock_sleep.assert_not_called() + @mock.patch("time.sleep") + def test_object_wrap_multilevel_with_exception(self, mock_sleep): + + class A: + + def func(self): + raise SomeException() + + class B: + + def __init__(self): + self.a = A() + + b = B() + # retry on a specific exception + wrapped_b = utilities.ObjectRetrierWraps( + b, num_retries=1, retry_exceptions=[SomeException]) + with self.assertRaises(SomeException): + wrapped_b.a.func() + + mock_sleep.assert_called_once_with(5) + @mock.patch("time.sleep") def test_log_called(self, mock_sleep): @@ -130,7 +152,7 @@ def func(self): # there should be two calls; one for the single retry and one for the # failure. - self.assertEqual(mock_log.call_count, 2) + self.assertEqual(mock_log.call_count, 6) @mock.patch("time.sleep") def test_back_off_maximum(self, mock_sleep): diff --git a/unit_tests/utilities/test_zaza_utilities_openstack.py b/unit_tests/utilities/test_zaza_utilities_openstack.py index 222aab2f8..e00f713b1 100644 --- a/unit_tests/utilities/test_zaza_utilities_openstack.py +++ b/unit_tests/utilities/test_zaza_utilities_openstack.py @@ -99,6 +99,9 @@ def setUp(self): self.neutronclient.list_agents.return_value = self.agents self.neutronclient.list_bgp_speaker_on_dragent.return_value = \ self.bgp_speakers + self.patch("zaza.openstack.utilities.ObjectRetrierWraps", + name="_object_retrier_wraps", + new=lambda x, *_, **__: x) def test_create_port(self): self.patch_object(openstack_utils, "get_net_uuid") diff --git a/zaza/openstack/utilities/__init__.py b/zaza/openstack/utilities/__init__.py index 68b0ce8b1..7a8ca104f 100644 --- a/zaza/openstack/utilities/__init__.py +++ b/zaza/openstack/utilities/__init__.py @@ -15,6 +15,7 @@ """Collection of utilities to support zaza tests etc.""" +import logging import time from keystoneauth1.exceptions.connection import ConnectFailure @@ -95,10 +96,19 @@ def __init__(self, obj, num_retries=3, initial_interval=5.0, backoff=1.0, If a list, then it will only retry if the exception is one of the ones in the list. :type retry_exceptions: List[Exception] + :param log: If False, disable logging; if None (the default) or True, + use logging.warn; otherwise use the passed param `log`. + :type param: None | Boolean | Callable """ # Note we use semi-private variable names that shouldn't clash with any # on the actual object. self.__obj = obj + if log in (None, True): + _log = logging.warning + elif log is False: + _log = lambda *_, **__: None # noqa + else: + _log = log self.__kwargs = { 'num_retries': num_retries, 'initial_interval': initial_interval, @@ -106,32 +116,19 @@ def __init__(self, obj, num_retries=3, initial_interval=5.0, backoff=1.0, 'max_interval': max_interval, 'total_wait': total_wait, 'retry_exceptions': retry_exceptions, - 'log': log or (lambda x: None), + 'log': _log, } + _log(f"ObjectRetrierWraps: wrapping {self.__obj}") def __getattr__(self, name): """Get attribute; delegates to wrapped object.""" - # Note the above may generate an attribute error; we expect this and - # will fail with an attribute error. - __log = self.__kwargs['log'] - __log(f"__getattr__(..) called with {name}") - attr = getattr(self.__obj, name) - if callable(attr) or hasattr(attr, "__getattr__"): - __log(f"__getattr__(..): wrapping {attr}") + obj = self.__obj + attr = getattr(obj, name) + if callable(attr): return ObjectRetrierWraps(attr, **self.__kwargs) - __log( f"__getattr__(): {name} is not callable or has __getattr__") - if isinstance(attr, property): - __log(f"__getattr__(): {name} is a property") - __log(f"__getattr__(): {name} on {self.__obj} is a {type(attr)}") - # return attr - __log(f"__getattr__(): wrapping {attr}") + if attr.__class__.__module__ == 'builtins': + return attr return ObjectRetrierWraps(attr, **self.__kwargs) - # TODO(ajkavanagh): Note detecting a property is a bit trickier. we - # can do isinstance(attr, property), but then the act of accessing it - # is what calls it. i.e. it would fail at the getattr(self.__obj, - # name) stage. The solution is to check first, and if it's a property, - # then treat it like the retrier. However, I think this is too - # complex for the first go, and to use manual retries in that instance. def __call__(self, *args, **kwargs): """Call the object; delegates to the wrapped object.""" @@ -147,7 +144,7 @@ def __call__(self, *args, **kwargs): wait_so_far = 0 while True: try: - log(f"Running {self.__name__}({args}, {kwargs})") + log(f"Running {self}({args}, {kwargs})") return obj(*args, **kwargs) except Exception as e: # if retry_exceptions is not None, or the type of the exception @@ -155,7 +152,7 @@ def __call__(self, *args, **kwargs): # immediately. This means that if retry_exceptions is None, # then the method is always retried. if isinstance(e, NEVER_RETRY_EXCEPTIONS): - log("ObjectRetrierWraps: error {} is never caught" + log("ObjectRetrierWraps: error {} is never caught; raising" .format(str(e))) raise if (retry_exceptions is not None and @@ -163,15 +160,16 @@ def __call__(self, *args, **kwargs): raise retry += 1 if retry > num_retries: - log("{}: exceeded number of retries, so erroring out" - .format(str(obj))) + log("ObjectRetrierWraps: {}: exceeded number of retries, " + "so erroring out" .format(str(obj))) raise e - log("{}: call failed: retrying in {} seconds" - .format(str(obj), wait)) + log("ObjectRetrierWraps: {}: call failed: retrying in {} " + "seconds" .format(str(obj), wait)) time.sleep(wait) wait_so_far += wait if wait_so_far >= total_wait: raise e + print('wait: ', wait, ' backoff:', backoff) wait = wait * backoff if wait > max_interval: wait = max_interval