Fix handling of exc_info in OSJournalHandler

exc_info is exception tuple not intended to be printed. It's using to
generate output by logging.Formatter().formatException() instead.
exc_text used to cache this output. So we use handler formatter to get
string from exc_info and send it as EXCEPTION_INFO. EXCEPTION_TEXT is
kept for backward compatibility.

Also adds type validation for journal.send fields to unit tests. Known
types could be gotten from journal.DEFAULT_CONVERTERS. The rest payload
must be either a string or bytes.

Change-Id: Idc0b9edc61b4ec39dc9df0ea8282cc104e4d83c0
Closes-Bug: 1802142

2 files changed, 30 insertions, 7 deletions

diff --git a/oslo_log/handlers.py b/oslo_log/handlers.py
index e8bc594..d602842 100644
--- a/oslo_log/handlers.py
+++ b/oslo_log/handlers.py
@@ -131,12 +131,17 @@ class OSJournalHandler(logging.Handler):
             'PRIORITY': priority
         }
 
+        if record.exc_info:
+            # Cache the traceback text to avoid converting it multiple times
+            # (it's constant anyway)
+            if not record.exc_text:
+                record.exc_text = self.formatter.formatException(
+                    record.exc_info)
         if record.exc_text:
+            extras['EXCEPTION_INFO'] = record.exc_text
+            # Leave EXCEPTION_TEXT for backward compatibility
             extras['EXCEPTION_TEXT'] = record.exc_text
 
-        if record.exc_info:
-            extras['EXCEPTION_INFO'] = record.exc_info
-
         for field in self.custom_fields:
             value = record.__dict__.get(field)
             if value:
diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py
index dcd524e..76f614a 100644
--- a/oslo_log/tests/unit/test_log.py
+++ b/oslo_log/tests/unit/test_log.py
@@ -400,7 +400,6 @@ class OSJournalHandlerTestCase(BaseTestCase):
         local_context = _fake_new_context()
         l.info("Foo", context=local_context)
         self.assertEqual(
-            self.journal.send.call_args,
             mock.call(mock.ANY, CODE_FILE=mock.ANY, CODE_FUNC='test_emit',
                       CODE_LINE=mock.ANY, LOGGER_LEVEL='INFO',
                       LOGGER_NAME='nova-test.foo', PRIORITY=6,
@@ -409,7 +408,17 @@ class OSJournalHandlerTestCase(BaseTestCase):
                       PROJECT_NAME='mytenant',
                       PROCESS_NAME='MainProcess',
                       THREAD_NAME='MainThread',
-                      USER_NAME='myuser'))
+                      USER_NAME='myuser'),
+            self.journal.send.call_args)
+        args, kwargs = self.journal.send.call_args
+        self.assertEqual(len(args), 1)
+        self.assertIsInstance(args[0], six.string_types)
+        self.assertIsInstance(kwargs['CODE_LINE'], int)
+        self.assertIsInstance(kwargs['PRIORITY'], int)
+        del kwargs['CODE_LINE'], kwargs['PRIORITY']
+        for key, arg in kwargs.items():
+            self.assertIsInstance(key, six.string_types)
+            self.assertIsInstance(arg, six.string_types + (six.binary_type,))
 
     def test_emit_exception(self):
         l = log.getLogger('nova-exception.foo')
@@ -419,7 +428,6 @@ class OSJournalHandlerTestCase(BaseTestCase):
         except Exception:
             l.exception("Foo", context=local_context)
         self.assertEqual(
-            self.journal.send.call_args,
             mock.call(mock.ANY, CODE_FILE=mock.ANY,
                       CODE_FUNC='test_emit_exception',
                       CODE_LINE=mock.ANY, LOGGER_LEVEL='ERROR',
@@ -431,7 +439,17 @@ class OSJournalHandlerTestCase(BaseTestCase):
                       PROJECT_NAME='mytenant',
                       PROCESS_NAME='MainProcess',
                       THREAD_NAME='MainThread',
-                      USER_NAME='myuser'))
+                      USER_NAME='myuser'),
+            self.journal.send.call_args)
+        args, kwargs = self.journal.send.call_args
+        self.assertEqual(len(args), 1)
+        self.assertIsInstance(args[0], six.string_types)
+        self.assertIsInstance(kwargs['CODE_LINE'], int)
+        self.assertIsInstance(kwargs['PRIORITY'], int)
+        del kwargs['CODE_LINE'], kwargs['PRIORITY']
+        for key, arg in kwargs.items():
+            self.assertIsInstance(key, six.string_types)
+            self.assertIsInstance(arg, six.string_types + (six.binary_type,))
 
 
 class LogLevelTestCase(BaseTestCase):