make handling of error_summary more flexible

Allow operators to override the location of the error summary within the
format string, if they choose.

Change-Id: I85fe5abaa0781d033638e3b6f120184726d205ac
Signed-off-by: Doug Hellmann <doug@doughellmann.com>

oslo_log/formatters.py

@@ -346,18 +346,6 @@ class ContextFormatter(logging.Formatter):
         else:
             fmt = self.conf.logging_default_format_string
 
-        if (record.levelno == logging.DEBUG and
-                self.conf.logging_debug_format_suffix):
-            fmt += " " + self.conf.logging_debug_format_suffix
-
-        self._compute_iso_time(record)
-
-        if sys.version_info < (3, 2):
-            self._fmt = fmt
-        else:
-            self._style = logging.PercentStyle(fmt)
-            self._fmt = self._style._fmt
-
         # Cache the formatted traceback on the record, Logger will
         # respect our formatted copy
         if record.exc_info:
@@ -376,23 +364,42 @@ class ContextFormatter(logging.Formatter):
             if not exc_info[0]:
                 exc_info = None
 
+        # If we have an exception, format it to be included in the
+        # output.
         if exc_info:
-            # Include the exception summary in the line with the
+            # Build 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(
+            # and warning cases.
+            record.error_summary = traceback.format_exception_only(
                 exc_info[0],
                 exc_info[1],
-            )[0].rstrip().replace('%', '*')
-            record.msg = '{}: {}'.format(record.msg, suffix)
+            )[0].rstrip()
+            # If the format string does not say where to put the error
+            # text, add it to the end of the line. This allows
+            # operators to put %(error_summary)s in their default format
+            # line if they want more control over it.
+            if '%(error_summary)s' not in fmt:
+                fmt += ': %(error_summary)s'
             # Remove the local reference to the exception and
             # traceback to avoid a memory leak through the frame
             # references.
             del exc_info
+        else:
+            # Set the error text to the usual default placeholder
+            # value.
+            record.error_summary = '-'
+
+        if (record.levelno == logging.DEBUG and
+                self.conf.logging_debug_format_suffix):
+            fmt += " " + self.conf.logging_debug_format_suffix
+
+        self._compute_iso_time(record)
+
+        if sys.version_info < (3, 2):
+            self._fmt = fmt
+        else:
+            self._style = logging.PercentStyle(fmt)
+            self._fmt = self._style._fmt
 
         try:
             return logging.Formatter.format(self, record)

oslo_log/tests/unit/test_log.py

@@ -643,6 +643,47 @@ class ContextFormatterTestCase(LogTestBase):
                                                six.text_type(message))
         self.assertEqual(expected, self.stream.getvalue())
 
+    def test_exception_logging(self):
+        # NOTE(dhellmann): If there is an exception and %(error_summary)s
+        # does not appear in the format string, ensure that it is
+        # appended to the end of the log lines.
+        ctxt = _fake_context()
+        ctxt.request_id = six.text_type('99')
+        message = self.trans_fixture.lazy('test ' + six.unichr(128))
+        try:
+            raise RuntimeError('test_exception_logging')
+        except RuntimeError:
+            self.log.info(message, context=ctxt)
+        expected = 'RuntimeError: test_exception_logging\n'
+        self.assertTrue(self.stream.getvalue().endswith(expected))
+
+    def test_exception_logging_format_string(self):
+        # NOTE(dhellmann): If the format string includes
+        # %(error_summary)s then ensure the exception message ends up in
+        # that position in the output.
+        self.config(logging_context_format_string="A %(error_summary)s B")
+        ctxt = _fake_context()
+        ctxt.request_id = six.text_type('99')
+        message = self.trans_fixture.lazy('test ' + six.unichr(128))
+        try:
+            raise RuntimeError('test_exception_logging')
+        except RuntimeError:
+            self.log.info(message, context=ctxt)
+        expected = 'A RuntimeError: test_exception_logging'
+        self.assertTrue(self.stream.getvalue().startswith(expected))
+
+    def test_no_exception_logging_format_string(self):
+        # NOTE(dhellmann): If there is no exception but the format
+        # string includes %(error_summary)s then ensure the "-" is
+        # inserted.
+        self.config(logging_context_format_string="%(error_summary)s")
+        ctxt = _fake_context()
+        ctxt.request_id = six.text_type('99')
+        message = self.trans_fixture.lazy('test ' + six.unichr(128))
+        self.log.info(message, context=ctxt)
+        expected = '-\n'
+        self.assertTrue(self.stream.getvalue().startswith(expected))
+
     def test_unicode_conversion_in_adapter(self):
         ctxt = _fake_context()
         ctxt.request_id = six.text_type('99')

releasenotes/notes/always-add-error-text-715022964364ffa0.yaml

@@ -0,0 +1,8 @@
+---
+features:
+  - |
+    If the log format string includes ``%(error_summary)s``, it will be
+    replaced with a summary of the current error when there is one and
+    with "``-``" when there is no error.  If the log format string
+    does not include ``%(error_summary)s`` it will be appended to the end
+    of the line automatically, only if there is an error.