Merge "enable isotime for exceptions"

oslo_log/formatters.py

@@ -254,19 +254,7 @@ class ContextFormatter(logging.Formatter):
                 self.conf.logging_debug_format_suffix):
             fmt += " " + self.conf.logging_debug_format_suffix
 
-        # set iso8601 timestamp
+        self._compute_iso_time(record)
-        localtz = tz.tzlocal()
-        record.isotime = datetime.datetime.fromtimestamp(
-            record.created).replace(tzinfo=localtz).isoformat()
-        if record.created == int(record.created):
-            # NOTE(stpierre): when the timestamp includes no
-            # microseconds -- e.g., 1450274066.000000 -- then the
-            # microseconds aren't included in the isoformat() time. As
-            # a result, in literally one in a million cases
-            # isoformat() looks different. This adds microseconds when
-            # that happens.
-            record.isotime = "%s.000000%s" % (record.isotime[:-6],
-                                              record.isotime[-6:])
 
         if sys.version_info < (3, 2):
             self._fmt = fmt
@@ -292,9 +280,26 @@ class ContextFormatter(logging.Formatter):
         if self.conf.logging_exception_prefix.find('%(asctime)') != -1:
             record.asctime = self.formatTime(record, self.datefmt)
 
+        self._compute_iso_time(record)
+
         formatted_lines = []
         for line in lines:
             pl = self.conf.logging_exception_prefix % record.__dict__
             fl = '%s%s' % (pl, line)
             formatted_lines.append(fl)
         return '\n'.join(formatted_lines)
+
+    def _compute_iso_time(self, record):
+        # set iso8601 timestamp
+        localtz = tz.tzlocal()
+        record.isotime = datetime.datetime.fromtimestamp(
+            record.created).replace(tzinfo=localtz).isoformat()
+        if record.created == int(record.created):
+            # NOTE(stpierre): when the timestamp includes no
+            # microseconds -- e.g., 1450274066.000000 -- then the
+            # microseconds aren't included in the isoformat() time. As
+            # a result, in literally one in a million cases
+            # isoformat() looks different. This adds microseconds when
+            # that happens.
+            record.isotime = "%s.000000%s" % (record.isotime[:-6],
+                                              record.isotime[-6:])

oslo_log/tests/unit/test_log.py

@@ -528,6 +528,32 @@ class ExceptionLoggingTestCase(LogTestBase):
         log.setup(self.CONF, "test_excepthook_installed")
         self.assertTrue(sys.excepthook != sys.__excepthook__)
 
+    @mock.patch("datetime.datetime",
+                get_fake_datetime(
+                    datetime.datetime(2015, 12, 16, 13, 54, 26, 517893)))
+    @mock.patch("dateutil.tz.tzlocal", new=mock.Mock(return_value=tz.tzutc()))
+    def test_rfc5424_isotime_format(self):
+        self.config(
+            logging_default_format_string="%(isotime)s %(message)s",
+            logging_exception_prefix="%(isotime)s ",
+        )
+
+        product_name = 'somename'
+        exc_log = log.getLogger(product_name)
+
+        self._add_handler_with_cleanup(exc_log)
+        excepthook = log._create_logging_excepthook(product_name)
+
+        try:
+            raise Exception('Some error happened')
+        except Exception:
+            excepthook(*sys.exc_info())
+
+        expected_string = ("2015-12-16T13:54:26.517893+00:00 "
+                           "Exception: Some error happened")
+        self.assertIn(expected_string,
+                      self.stream.getvalue())
+
 
 class FancyRecordTestCase(LogTestBase):
     """Test how we handle fancy record keys that are not in the