1 files changed, 93 insertions, 11 deletions

diff --git a/keystone-moon/keystone/common/manager.py b/keystone-moon/keystone/common/manager.py
index f98a1763..4ce9f2a6 100644
--- a/keystone-moon/keystone/common/manager.py
+++ b/keystone-moon/keystone/common/manager.py
@@ -13,12 +13,19 @@
 # under the License.
 
 import functools
+import inspect
+import time
+import types
 
 from oslo_log import log
 from oslo_log import versionutils
 from oslo_utils import importutils
+from oslo_utils import reflection
+import six
 import stevedore
 
+from keystone.i18n import _
+
 
 LOG = log.getLogger(__name__)
 
@@ -70,17 +77,93 @@ def load_driver(namespace, driver_name, *args):
         LOG.debug('Failed to load %r using stevedore: %s', driver_name, e)
         # Ignore failure and continue on.
 
-    @versionutils.deprecated(as_of=versionutils.deprecated.LIBERTY,
-                             in_favor_of='entrypoints',
-                             what='direct import of driver')
-    def _load_using_import(driver_name, *args):
-        return importutils.import_object(driver_name, *args)
+    driver = importutils.import_object(driver_name, *args)
+
+    msg = (_(
+        'Direct import of driver %(name)r is deprecated as of Liberty in '
+        'favor of its entrypoint from %(namespace)r and may be removed in '
+        'N.') %
+        {'name': driver_name, 'namespace': namespace})
+    versionutils.report_deprecated_feature(LOG, msg)
+
+    return driver
 
-    # For backwards-compatibility, an unregistered class reference can
-    # still be used.
-    return _load_using_import(driver_name, *args)
 
+class _TraceMeta(type):
+    """A metaclass that, in trace mode, will log entry and exit of methods.
 
+    This metaclass automatically wraps all methods on the class when
+    instantiated with a decorator that will log entry/exit from a method
+    when keystone is run in Trace log level.
+    """
+
+    @staticmethod
+    def wrapper(__f, __classname):
+        __argspec = inspect.getargspec(__f)
+        __fn_info = '%(module)s.%(classname)s.%(funcname)s' % {
+            'module': inspect.getmodule(__f).__name__,
+            'classname': __classname,
+            'funcname': __f.__name__
+        }
+        # NOTE(morganfainberg): Omit "cls" and "self" when printing trace logs
+        # the index can be calculated at wrap time rather than at runtime.
+        if __argspec.args and __argspec.args[0] in ('self', 'cls'):
+            __arg_idx = 1
+        else:
+            __arg_idx = 0
+
+        @functools.wraps(__f)
+        def wrapped(*args, **kwargs):
+            __exc = None
+            __t = time.time()
+            __do_trace = LOG.logger.getEffectiveLevel() <= log.TRACE
+            __ret_val = None
+            try:
+                if __do_trace:
+                    LOG.trace('CALL => %s', __fn_info)
+                __ret_val = __f(*args, **kwargs)
+            except Exception as e:  # nosec
+                __exc = e
+                raise
+            finally:
+                if __do_trace:
+                    __subst = {
+                        'run_time': (time.time() - __t),
+                        'passed_args': ', '.join([
+                            ', '.join([repr(a)
+                                       for a in args[__arg_idx:]]),
+                            ', '.join(['%(k)s=%(v)r' % {'k': k, 'v': v}
+                                       for k, v in kwargs.items()]),
+                        ]),
+                        'function': __fn_info,
+                        'exception': __exc,
+                        'ret_val': __ret_val,
+                    }
+                    if __exc is not None:
+                        __msg = ('[%(run_time)ss] %(function)s '
+                                 '(%(passed_args)s) => raised '
+                                 '%(exception)r')
+                    else:
+                        # TODO(morganfainberg): find a way to indicate if this
+                        # was a cache hit or cache miss.
+                        __msg = ('[%(run_time)ss] %(function)s'
+                                 '(%(passed_args)s) => %(ret_val)r')
+                    LOG.trace(__msg, __subst)
+            return __ret_val
+        return wrapped
+
+    def __new__(meta, classname, bases, class_dict):
+        final_cls_dict = {}
+        for attr_name, attr in class_dict.items():
+            # NOTE(morganfainberg): only wrap public instances and methods.
+            if (isinstance(attr, types.FunctionType) and
+                    not attr_name.startswith('_')):
+                attr = _TraceMeta.wrapper(attr, classname)
+            final_cls_dict[attr_name] = attr
+        return type.__new__(meta, classname, bases, final_cls_dict)
+
+
+@six.add_metaclass(_TraceMeta)
 class Manager(object):
     """Base class for intermediary request layer.
 
@@ -121,16 +204,15 @@ def create_legacy_driver(driver_class):
         Driver = create_legacy_driver(CatalogDriverV8)
 
     """
-
     module_name = driver_class.__module__
-    class_name = driver_class.__name__
+    class_name = reflection.get_class_name(driver_class)
 
     class Driver(driver_class):
 
         @versionutils.deprecated(
             as_of=versionutils.deprecated.LIBERTY,
             what='%s.Driver' % module_name,
-            in_favor_of='%s.%s' % (module_name, class_name),
+            in_favor_of=class_name,
             remove_in=+2)
         def __init__(self, *args, **kwargs):
             super(Driver, self).__init__(*args, **kwargs)