Fix bug in log_method_call decorator

log_method_call decorator miss first argument of staticmethod and function.
the cause of bug is wrong start position of argument array for staticmethod.
This patch adds a bug fix and test code.

Change-Id: Id83378ba5954a855f18a4fdcfd22d2c7887991b2
Closes-Bug: #1672283

oslo_log/helpers.py

@@ -15,6 +15,7 @@
 """Log helper functions."""
 
 import functools
+import inspect
 import logging
 
 
@@ -23,6 +24,19 @@ def _get_full_class_name(cls):
                       getattr(cls, '__qualname__', cls.__name__))
 
 
+def _is_method(obj, method):
+    """Returns True if a given method is obj's method.
+
+    You can not simply test a given method like:
+
+    return inspect.ismethod(method)
+
+    This is because functools.wraps converts the method to a function
+    in log_method_call function.
+    """
+    return inspect.ismethod(getattr(obj, method.__name__, None))
+
+
 def log_method_call(method):
     """Decorator helping to log method calls.
 
@@ -33,16 +47,21 @@ def log_method_call(method):
 
     @functools.wraps(method)
     def wrapper(*args, **kwargs):
+        args_start_pos = 0
         if args:
             first_arg = args[0]
+            if _is_method(first_arg, method):
                 cls = (first_arg if isinstance(first_arg, type)
                        else first_arg.__class__)
                 caller = _get_full_class_name(cls)
+                args_start_pos = 1
+            else:
+                caller = 'static'
         else:
             caller = 'static'
         data = {'caller': caller,
                 'method_name': method.__name__,
-                'args': args[1:], 'kwargs': kwargs}
+                'args': args[args_start_pos:], 'kwargs': kwargs}
         log.debug('%(caller)s method %(method_name)s '
                   'called with arguments %(args)s %(kwargs)s', data)
         return method(*args, **kwargs)

oslo_log/tests/unit/test_helpers.py

@@ -15,11 +15,6 @@ from oslo_log import helpers
 from oslotest import base as test_base
 
 
-@helpers.log_method_call
-def _static_method():
-    pass
-
-
 class LogHelpersTestCase(test_base.BaseTestCase):
 
     def test_log_decorator(self):
@@ -53,6 +48,16 @@ class LogHelpersTestCase(test_base.BaseTestCase):
     def test_log_decorator_for_static(self):
         '''Test that LOG.debug is called with proper arguments.'''
 
+        @helpers.log_method_call
+        def _static_method():
+            pass
+
+        class test_class(object):
+            @staticmethod
+            @helpers.log_method_call
+            def test_staticmethod(arg1, arg2, arg3, *args, **kwargs):
+                pass
+
         data = {'caller': 'static',
                 'method_name': '_static_method',
                 'args': (),
@@ -60,3 +65,13 @@ class LogHelpersTestCase(test_base.BaseTestCase):
         with mock.patch('logging.Logger.debug') as debug:
             _static_method()
             debug.assert_called_with(mock.ANY, data)
+
+        args = tuple(range(6))
+        kwargs = {'kwarg1': 6, 'kwarg2': 7}
+        data = {'caller': 'static',
+                'method_name': 'test_staticmethod',
+                'args': args,
+                'kwargs': kwargs}
+        with mock.patch('logging.Logger.debug') as debug:
+            test_class.test_staticmethod(*args, **kwargs)
+            debug.assert_called_with(mock.ANY, data)