Add tracing unit tests

This patch adds some unit tests for the tracing facility.

Change-Id: Ib18ec5751f74ae2d34c002b191785d51c285e16a

os_brick/tests/base.py

@@ -97,6 +97,13 @@ class TestCase(testtools.TestCase):
         self.addCleanup(patcher.stop)
         return mocked
 
+    def patch(self, path, *args, **kwargs):
+        """Use python mock to mock a path with automatic cleanup."""
+        patcher = mock.patch(path, *args, **kwargs)
+        result = patcher.start()
+        self.addCleanup(patcher.stop)
+        return result
+
     # Useful assertions
     def assertDictMatch(self, d1, d2, approx_equal=False, tolerance=0.001):
         """Assert two dicts are equivalent.

os_brick/tests/test_utils.py

@@ -12,6 +12,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import functools
 import time
 
 import mock
@@ -106,3 +107,127 @@ class TestRetryDecorator(base.TestCase):
 
             self.assertRaises(WrongException, raise_unexpected_error)
             self.assertFalse(mock_sleep.called)
+
+
+class LogTracingTestCase(base.TestCase):
+    """Test out the log tracing."""
+
+    def test_utils_trace_method_default_logger(self):
+        mock_log = self.mock_object(utils, 'LOG')
+
+        @utils.trace
+        def _trace_test_method_custom_logger(*args, **kwargs):
+            return 'OK'
+
+        result = _trace_test_method_custom_logger()
+
+        self.assertEqual('OK', result)
+        self.assertEqual(2, mock_log.debug.call_count)
+
+    def test_utils_trace_method_inner_decorator(self):
+        mock_logging = self.mock_object(utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        def _test_decorator(f):
+            def blah(*args, **kwargs):
+                return f(*args, **kwargs)
+            return blah
+
+        @_test_decorator
+        @utils.trace
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        result = _trace_test_method(self)
+
+        self.assertEqual('OK', result)
+        self.assertEqual(2, mock_log.debug.call_count)
+        # Ensure the correct function name was logged
+        for call in mock_log.debug.call_args_list:
+            self.assertIn('_trace_test_method', str(call))
+            self.assertNotIn('blah', str(call))
+
+    def test_utils_trace_method_outer_decorator(self):
+        mock_logging = self.mock_object(utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        def _test_decorator(f):
+            def blah(*args, **kwargs):
+                return f(*args, **kwargs)
+            return blah
+
+        @utils.trace
+        @_test_decorator
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        result = _trace_test_method(self)
+
+        self.assertEqual('OK', result)
+        self.assertEqual(2, mock_log.debug.call_count)
+        # Ensure the incorrect function name was logged
+        for call in mock_log.debug.call_args_list:
+            self.assertNotIn('_trace_test_method', str(call))
+            self.assertIn('blah', str(call))
+
+    def test_utils_trace_method_outer_decorator_with_functools(self):
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        self.mock_object(utils.logging, 'getLogger', mock_log)
+        mock_log = self.mock_object(utils, 'LOG')
+
+        def _test_decorator(f):
+            @functools.wraps(f)
+            def wraps(*args, **kwargs):
+                return f(*args, **kwargs)
+            return wraps
+
+        @utils.trace
+        @_test_decorator
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        result = _trace_test_method()
+
+        self.assertEqual('OK', result)
+        self.assertEqual(2, mock_log.debug.call_count)
+        # Ensure the incorrect function name was logged
+        for call in mock_log.debug.call_args_list:
+            self.assertIn('_trace_test_method', str(call))
+            self.assertNotIn('wraps', str(call))
+
+    def test_utils_trace_method_with_exception(self):
+        self.LOG = self.mock_object(utils, 'LOG')
+
+        @utils.trace
+        def _trace_test_method(*args, **kwargs):
+            raise exception.VolumeDeviceNotFound('test message')
+
+        self.assertRaises(exception.VolumeDeviceNotFound, _trace_test_method)
+
+        exception_log = self.LOG.debug.call_args_list[1]
+        self.assertIn('exception', str(exception_log))
+        self.assertIn('test message', str(exception_log))
+
+    def test_utils_trace_method_with_time(self):
+        mock_logging = self.mock_object(utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        mock_time = mock.Mock(side_effect=[3.1, 6])
+        self.mock_object(time, 'time', mock_time)
+
+        @utils.trace
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        result = _trace_test_method(self)
+
+        self.assertEqual('OK', result)
+        return_log = mock_log.debug.call_args_list[1]
+        self.assertIn('2900', str(return_log))