[Logging] Enable filtering of trace_api logs

This improvement allows trace_api decorators to be
passed a filter function argument, which can validate
the parameters of the object being logged to decide
to not filter it.

Change-Id: I2dbf5583b8d2c9b9afe35bc5a916f480637d79f5

cinder/tests/unit/test_utils.py

@@ -1137,6 +1137,38 @@ class LogTracingTestCase(test.TestCase):
         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')
 

cinder/utils.py

@@ -850,17 +850,26 @@ def trace_method(f):
     return trace_method_logging_wrapper
 
 
-def trace_api(f):
+def trace_api(*dec_args, **dec_kwargs):
     """Decorates a function if TRACE_API is true."""
-    @functools.wraps(f)
+
-    def trace_api_logging_wrapper(*args, **kwargs):
+    def _decorator(f):
-        if TRACE_API:
+        @functools.wraps(f)
-            return trace(f)(*args, **kwargs)
+        def trace_api_logging_wrapper(*args, **kwargs):
-        return f(*args, **kwargs)
+            if TRACE_API:
-    return trace_api_logging_wrapper
+                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(f):
+def trace(*dec_args, **dec_kwargs):
     """Trace calls to the decorated function.
 
     This decorator should always be defined as the outermost decorator so it
@@ -873,55 +882,70 @@ def trace(f):
     :returns: a function decorator
     """
 
-    func_name = f.__name__
+    def _decorator(f):
 
-    @functools.wraps(f)
+        func_name = f.__name__
-    def trace_logging_wrapper(*args, **kwargs):
-        if len(args) > 0:
-            maybe_self = args[0]
-        else:
-            maybe_self = kwargs.get('self', None)
 
-        if maybe_self and hasattr(maybe_self, '__module__'):
+        @functools.wraps(f)
-            logger = logging.getLogger(maybe_self.__module__)
+        def trace_logging_wrapper(*args, **kwargs):
-        else:
+            filter_function = dec_kwargs.get('filter_function')
-            logger = LOG
 
-        # NOTE(ameade): Don't bother going any further if DEBUG log level
+            if len(args) > 0:
-        # is not enabled for the logger.
+                maybe_self = args[0]
-        if not logger.isEnabledFor(py_logging.DEBUG):
+            else:
-            return f(*args, **kwargs)
+                maybe_self = kwargs.get('self', None)
 
-        all_args = inspect.getcallargs(f, *args, **kwargs)
+            if maybe_self and hasattr(maybe_self, '__module__'):
+                logger = logging.getLogger(maybe_self.__module__)
+            else:
+                logger = LOG
 
-        logger.debug('==> %(func)s: call %(all_args)r',
+            # NOTE(ameade): Don't bother going any further if DEBUG log level
-                     {'func': func_name, 'all_args': all_args})
+            # is not enabled for the logger.
+            if not logger.isEnabledFor(py_logging.DEBUG):
+                return f(*args, **kwargs)
 
-        start_time = time.time() * 1000
+            all_args = inspect.getcallargs(f, *args, **kwargs)
-        try:
+
-            result = f(*args, **kwargs)
+            pass_filter = filter_function is None or filter_function(all_args)
-        except Exception as exc:
+
+            if pass_filter:
+                logger.debug('==> %(func)s: call %(all_args)r',
+                             {'func': func_name, 'all_args': 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
-            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):
+            if isinstance(result, dict):
-            mask_result = strutils.mask_dict_password(result)
+                mask_result = strutils.mask_dict_password(result)
-        elif isinstance(result, six.string_types):
+            elif isinstance(result, six.string_types):
-            mask_result = strutils.mask_password(result)
+                mask_result = strutils.mask_password(result)
-        else:
+            else:
-            mask_result = result
+                mask_result = result
 
-        logger.debug('<== %(func)s: return (%(time)dms) %(result)r',
+            if pass_filter:
-                     {'func': func_name,
+                logger.debug('<== %(func)s: return (%(time)dms) %(result)r',
-                      'time': total_time,
+                             {'func': func_name,
-                      'result': mask_result})
+                              'time': total_time,
-        return result
+                              'result': mask_result})
-    return trace_logging_wrapper
+            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):