add exception summaries to the main log line

Normally when logging while there is an active exception, the exception
is formatted as a traceback and the log message string ends up on a
separate line. This change adds the 1-line summary of the exception,
including the exception class name and the text of the exception, to the
end of the log line. The traceback is retained, so that the full details
are still logged.

Adding the exception info in the formatter means that the default
excepthook function no longer needs to do that (otherwise we end up with
duplicate information on the lines logged by the excepthook). Fix the
duplication by replacing the extra traceback formatting with a static
message that there is an unhandled error.

Depends-On: Icb2e1c6d9fe40229119467e9261055d9464d331d
Change-Id: Ib29883a1b7aa665b5d3c728dd7bd53d449987191
Signed-off-by: Doug Hellmann <doug@doughellmann.com>

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):