Add tracing facility for drivers

It is useful for engineering to be able to see the API traffic
to and from the storage controllers, as well as to see the
progression of method calls through the driver.

This work will add a simple config option to enable various
debug tracing types to be written to the debug log at runtime.
Use of the decorator has been added to NetApp drivers.

Drivers can make use of this facility by adding the
@cinder.utils.trace_method decorator to any method
calls they would like to allow tracing for or use trace_flags
for any other developer targeted debug logs. The trace_method
decorator can easily be added to every function of a class by
using the cinder.utils.TraceWrapperMetaclass or
cinder.utils.TraceWrapperWithABCMetaclass metaclasses. It is
advised to use the added decorators as the outer most decorator
for a function in order to avoid side-effects with other
decorators.

The @cinder.utils.trace_api method should be used to log
requests to storage backends by wrapping a method that
has the request as an argument and returns the response.

For example:
@six.add_metaclass(cinder.utils.TraceWrapperMetaclass)
class MyClass(object):
    pass

DocImpact
Change-Id: Ib9b9d3f40a272bb9c7ebccd1dc63df68a555eac5

diff --git a/cinder/tests/unit/test_utils.py b/cinder/tests/unit/test_utils.py
index b8a21f3f83ce1f19a64362971412ab46899ed65b..6faddecef1ffef0278f8e7ac6109811fde07c327 100644 (file)
--- a/cinder/tests/unit/test_utils.py
+++ b/cinder/tests/unit/test_utils.py
@@ -14,6 +14,7 @@
 
 
 import datetime
+import functools
 import hashlib
 import os
 import time
@@ -1506,3 +1507,232 @@ class VersionTestCase(test.TestCase):
 
     def test_convert_version_to_tuple(self):
         self.assertEqual(utils.convert_version_to_tuple('6.7.0'), (6, 7, 0))
+
+
+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_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.assertTrue('_trace_test_method' in str(call))
+            self.assertFalse('blah' in 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.assertFalse('_trace_test_method' in str(call))
+            self.assertTrue('blah' in 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.assertTrue('_trace_test_method' in str(call))
+            self.assertFalse('wraps' in 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.assertTrue('exception' in str(exception_log))
+        self.assertTrue('test message' in 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.assertTrue('2900' in 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'])
+
+        @six.add_metaclass(utils.TraceWrapperMetaclass)
+        class MyClass(object):
+            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)

diff --git a/cinder/utils.py b/cinder/utils.py
index fe711f2a125f1cebe47717324e14f55e5854e2da..12c92a12b4898932e35da6bf938242eec7b1b689 100644 (file)
--- a/cinder/utils.py
+++ b/cinder/utils.py
@@ -18,10 +18,13 @@
 """Utilities and helper functions."""
 
 
+import abc
 import contextlib
 import datetime
+import functools
 import hashlib
 import inspect
+import logging as py_logging
 import os
 import pyclbr
 import re
@@ -29,6 +32,8 @@ import shutil
 import stat
 import sys
 import tempfile
+import time
+import types
 from xml.dom import minidom
 from xml.parsers import expat
 from xml import sax
@@ -47,13 +52,16 @@ import retrying
 import six
 
 from cinder import exception
-from cinder.i18n import _, _LE
+from cinder.i18n import _, _LE, _LW
 
 
 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
 
 synchronized = lockutils.synchronized_with_prefix('cinder-')
 
@@ -828,3 +836,126 @@ def convert_str(text):
             return text.decode('utf-8')
         else:
             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(f):
+    """Decorates a function if TRACE_API is true."""
+    @functools.wraps(f)
+    def trace_api_logging_wrapper(*args, **kwargs):
+        if TRACE_API:
+            return trace(f)(*args, **kwargs)
+        return f(*args, **kwargs)
+    return trace_api_logging_wrapper
+
+
+def trace(f):
+    """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
+    """
+
+    func_name = f.__name__
+
+    @functools.wraps(f)
+    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__'):
+            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)
+        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: return (%(time)dms) %(result)r',
+                     {'func': func_name,
+                      'time': total_time,
+                      'result': result})
+        return result
+    return trace_logging_wrapper
+
+
+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:
+    @six.add_metaclass(utils.TraceWrapperMetaclass)
+    class MyClass(object):
+    """
+    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 method and 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(_LW('Invalid trace flag: %s'), invalid_flag)
+    TRACE_METHOD = 'method' in trace_flags
+    TRACE_API = 'api' in trace_flags

diff --git a/cinder/volume/driver.py b/cinder/volume/driver.py
index ba5c52a2b5ad61ce65606e436c4c8b48e94084cf..1d6436ba2c4fae7c0b23ffcb57309d4feb363cf2 100644 (file)
--- a/cinder/volume/driver.py
+++ b/cinder/volume/driver.py
@@ -221,6 +221,11 @@ volume_opts = [
                 default=False,
                 help='If set to True the http client will validate the SSL '
                      'certificate of the backend endpoint.'),
+    cfg.ListOpt('trace_flags',
+                default=None,
+                help='List of options that control which trace info '
+                     'is written to the DEBUG log level to assist '
+                     'developers. Valid values are method and api.'),
 ]
 
 # for backward compatibility
@@ -289,6 +294,7 @@ class BaseVD(object):
         if self.configuration:
             self.configuration.append_config_values(volume_opts)
             self.configuration.append_config_values(iser_opts)
+            utils.setup_tracing(self.configuration.safe_get('trace_flags'))
         self.set_execute(execute)
         self._stats = {}