Fix ObjectRetrierWraps recursive wrapping

In order to ensure that an object that contains other objects that are
called (e.g. the VolumeManager object on the Cinder client object), the
ObjectRetrierWraps class needs to more agressively wrap non builtin
classes.

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

unit_tests/utilities/test_utilities.py

@@ -113,6 +113,28 @@ class TestObjectRetrierWraps(ut_utils.BaseTestCase):
 
         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 @@ class TestObjectRetrierWraps(ut_utils.BaseTestCase):
 
         # 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):

unit_tests/utilities/test_zaza_utilities_openstack.py

@@ -99,6 +99,9 @@ class TestOpenStackUtils(ut_utils.BaseTestCase):
         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")

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 @@ class ObjectRetrierWraps(object):
             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 @@ class ObjectRetrierWraps(object):
             '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 @@ class ObjectRetrierWraps(object):
         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 @@ class ObjectRetrierWraps(object):
                 # 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 @@ class ObjectRetrierWraps(object):
                     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