diff --git a/os_brick/tests/base.py b/os_brick/tests/base.py index b02a2015f..d24ec7033 100644 --- a/os_brick/tests/base.py +++ b/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. diff --git a/os_brick/tests/test_utils.py b/os_brick/tests/test_utils.py index fecc9cc47..166a22362 100644 --- a/os_brick/tests/test_utils.py +++ b/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))