[logging] Check the right usage of logging.exception

Method `exception` expects to see a user-friednly message as a first
argument, but we had a lot of places where exception objects are
transmitted instead.

This patch adds a proper check for such case.

Change-Id: I346814304de41c986354d25258275cdde838f870

rally/common/logging.py

@@ -19,6 +19,7 @@ import traceback
 from oslo_config import cfg
 from oslo_log import handlers
 from oslo_log import log as oslogging
+import six
 
 
 log = __import__("logging")
@@ -60,11 +61,33 @@ def setup(product_name, version="unknown"):
 
 class RallyContextAdapter(oslogging.KeywordArgumentAdapter):
 
-    _msg = "Do not use *args for string formatting for log message: %s"
+    _posargs_msg = "Do not use *args for string formatting for log message: %s"
+    _exc_msg = ("Do not transmit an exception objects to logging. It will "
+                "be included automagically. Transmit a user-friendly "
+                "explanation instead.")
+
+    @staticmethod
+    def _find_the_caller(i=0):
+        """Finds the caller of logging method
+
+        :param i: number of upper elements relatively to the place of calling
+            `_find_the_caller` method
+        :return: a tuple where the first element is a filename, the second is
+            a line number and the third is a line of code
+        """
+        import inspect
+
+        # the first 2 elements in the stack are the current line and the line
+        #   of caller of `_find_the_caller`
+        i = i + 2
+        caller = inspect.stack()[i]
+        return caller[1], caller[2], caller[4][0].rstrip("\n").strip()
 
     def _check_args(self, msg, *args):
         if args:
-            self.log(log.WARNING, self._msg % msg)
+            caller = self._find_the_caller(1)
+            logger = getLogger("%s:%s" % (caller[0], caller[1]))
+            logger.warning("[%s] %s" % (caller[2], self._posargs_msg % msg))
 
     def debug(self, msg, *args, **kwargs):
         self._check_args(msg, *args)
@@ -82,6 +105,14 @@ class RallyContextAdapter(oslogging.KeywordArgumentAdapter):
         self._check_args(msg, *args)
         self.log(log.ERROR, msg, *args, **kwargs)
 
+    def exception(self, msg, exc_info=True, *args, **kwargs):
+        if not isinstance(msg, (six.text_type, six.string_types)):
+            caller = self._find_the_caller()
+            logger = getLogger("%s:%s" % (caller[0], caller[1]))
+            logger.warning("[%s] %s" % (caller[2], self._exc_msg))
+        super(RallyContextAdapter, self).exception(msg, exc_info=exc_info,
+                                                   *args, **kwargs)
+
 
 def getLogger(name="unknown", version="unknown"):
 

tests/unit/common/test_logging.py

@@ -64,7 +64,7 @@ class SetUpLogTestCase(test.TestCase):
         self.assertEqual(mock_oslogging._loggers[name], returned_logger)
 
 
-class LogRallyContaxtAdapterTestCase(test.TestCase):
+class RallyContaxtAdapterTestCase(test.TestCase):
 
     @mock.patch("rally.common.logging.log")
     @mock.patch("rally.common.logging.oslogging.KeywordArgumentAdapter")
@@ -80,6 +80,64 @@ class LogRallyContaxtAdapterTestCase(test.TestCase):
         radapter.log.assert_called_once_with(mock_log.RDEBUG,
                                              fake_msg)
 
+    def test__find_caller(self):
+        radapter = rally_logging.RallyContextAdapter(mock.MagicMock(), "fakep")
+
+        self.caller = None
+
+        def logging_method():
+            self.caller = radapter._find_the_caller()
+
+        def foo():
+            logging_method()
+
+        foo()
+        # the number of the line which calls logging_method
+        lineno = 92
+        self.assertEqual((__file__, lineno, "logging_method()"), self.caller)
+
+    @mock.patch("rally.common.logging.getLogger")
+    def test__check_args(self, mock_get_logger):
+        radapter = rally_logging.RallyContextAdapter(mock.MagicMock(), "fakep")
+
+        def foo(*args):
+            radapter._check_args("", *args)
+
+        foo()
+
+        self.assertFalse(mock_get_logger.called)
+
+        foo(1)
+
+        # the number of the line which calls foo
+        lineno = 110
+        mock_get_logger.assert_called_once_with("%s:%s" % (__file__, lineno))
+        logger = mock_get_logger.return_value
+        self.assertEqual(1, logger.warning.call_count)
+        args = logger.warning.call_args_list[0]
+        self.assertTrue(args[0][0].startswith("[foo(1)] Do not use"))
+
+    @mock.patch("rally.common.logging.getLogger")
+    def test_exception(self, mock_get_logger):
+        radapter = rally_logging.RallyContextAdapter(mock.MagicMock(), {})
+        radapter.log = mock.MagicMock()
+
+        radapter.exception("foo")
+
+        self.assertFalse(mock_get_logger.called)
+
+        radapter.exception(Exception("!2!"))
+
+        # the number of the line which calls foo
+        lineno = 129
+        mock_get_logger.assert_called_once_with("%s:%s" % (__file__, lineno))
+
+        logger = mock_get_logger.return_value
+        self.assertEqual(1, logger.warning.call_count)
+        args = logger.warning.call_args_list[0]
+        self.assertTrue(args[0][0].startswith("[radapter.exception(Exception("
+                                              "\"!2!\"))] Do not transmit"))
+
 
 class ExceptionLoggerTestCase(test.TestCase):