Move trace methods from utils to volume_utils

This continues moving code only used by volume
drivers or the volume manager to volume_utils.

The result of this is that fewer drivers import
cinder.utils (and everything it imports), and less code
is loaded by non-volume cinder code (api service,
cinder-manage, etc.)

Closes-Bug: #1912278
Change-Id: I5aa82cf0de4c70f53ddc998bf25e64f4ad8f5774

cinder/tests/fake_driver.py

@@ -18,7 +18,6 @@ from cinder import exception
 from cinder import objects
 from cinder.objects import fields
 from cinder.tests.unit.brick import fake_lvm
-from cinder import utils
 from cinder.volume import driver
 from cinder.volume.drivers import lvm
 from cinder.volume import volume_utils
@@ -38,12 +37,12 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
                                         None, 'default',
                                         self.fake_execute)
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def check_for_setup_error(self):
         """No setup necessary in fake mode."""
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_volume(self, volume):
         """Creates a volume."""
         super(FakeLoggingVolumeDriver, self).create_volume(volume)
@@ -60,51 +59,51 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
         if model_update:
             return model_update
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def delete_volume(self, volume):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_snapshot(self, snapshot):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def delete_snapshot(self, snapshot):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def ensure_export(self, context, volume):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_export(self, context, volume, connector):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def remove_export(self, context, volume):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_export_snapshot(self, context, snapshot):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def remove_export_snapshot(self, context, snapshot):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def terminate_connection_snapshot(self, snapshot, connector):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_cloned_volume(self, volume, src_vol):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_volume_from_snapshot(self, volume, snapshot):
         pass
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def initialize_connection(self, volume, connector):
         # NOTE(thangp): There are several places in the core cinder code where
         # the volume passed through is a dict and not an oslo_versionedobject.
@@ -126,18 +125,18 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
         return {'driver_volume_type': 'iscsi',
                 'data': {'access_mode': access_mode}}
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def initialize_connection_snapshot(self, snapshot, connector):
         return {
             'driver_volume_type': 'iscsi',
         }
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def terminate_connection(self, volume, connector, **kwargs):
         pass
 
     # Replication Group (Tiramisu)
-    @utils.trace_method
+    @volume_utils.trace_method
     def enable_replication(self, context, group, volumes):
         """Enables replication for a group and volumes in the group."""
         model_update = {
@@ -152,7 +151,7 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
         return model_update, volume_model_updates
 
     # Replication Group (Tiramisu)
-    @utils.trace_method
+    @volume_utils.trace_method
     def disable_replication(self, context, group, volumes):
         """Disables replication for a group and volumes in the group."""
         model_update = {
@@ -167,7 +166,7 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
         return model_update, volume_model_updates
 
     # Replication Group (Tiramisu)
-    @utils.trace_method
+    @volume_utils.trace_method
     def failover_replication(self, context, group, volumes,
                              secondary_backend_id=None):
         """Fails over replication for a group and volumes in the group."""
@@ -183,7 +182,7 @@ class FakeLoggingVolumeDriver(lvm.LVMVolumeDriver):
         return model_update, volume_model_updates
 
     # Replication Group (Tiramisu)
-    @utils.trace_method
+    @volume_utils.trace_method
     def create_group(self, context, group):
         """Creates a group."""
         model_update = super(FakeLoggingVolumeDriver, self).create_group(
@@ -424,6 +423,6 @@ class FakeGateDriver(lvm.LVMVolumeDriver):
 class FakeHAReplicatedLoggingVolumeDriver(FakeLoggingVolumeDriver):
     SUPPORTS_ACTIVE_ACTIVE = True
 
-    @utils.trace_method
+    @volume_utils.trace_method
     def failover_completed(self, context, active_backend_id=None):
         pass

cinder/tests/unit/test_utils.py

@@ -13,11 +13,9 @@
 #    under the License.
 
 import datetime
-import functools
 import json
 import os
 import sys
-import time
 from unittest import mock
 
 import ddt
@@ -1060,328 +1058,7 @@ class TestRetryDecorator(test.TestCase):
 
 
 @ddt.ddt
-class LogTracingTestCase(test.TestCase):
-
-    def test_utils_setup_tracing(self):
-        self.mock_object(utils, 'LOG')
-
-        utils.setup_tracing(None)
-        self.assertFalse(utils.TRACE_API)
-        self.assertFalse(utils.TRACE_METHOD)
-        self.assertEqual(0, utils.LOG.warning.call_count)
-
-        utils.setup_tracing(['method'])
-        self.assertFalse(utils.TRACE_API)
-        self.assertTrue(utils.TRACE_METHOD)
-        self.assertEqual(0, utils.LOG.warning.call_count)
-
-        utils.setup_tracing(['method', 'api'])
-        self.assertTrue(utils.TRACE_API)
-        self.assertTrue(utils.TRACE_METHOD)
-        self.assertEqual(0, utils.LOG.warning.call_count)
-
-    def test_utils_setup_tracing_invalid_key(self):
-        self.mock_object(utils, 'LOG')
-
-        utils.setup_tracing(['fake'])
-
-        self.assertFalse(utils.TRACE_API)
-        self.assertFalse(utils.TRACE_METHOD)
-        self.assertEqual(1, utils.LOG.warning.call_count)
-
-    def test_utils_setup_tracing_valid_and_invalid_key(self):
-        self.mock_object(utils, 'LOG')
-
-        utils.setup_tracing(['method', 'fake'])
-
-        self.assertFalse(utils.TRACE_API)
-        self.assertTrue(utils.TRACE_METHOD)
-        self.assertEqual(1, utils.LOG.warning.call_count)
-
-    def test_trace_no_tracing(self):
-        self.mock_object(utils, 'LOG')
-
-        @utils.trace_method
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(None)
-
-        result = _trace_test_method()
-
-        self.assertEqual('OK', result)
-        self.assertEqual(0, utils.LOG.debug.call_count)
-
-    def test_utils_trace_method(self):
-        self.mock_object(utils, 'LOG')
-
-        @utils.trace_method
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['method'])
-
-        result = _trace_test_method()
-        self.assertEqual('OK', result)
-        self.assertEqual(2, utils.LOG.debug.call_count)
-
-    def test_utils_trace_api(self):
-        self.mock_object(utils, 'LOG')
-
-        @utils.trace_api
-        def _trace_test_api(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['api'])
-
-        result = _trace_test_api()
-        self.assertEqual('OK', result)
-        self.assertEqual(2, utils.LOG.debug.call_count)
-
-    def test_utils_trace_api_filtered(self):
-        self.mock_object(utils, 'LOG')
-
-        def filter_func(all_args):
-            return False
-
-        @utils.trace_api(filter_function=filter_func)
-        def _trace_test_api(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['api'])
-
-        result = _trace_test_api()
-        self.assertEqual('OK', result)
-        self.assertEqual(0, utils.LOG.debug.call_count)
-
-    def test_utils_trace_filtered(self):
-        self.mock_object(utils, 'LOG')
-
-        def filter_func(all_args):
-            return False
-
-        @utils.trace(filter_function=filter_func)
-        def _trace_test(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['api'])
-
-        result = _trace_test()
-        self.assertEqual('OK', result)
-        self.assertEqual(0, utils.LOG.debug.call_count)
-
-    def test_utils_trace_method_default_logger(self):
-        mock_log = self.mock_object(utils, 'LOG')
-
-        @utils.trace_method
-        def _trace_test_method_custom_logger(*args, **kwargs):
-            return 'OK'
-        utils.setup_tracing(['method'])
-
-        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_method
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['method'])
-
-        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_method
-        @_test_decorator
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['method'])
-
-        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_method
-        @_test_decorator
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['method'])
-
-        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_method
-        def _trace_test_method(*args, **kwargs):
-            raise exception.APITimeout('test message')
-
-        utils.setup_tracing(['method'])
-
-        self.assertRaises(exception.APITimeout, _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_method
-        def _trace_test_method(*args, **kwargs):
-            return 'OK'
-
-        utils.setup_tracing(['method'])
-
-        result = _trace_test_method(self)
-
-        self.assertEqual('OK', result)
-        return_log = mock_log.debug.call_args_list[1]
-        self.assertIn('2900', str(return_log))
-
-    def test_utils_trace_wrapper_class(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)
-
-        utils.setup_tracing(['method'])
-
-        class MyClass(object, metaclass=utils.TraceWrapperMetaclass):
-            def trace_test_method(self):
-                return 'OK'
-
-        test_class = MyClass()
-        result = test_class.trace_test_method()
-
-        self.assertEqual('OK', result)
-        self.assertEqual(2, mock_log.debug.call_count)
-
-    def test_utils_trace_method_with_password_dict(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)
-
-        @utils.trace_method
-        def _trace_test_method(*args, **kwargs):
-            return {'something': 'test',
-                    'password': 'Now you see me'}
-
-        utils.setup_tracing(['method'])
-        result = _trace_test_method(self)
-        expected_unmasked_dict = {'something': 'test',
-                                  'password': 'Now you see me'}
-
-        self.assertEqual(expected_unmasked_dict, result)
-        self.assertEqual(2, mock_log.debug.call_count)
-        self.assertIn("'password': '***'",
-                      str(mock_log.debug.call_args_list[1]))
-
-    def test_utils_trace_method_with_password_str(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)
-
-        @utils.trace_method
-        def _trace_test_method(*args, **kwargs):
-            return "'adminPass': 'Now you see me'"
-
-        utils.setup_tracing(['method'])
-        result = _trace_test_method(self)
-        expected_unmasked_str = "'adminPass': 'Now you see me'"
-
-        self.assertEqual(expected_unmasked_str, result)
-        self.assertEqual(2, mock_log.debug.call_count)
-        self.assertIn("'adminPass': '***'",
-                      str(mock_log.debug.call_args_list[1]))
-
-    def test_utils_trace_method_with_password_in_formal_params(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)
-
-        @utils.trace
-        def _trace_test_method(*args, **kwargs):
-            self.assertEqual('verybadpass',
-                             kwargs['test_args']['data']['password'])
-            pass
-
-        test_args = {
-            'data': {
-                'password': 'verybadpass'
-            }
-        }
-        _trace_test_method(self, test_args=test_args)
-
-        self.assertEqual(2, mock_log.debug.call_count)
-        self.assertIn("'password': '***'",
-                      str(mock_log.debug.call_args_list[0]))
-
+class TestCalculateVirtualFree(test.TestCase):
     @ddt.data(
         {'total': 30.01, 'free': 28.01, 'provisioned': 2.0, 'max_ratio': 1.0,
          'thin_support': False, 'thick_support': True,

cinder/tests/unit/test_volume_utils.py

@@ -17,7 +17,9 @@
 
 
 import datetime
+import functools
 import io
+import time
 from unittest import mock
 
 from castellan import key_manager
@@ -1229,3 +1231,327 @@ class VolumeUtilsTestCase(test.TestCase):
         volume_utils.get_backend_configuration('backendA')
         mock_configuration.assert_called_with(driver.volume_opts,
                                               config_group='backendA')
+
+
+@ddt.ddt
+class LogTracingTestCase(test.TestCase):
+
+    def test_utils_setup_tracing(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        volume_utils.setup_tracing(None)
+        self.assertFalse(volume_utils.TRACE_API)
+        self.assertFalse(volume_utils.TRACE_METHOD)
+        self.assertEqual(0, volume_utils.LOG.warning.call_count)
+
+        volume_utils.setup_tracing(['method'])
+        self.assertFalse(volume_utils.TRACE_API)
+        self.assertTrue(volume_utils.TRACE_METHOD)
+        self.assertEqual(0, volume_utils.LOG.warning.call_count)
+
+        volume_utils.setup_tracing(['method', 'api'])
+        self.assertTrue(volume_utils.TRACE_API)
+        self.assertTrue(volume_utils.TRACE_METHOD)
+        self.assertEqual(0, volume_utils.LOG.warning.call_count)
+
+    def test_utils_setup_tracing_invalid_key(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        volume_utils.setup_tracing(['fake'])
+
+        self.assertFalse(volume_utils.TRACE_API)
+        self.assertFalse(volume_utils.TRACE_METHOD)
+        self.assertEqual(1, volume_utils.LOG.warning.call_count)
+
+    def test_utils_setup_tracing_valid_and_invalid_key(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        volume_utils.setup_tracing(['method', 'fake'])
+
+        self.assertFalse(volume_utils.TRACE_API)
+        self.assertTrue(volume_utils.TRACE_METHOD)
+        self.assertEqual(1, volume_utils.LOG.warning.call_count)
+
+    def test_trace_no_tracing(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(None)
+
+        result = _trace_test_method()
+
+        self.assertEqual('OK', result)
+        self.assertEqual(0, volume_utils.LOG.debug.call_count)
+
+    def test_utils_trace_method(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['method'])
+
+        result = _trace_test_method()
+        self.assertEqual('OK', result)
+        self.assertEqual(2, volume_utils.LOG.debug.call_count)
+
+    def test_utils_trace_api(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        @volume_utils.trace_api
+        def _trace_test_api(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['api'])
+
+        result = _trace_test_api()
+        self.assertEqual('OK', result)
+        self.assertEqual(2, volume_utils.LOG.debug.call_count)
+
+    def test_utils_trace_api_filtered(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        def filter_func(all_args):
+            return False
+
+        @volume_utils.trace_api(filter_function=filter_func)
+        def _trace_test_api(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['api'])
+
+        result = _trace_test_api()
+        self.assertEqual('OK', result)
+        self.assertEqual(0, volume_utils.LOG.debug.call_count)
+
+    def test_utils_trace_filtered(self):
+        self.mock_object(volume_utils, 'LOG')
+
+        def filter_func(all_args):
+            return False
+
+        @volume_utils.trace(filter_function=filter_func)
+        def _trace_test(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['api'])
+
+        result = _trace_test()
+        self.assertEqual('OK', result)
+        self.assertEqual(0, volume_utils.LOG.debug.call_count)
+
+    def test_utils_trace_method_default_logger(self):
+        mock_log = self.mock_object(volume_utils, 'LOG')
+
+        @volume_utils.trace_method
+        def _trace_test_method_custom_logger(*args, **kwargs):
+            return 'OK'
+        volume_utils.setup_tracing(['method'])
+
+        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(volume_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
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['method'])
+
+        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(volume_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
+
+        @volume_utils.trace_method
+        @_test_decorator
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['method'])
+
+        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(volume_utils, 'LOG')
+
+        def _test_decorator(f):
+            @functools.wraps(f)
+            def wraps(*args, **kwargs):
+                return f(*args, **kwargs)
+            return wraps
+
+        @volume_utils.trace_method
+        @_test_decorator
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['method'])
+
+        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(volume_utils, 'LOG')
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            raise exception.APITimeout('test message')
+
+        volume_utils.setup_tracing(['method'])
+
+        self.assertRaises(exception.APITimeout, _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(volume_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)
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return 'OK'
+
+        volume_utils.setup_tracing(['method'])
+
+        result = _trace_test_method(self)
+
+        self.assertEqual('OK', result)
+        return_log = mock_log.debug.call_args_list[1]
+        self.assertIn('2900', str(return_log))
+
+    def test_utils_trace_wrapper_class(self):
+        mock_logging = self.mock_object(volume_utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        volume_utils.setup_tracing(['method'])
+
+        class MyClass(object, metaclass=volume_utils.TraceWrapperMetaclass):
+            def trace_test_method(self):
+                return 'OK'
+
+        test_class = MyClass()
+        result = test_class.trace_test_method()
+
+        self.assertEqual('OK', result)
+        self.assertEqual(2, mock_log.debug.call_count)
+
+    def test_utils_trace_method_with_password_dict(self):
+        mock_logging = self.mock_object(volume_utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return {'something': 'test',
+                    'password': 'Now you see me'}
+
+        volume_utils.setup_tracing(['method'])
+        result = _trace_test_method(self)
+        expected_unmasked_dict = {'something': 'test',
+                                  'password': 'Now you see me'}
+
+        self.assertEqual(expected_unmasked_dict, result)
+        self.assertEqual(2, mock_log.debug.call_count)
+        self.assertIn("'password': '***'",
+                      str(mock_log.debug.call_args_list[1]))
+
+    def test_utils_trace_method_with_password_str(self):
+        mock_logging = self.mock_object(volume_utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        @volume_utils.trace_method
+        def _trace_test_method(*args, **kwargs):
+            return "'adminPass': 'Now you see me'"
+
+        volume_utils.setup_tracing(['method'])
+        result = _trace_test_method(self)
+        expected_unmasked_str = "'adminPass': 'Now you see me'"
+
+        self.assertEqual(expected_unmasked_str, result)
+        self.assertEqual(2, mock_log.debug.call_count)
+        self.assertIn("'adminPass': '***'",
+                      str(mock_log.debug.call_args_list[1]))
+
+    def test_utils_trace_method_with_password_in_formal_params(self):
+        mock_logging = self.mock_object(volume_utils, 'logging')
+        mock_log = mock.Mock()
+        mock_log.isEnabledFor = lambda x: True
+        mock_logging.getLogger = mock.Mock(return_value=mock_log)
+
+        @volume_utils.trace
+        def _trace_test_method(*args, **kwargs):
+            self.assertEqual('verybadpass',
+                             kwargs['test_args']['data']['password'])
+            pass
+
+        test_args = {
+            'data': {
+                'password': 'verybadpass'
+            }
+        }
+        _trace_test_method(self, test_args=test_args)
+
+        self.assertEqual(2, mock_log.debug.call_count)
+        self.assertIn("'password': '***'",
+                      str(mock_log.debug.call_args_list[0]))

cinder/utils.py

@@ -17,13 +17,11 @@
 
 """Utilities and helper functions."""
 
-import abc
 from collections import OrderedDict
 import contextlib
 import datetime
 import functools
 import inspect
-import logging as py_logging
 import math
 import multiprocessing
 import operator
@@ -34,8 +32,6 @@ import shutil
 import stat
 import sys
 import tempfile
-import time
-import types
 
 import eventlet
 from eventlet import tpool
@@ -56,9 +52,6 @@ CONF = cfg.CONF
 LOG = logging.getLogger(__name__)
 ISO_TIME_FORMAT = "%Y-%m-%dT%H:%M:%S"
 PERFECT_TIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%f"
-VALID_TRACE_FLAGS = {'method', 'api'}
-TRACE_METHOD = False
-TRACE_API = False
 INITIAL_AUTO_MOSR = 20
 INFINITE_UNKNOWN_VALUES = ('infinite', 'unknown')
 
@@ -629,162 +622,6 @@ def convert_str(text):
         return text
 
 
-def trace_method(f):
-    """Decorates a function if TRACE_METHOD is true."""
-    @functools.wraps(f)
-    def trace_method_logging_wrapper(*args, **kwargs):
-        if TRACE_METHOD:
-            return trace(f)(*args, **kwargs)
-        return f(*args, **kwargs)
-    return trace_method_logging_wrapper
-
-
-def trace_api(*dec_args, **dec_kwargs):
-    """Decorates a function if TRACE_API is true."""
-
-    def _decorator(f):
-        @functools.wraps(f)
-        def trace_api_logging_wrapper(*args, **kwargs):
-            if TRACE_API:
-                return trace(f, *dec_args, **dec_kwargs)(*args, **kwargs)
-            return f(*args, **kwargs)
-        return trace_api_logging_wrapper
-
-    if len(dec_args) == 0:
-        # filter_function is passed and args does not contain f
-        return _decorator
-    else:
-        # filter_function is not passed
-        return _decorator(dec_args[0])
-
-
-def trace(*dec_args, **dec_kwargs):
-    """Trace calls to the decorated function.
-
-    This decorator should always be defined as the outermost decorator so it
-    is defined last. This is important so it does not interfere
-    with other decorators.
-
-    Using this decorator on a function will cause its execution to be logged at
-    `DEBUG` level with arguments, return values, and exceptions.
-
-    :returns: a function decorator
-    """
-
-    def _decorator(f):
-
-        func_name = f.__name__
-
-        @functools.wraps(f)
-        def trace_logging_wrapper(*args, **kwargs):
-            filter_function = dec_kwargs.get('filter_function')
-
-            if len(args) > 0:
-                maybe_self = args[0]
-            else:
-                maybe_self = kwargs.get('self', None)
-
-            if maybe_self and hasattr(maybe_self, '__module__'):
-                logger = logging.getLogger(maybe_self.__module__)
-            else:
-                logger = LOG
-
-            # NOTE(ameade): Don't bother going any further if DEBUG log level
-            # is not enabled for the logger.
-            if not logger.isEnabledFor(py_logging.DEBUG):
-                return f(*args, **kwargs)
-
-            all_args = inspect.getcallargs(f, *args, **kwargs)
-
-            pass_filter = filter_function is None or filter_function(all_args)
-
-            if pass_filter:
-                logger.debug('==> %(func)s: call %(all_args)r',
-                             {'func': func_name,
-                              'all_args': strutils.mask_password(
-                                  str(all_args))})
-
-            start_time = time.time() * 1000
-            try:
-                result = f(*args, **kwargs)
-            except Exception as exc:
-                total_time = int(round(time.time() * 1000)) - start_time
-                logger.debug('<== %(func)s: exception (%(time)dms) %(exc)r',
-                             {'func': func_name,
-                              'time': total_time,
-                              'exc': exc})
-                raise
-            total_time = int(round(time.time() * 1000)) - start_time
-
-            if isinstance(result, dict):
-                mask_result = strutils.mask_dict_password(result)
-            elif isinstance(result, str):
-                mask_result = strutils.mask_password(result)
-            else:
-                mask_result = result
-
-            if pass_filter:
-                logger.debug('<== %(func)s: return (%(time)dms) %(result)r',
-                             {'func': func_name,
-                              'time': total_time,
-                              'result': mask_result})
-            return result
-        return trace_logging_wrapper
-
-    if len(dec_args) == 0:
-        # filter_function is passed and args does not contain f
-        return _decorator
-    else:
-        # filter_function is not passed
-        return _decorator(dec_args[0])
-
-
-class TraceWrapperMetaclass(type):
-    """Metaclass that wraps all methods of a class with trace_method.
-
-    This metaclass will cause every function inside of the class to be
-    decorated with the trace_method decorator.
-
-    To use the metaclass you define a class like so:
-    class MyClass(object, metaclass=utils.TraceWrapperMetaclass):
-    """
-    def __new__(meta, classname, bases, classDict):
-        newClassDict = {}
-        for attributeName, attribute in classDict.items():
-            if isinstance(attribute, types.FunctionType):
-                # replace it with a wrapped version
-                attribute = functools.update_wrapper(trace_method(attribute),
-                                                     attribute)
-            newClassDict[attributeName] = attribute
-
-        return type.__new__(meta, classname, bases, newClassDict)
-
-
-class TraceWrapperWithABCMetaclass(abc.ABCMeta, TraceWrapperMetaclass):
-    """Metaclass that wraps all methods of a class with trace."""
-    pass
-
-
-def setup_tracing(trace_flags):
-    """Set global variables for each trace flag.
-
-    Sets variables TRACE_METHOD and TRACE_API, which represent
-    whether to log methods or api traces.
-
-    :param trace_flags: a list of strings
-    """
-    global TRACE_METHOD
-    global TRACE_API
-    try:
-        trace_flags = [flag.strip() for flag in trace_flags]
-    except TypeError:  # Handle when trace_flags is None or a test mock
-        trace_flags = []
-    for invalid_flag in (set(trace_flags) - VALID_TRACE_FLAGS):
-        LOG.warning('Invalid trace flag: %s', invalid_flag)
-    TRACE_METHOD = 'method' in trace_flags
-    TRACE_API = 'api' in trace_flags
-
-
 def build_or_str(elements, str_format=None):
     """Builds a string of elements joined by 'or'.
 

cinder/volume/driver.py

@@ -414,7 +414,8 @@ class BaseVD(object, metaclass=abc.ABCMeta):
             self.configuration.append_config_values(backup_opts)
             self.configuration.append_config_values(image_opts)
             self.configuration.append_config_values(fqdn_opts)
-            utils.setup_tracing(self.configuration.safe_get('trace_flags'))
+            volume_utils.setup_tracing(
+                self.configuration.safe_get('trace_flags'))
 
             # NOTE(geguileo): Don't allow to start if we are enabling
             # replication on a cluster service with a backend that doesn't

cinder/volume/drivers/ceph/rbd_iscsi.py

@@ -20,7 +20,6 @@ from oslo_utils import netutils
 from cinder import exception
 from cinder.i18n import _
 from cinder import interface
-from cinder import utils
 from cinder.volume import configuration
 from cinder.volume.drivers import rbd
 from cinder.volume import volume_utils
@@ -243,7 +242,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
         resp, disks = self.client.get_disks()
         return disks['disks']
 
-    @utils.trace
+    @volume_utils.trace
     def create_disk(self, volume_name):
         """Register the volume with the iscsi gateways.
 
@@ -265,7 +264,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
                 raise exception.VolumeBackendAPIException(
                     data=ex.get_description())
 
-    @utils.trace
+    @volume_utils.trace
     def register_disk(self, target_iqn, volume_name):
         """Register the disk with the target_iqn."""
         lun_name = self._lun_name(volume_name)
@@ -288,7 +287,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
             raise exception.VolumeBackendAPIException(
                 data=ex.get_description())
 
-    @utils.trace
+    @volume_utils.trace
     def unregister_disk(self, target_iqn, volume_name):
         """Unregister the volume from the gateway."""
         lun_name = self._lun_name(volume_name)
@@ -300,7 +299,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
             raise exception.VolumeBackendAPIException(
                 data=ex.get_description())
 
-    @utils.trace
+    @volume_utils.trace
     def export_disk(self, initiator_iqn, volume_name, iscsi_config):
         """Export a volume to an initiator."""
         lun_name = self._lun_name(volume_name)
@@ -323,7 +322,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
             raise exception.VolumeBackendAPIException(
                 data=ex.get_description())
 
-    @utils.trace
+    @volume_utils.trace
     def unexport_disk(self, initiator_iqn, volume_name, iscsi_config):
         """Remove a volume from an initiator."""
         lun_name = self._lun_name(volume_name)
@@ -354,7 +353,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
                     luns = client['luns']
                     return luns
 
-    @utils.trace
+    @volume_utils.trace
     def initialize_connection(self, volume, connector):
         """Export a volume to a host."""
         # create client
@@ -480,7 +479,7 @@ class RBDISCSIDriver(rbd.RBDDriver):
 
         self._delete_disk(volume)
 
-    @utils.trace
+    @volume_utils.trace
     def terminate_connection(self, volume, connector, **kwargs):
         """Unexport the volume from the gateway."""
         iscsi_config = self._get_config()

cinder/volume/drivers/datera/datera_iscsi.py

@@ -25,11 +25,11 @@ import six
 from cinder import exception
 from cinder.i18n import _
 from cinder import interface
-from cinder import utils
 import cinder.volume.drivers.datera.datera_api21 as api21
 import cinder.volume.drivers.datera.datera_api22 as api22
 import cinder.volume.drivers.datera.datera_common as datc
 from cinder.volume.drivers.san import san
+from cinder.volume import volume_utils
 
 LOG = logging.getLogger(__name__)
 
@@ -103,7 +103,7 @@ CONF.import_opt('driver_use_ssl', 'cinder.volume.driver')
 CONF.register_opts(d_opts)
 
 
-@six.add_metaclass(utils.TraceWrapperWithABCMetaclass)
+@six.add_metaclass(volume_utils.TraceWrapperWithABCMetaclass)
 @interface.volumedriver
 class DateraDriver(san.SanISCSIDriver, api21.DateraApi, api22.DateraApi):
     """The OpenStack Datera iSCSI volume driver.
@@ -211,7 +211,7 @@ class DateraDriver(san.SanISCSIDriver, api21.DateraApi, api22.DateraApi):
         self.datera_debug = self.configuration.datera_debug
 
         if self.datera_debug:
-            utils.setup_tracing(['method'])
+            volume_utils.setup_tracing(['method'])
         self.tenant_id = self.configuration.datera_tenant_id
         if self.tenant_id is None:
             self.tenant_id = ''

cinder/volume/drivers/dell_emc/unity/adapter.py

@@ -530,7 +530,7 @@ class CommonAdapter(object):
         }
         return conn_info
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def initialize_connection(self, volume, connector):
         lun = self.client.get_lun(lun_id=self.get_lun_id(volume))
         return self._initialize_connection(lun, connector, volume.id)
@@ -578,7 +578,7 @@ class CommonAdapter(object):
             'data': data,
         }
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def terminate_connection(self, volume, connector):
         lun = self.client.get_lun(lun_id=self.get_lun_id(volume))
         # None `connector` indicates force detach, then detach all even the
@@ -952,17 +952,17 @@ class CommonAdapter(object):
     def get_pool_id_by_name(self, name):
         return self.client.get_pool_id_by_name(name=name)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def initialize_connection_snapshot(self, snapshot, connector):
         snap = self.client.get_snap(snapshot.name)
         return self._initialize_connection(snap, connector, snapshot.id)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def terminate_connection_snapshot(self, snapshot, connector):
         snap = self.client.get_snap(snapshot.name)
         return self._terminate_connection(snap, connector)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def restore_snapshot(self, volume, snapshot):
         return self.client.restore_snapshot(snapshot.name)
 
@@ -1265,7 +1265,7 @@ class CommonAdapter(object):
         """The failover only happens manually, no need to update the status."""
         return [], []
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def failover(self, volumes, secondary_id=None, groups=None):
         # TODO(ryan) support group failover after group bp merges
         # https://review.opendev.org/#/c/574119/

cinder/volume/drivers/hitachi/hbsd_fc.py

@@ -17,11 +17,11 @@
 from oslo_config import cfg
 
 from cinder import interface
-from cinder import utils as cinder_utils
 from cinder.volume import configuration
 from cinder.volume import driver
 from cinder.volume.drivers.hitachi import hbsd_common as common
 from cinder.volume.drivers.hitachi import hbsd_utils as utils
+from cinder.volume import volume_utils
 
 FC_VOLUME_OPTS = [
     cfg.BoolOpt(
@@ -87,32 +87,32 @@ class HBSDFCDriver(driver.FibreChannelDriver):
     def check_for_setup_error(self):
         pass
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_volume(self, volume):
         """Create a volume and return its properties."""
         return self.common.create_volume(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_volume_from_snapshot(self, volume, snapshot):
         """Create a volume from a snapshot and return its properties."""
         return self.common.create_volume_from_snapshot(volume, snapshot)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_cloned_volume(self, volume, src_vref):
         """Create a clone of the specified volume and return its properties."""
         return self.common.create_cloned_volume(volume, src_vref)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def delete_volume(self, volume):
         """Delete the specified volume."""
         self.common.delete_volume(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_snapshot(self, snapshot):
         """Create a snapshot from a volume and return its properties."""
         return self.common.create_snapshot(snapshot)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def delete_snapshot(self, snapshot):
         """Delete the specified snapshot."""
         self.common.delete_snapshot(snapshot)
@@ -129,7 +129,7 @@ class HBSDFCDriver(driver.FibreChannelDriver):
                 self.get_goodness_function())
         return data
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def update_migrated_volume(
             self, ctxt, volume, new_volume, original_volume_status):
         """Do any remaining jobs after migration."""
@@ -137,34 +137,34 @@ class HBSDFCDriver(driver.FibreChannelDriver):
         super(HBSDFCDriver, self).update_migrated_volume(
             ctxt, volume, new_volume, original_volume_status)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def copy_image_to_volume(self, context, volume, image_service, image_id):
         """Fetch the image from image_service and write it to the volume."""
         super(HBSDFCDriver, self).copy_image_to_volume(
             context, volume, image_service, image_id)
         self.common.discard_zero_page(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def extend_volume(self, volume, new_size):
         """Extend the specified volume to the specified size."""
         self.common.extend_volume(volume, new_size)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def manage_existing(self, volume, existing_ref):
         """Return volume properties which Cinder needs to manage the volume."""
         return self.common.manage_existing(volume, existing_ref)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def manage_existing_get_size(self, volume, existing_ref):
         """Return the size[GB] of the specified volume."""
         return self.common.manage_existing_get_size(existing_ref)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def unmanage(self, volume):
         """Prepare the volume for removing it from Cinder management."""
         self.common.unmanage(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def do_setup(self, context):
         """Prepare for the startup of the driver."""
         self.common.do_setup(context)
@@ -187,12 +187,12 @@ class HBSDFCDriver(driver.FibreChannelDriver):
     def remove_export_snapshot(self, context, snapshot):
         pass
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def initialize_connection(self, volume, connector):
         """Initialize connection between the server and the volume."""
         return self.common.initialize_connection(volume, connector)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def terminate_connection(self, volume, connector, **kwargs):
         """Terminate connection between the server and the volume."""
         if connector is None:
@@ -201,22 +201,22 @@ class HBSDFCDriver(driver.FibreChannelDriver):
             return
         self.common.terminate_connection(volume, connector)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def initialize_connection_snapshot(self, snapshot, connector, **kwargs):
         """Initialize connection between the server and the snapshot."""
         return self.common.initialize_connection(snapshot, connector)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def terminate_connection_snapshot(self, snapshot, connector, **kwargs):
         """Terminate connection between the server and the snapshot."""
         self.common.terminate_connection(snapshot, connector)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def unmanage_snapshot(self, snapshot):
         """Prepare the snapshot for removing it from Cinder management."""
         return self.common.unmanage_snapshot(snapshot)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def retype(self, ctxt, volume, new_type, diff, host):
         """Retype the specified volume."""
         return self.common.retype()
@@ -224,7 +224,7 @@ class HBSDFCDriver(driver.FibreChannelDriver):
     def backup_use_temp_snapshot(self):
         return True
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def revert_to_snapshot(self, context, volume, snapshot):
         """Rollback the specified snapshot"""
         return self.common.revert_to_snapshot(volume, snapshot)

cinder/volume/drivers/hitachi/hbsd_iscsi.py

@@ -15,10 +15,10 @@
 """iSCSI module for Hitachi HBSD Driver."""
 
 from cinder import interface
-from cinder import utils as cinder_utils
 from cinder.volume import driver
 from cinder.volume.drivers.hitachi import hbsd_common as common
 from cinder.volume.drivers.hitachi import hbsd_utils as utils
+from cinder.volume import volume_utils
 
 MSG = utils.HBSDMsg
 
@@ -71,32 +71,32 @@ class HBSDISCSIDriver(driver.ISCSIDriver):
     def check_for_setup_error(self):
         pass
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_volume(self, volume):
         """Create a volume and return its properties."""
         return self.common.create_volume(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_volume_from_snapshot(self, volume, snapshot):
         """Create a volume from a snapshot and return its properties."""
         return self.common.create_volume_from_snapshot(volume, snapshot)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_cloned_volume(self, volume, src_vref):
         """Create a clone of the specified volume and return its properties."""
         return self.common.create_cloned_volume(volume, src_vref)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def delete_volume(self, volume):
         """Delete the specified volume."""
         self.common.delete_volume(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def create_snapshot(self, snapshot):
         """Create a snapshot from a volume and return its properties."""
         return self.common.create_snapshot(snapshot)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def delete_snapshot(self, snapshot):
         """Delete the specified snapshot."""
         self.common.delete_snapshot(snapshot)
@@ -113,7 +113,7 @@ class HBSDISCSIDriver(driver.ISCSIDriver):
                 self.get_goodness_function())
         return data
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def update_migrated_volume(
             self, ctxt, volume, new_volume, original_volume_status):
         """Do any remaining jobs after migration."""
@@ -121,34 +121,34 @@ class HBSDISCSIDriver(driver.ISCSIDriver):
         super(HBSDISCSIDriver, self).update_migrated_volume(
             ctxt, volume, new_volume, original_volume_status)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def copy_image_to_volume(self, context, volume, image_service, image_id):
         """Fetch the image from image_service and write it to the volume."""
         super(HBSDISCSIDriver, self).copy_image_to_volume(
             context, volume, image_service, image_id)
         self.common.discard_zero_page(volume)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def extend_volume(self, volume, new_size):
         """Extend the specified volume to the specified size."""
         self.common.extend_volume(volume, new_size)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def manage_existing(self, volume, existing_ref):
         """Return volume properties which Cinder needs to manage the volume."""
         return self.common.manage_existing(volume, existing_ref)
 
-    @cinder_utils.trace
+    @volume_utils.trace
     def manage_existing_get_size(self, volume, existing_ref):
         """Return the size[GB] of the specified volume."""