Merge "add exception summaries to the main log line"

3 files changed, 64 insertions, 31 deletions

diff --git a/oslo_log/formatters.py b/oslo_log/formatters.py
index b57e5aa..bf12c66 100644
--- a/oslo_log/formatters.py
+++ b/oslo_log/formatters.py
@@ -267,7 +267,6 @@ class ContextFormatter(logging.Formatter):
 
     def format(self, record):
         """Uses contextstring if request_id is set, otherwise default."""
-
         if six.PY2:
             should_use_unicode = True
             args = (record.args.values() if isinstance(record.args, dict)
@@ -358,10 +357,51 @@ class ContextFormatter(logging.Formatter):
         else:
             self._style = logging.PercentStyle(fmt)
             self._fmt = self._style._fmt
-        # Cache this on the record, Logger will respect our formatted copy
+
+        # Cache the formatted traceback on the record, Logger will
+        # respect our formatted copy
         if record.exc_info:
             record.exc_text = self.formatException(record.exc_info, record)
-        return logging.Formatter.format(self, record)
+            # Save the exception we were given so we can include the
+            # summary in the log line.
+            exc_info = record.exc_info
+        else:
+            # Check to see if there is an active exception that was
+            # not given to us explicitly. If so, save it so we can
+            # include the summary in the log line.
+            exc_info = sys.exc_info()
+            # If we get (None, None, None) because there is no
+            # exception, convert it to a simple None to make the logic
+            # that uses the value simpler.
+            if not exc_info[0]:
+                exc_info = None
+
+        if exc_info:
+            # Include the exception summary in the line with the
+            # primary log message, to serve as a mnemonic for error
+            # and warning cases. Replace % with * to remove any
+            # patterns that look like they would be python string
+            # interpolation instructions, since we may not have the
+            # arguments for them and that will break the log
+            # formatter.
+            suffix = traceback.format_exception_only(
+                exc_info[0],
+                exc_info[1],
+            )[0].rstrip().replace('%', '*')
+            record.msg = '{}: {}'.format(record.msg, suffix)
+            # Remove the local reference to the exception and
+            # traceback to avoid a memory leak through the frame
+            # references.
+            del exc_info
+
+        try:
+            return logging.Formatter.format(self, record)
+        except TypeError as err:
+            # Something went wrong, report that instead so we at least
+            # get the error message.
+            record.msg = 'Error formatting log line msg={!r} err={!r}'.format(
+                record.msg, err).replace('%', '*')
+            return logging.Formatter.format(self, record)
 
     def formatException(self, exc_info, record=None):
         """Format exception output with CONF.logging_exception_prefix."""
diff --git a/oslo_log/log.py b/oslo_log/log.py
index afb73a2..b22fa97 100644
--- a/oslo_log/log.py
+++ b/oslo_log/log.py
@@ -37,7 +37,6 @@ try:
     import syslog
 except ImportError:
     syslog = None
-import traceback
 
 from oslo_config import cfg
 from oslo_utils import importutils
@@ -191,9 +190,7 @@ class KeywordArgumentAdapter(BaseLoggerAdapter):
 def _create_logging_excepthook(product_name):
     def logging_excepthook(exc_type, value, tb):
         extra = {'exc_info': (exc_type, value, tb)}
-        getLogger(product_name).critical(
-            "".join(traceback.format_exception_only(exc_type, value)),
-            **extra)
+        getLogger(product_name).critical('Unhandled error', **extra)
     return logging_excepthook
 
 
diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py
index d7c50f7..543e891 100644
--- a/oslo_log/tests/unit/test_log.py
+++ b/oslo_log/tests/unit/test_log.py
@@ -759,7 +759,7 @@ class ExceptionLoggingTestCase(LogTestBase):
         except Exception:
             excepthook(*sys.exc_info())
 
-        expected_string = ("CRITICAL somename [-] "
+        expected_string = ("CRITICAL somename [-] Unhandled error: "
                            "Exception: Some error happened")
         self.assertIn(expected_string, self.stream.getvalue(),
                       message="Exception is not logged")
@@ -834,15 +834,16 @@ class FancyRecordTestCase(LogTestBase):
         warncolor = handlers.ColorHandler.LEVEL_COLORS[logging.WARN]
         info_msg = 'info'
         warn_msg = 'warn'
-        infoexpected = "%s %s %s\n" % (infocolor, keyed_log_string, info_msg)
-        warnexpected = "%s %s %s\n" % (warncolor, keyed_log_string, warn_msg)
+        infoexpected = "%s %s %s" % (infocolor, keyed_log_string, info_msg)
+        warnexpected = "%s %s %s" % (warncolor, keyed_log_string, warn_msg)
 
         self.colorlog.info(info_msg, context=ctxt)
-        self.assertEqual(infoexpected, self.stream.getvalue())
+        self.assertIn(infoexpected, self.stream.getvalue())
         self.assertEqual('\033[00;36m', infocolor)
 
         self.colorlog.warn(warn_msg, context=ctxt)
-        self.assertEqual(infoexpected + warnexpected, self.stream.getvalue())
+        self.assertIn(infoexpected, self.stream.getvalue())
+        self.assertIn(warnexpected, self.stream.getvalue())
         self.assertEqual('\033[01;33m', warncolor)
 
     def test_fancy_key_in_log_msg(self):
@@ -900,51 +901,47 @@ class InstanceRecordTestCase(LogTestBase):
         fake_resource = {'uuid': uuid}
         message = 'info'
         self.log.info(message, context=ctxt, instance=fake_resource)
-        expected = ('[%s]: [instance: %s] %s\n' %
-                    (ctxt.request_id, uuid, message))
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_instance_dict_in_default_log_msg(self):
         uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
         fake_resource = {'uuid': uuid}
         message = 'info'
         self.log.info(message, instance=fake_resource)
-        expected = '[instance: %s] %s\n' % (uuid, message)
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_instance_uuid_as_arg_in_context_log_msg(self):
         ctxt = _fake_context()
         uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
         message = 'info'
         self.log.info(message, context=ctxt, instance_uuid=uuid)
-        expected = ('[%s]: [instance: %s] %s\n' %
-                    (ctxt.request_id, uuid, message))
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_instance_uuid_as_arg_in_default_log_msg(self):
         uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
         message = 'info'
         self.log.info(message, instance_uuid=uuid)
-        expected = '[instance: %s] %s\n' % (uuid, message)
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_instance_uuid_from_context_in_context_log_msg(self):
         ctxt = _fake_context()
         ctxt.instance_uuid = 'CCCCCCCC-8A12-4C53-A736-D7A1C36A62F3'
         message = 'info'
         self.log.info(message, context=ctxt)
-        expected = ('[%s]: [instance: %s] %s\n' %
-                    (ctxt.request_id, ctxt.instance_uuid, message))
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % ctxt.instance_uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_resource_uuid_from_context_in_context_log_msg(self):
         ctxt = _fake_context()
         ctxt.resource_uuid = 'RRRRRRRR-8A12-4C53-A736-D7A1C36A62F3'
         message = 'info'
         self.log.info(message, context=ctxt)
-        expected = ('[%s]: [instance: %s] %s\n' %
-                    (ctxt.request_id, ctxt.resource_uuid, message))
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % ctxt.resource_uuid
+        self.assertIn(expected, self.stream.getvalue())
 
     def test_instance_from_context_in_context_log_msg(self):
         # NOTE: instance when passed in a context object is just a uuid.
@@ -953,9 +950,8 @@ class InstanceRecordTestCase(LogTestBase):
         ctxt.instance = 'IIIIIIII-8A12-4C53-A736-D7A1C36A62F3'
         message = 'info'
         self.log.info(message, context=ctxt)
-        values = (ctxt.request_id, ctxt.instance, message)
-        expected = '[%s]: [instance: %s] %s\n' % values
-        self.assertEqual(expected, self.stream.getvalue())
+        expected = '[instance: %s]' % ctxt.instance
+        self.assertIn(expected, self.stream.getvalue())
 
 
 class TraceLevelTestCase(LogTestBase):