Add ISO8601/RFC3339 timestamp to ContextFormatter

This is necessary to produce RFC5424-compliant log messages.

Change-Id: Id4754c18935940cc7c738e4a91880267fdeb808f

oslo_log/formatters.py

@@ -10,6 +10,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import datetime
 import itertools
 import logging
 import logging.config
@@ -18,6 +19,7 @@ import socket
 import sys
 import traceback
 
+from dateutil import tz
 import six
 from six import moves
 
@@ -141,11 +143,18 @@ class ContextFormatter(logging.Formatter):
     logging_debug_format_suffix to append extra formatting if the log level is
     debug.
 
-    For information about what variables are available for the formatter see:
+    The standard variables available to the formatter are listed at:
     http://docs.python.org/library/logging.html#formatter
 
-    If available, uses the context value stored in TLS - local.store.context
+    In addition to the standard variables, one custom variable is
+    available to both formatting string: `isotime` produces a
+    timestamp in ISO8601 format, suitable for producing
+    RFC5424-compliant log messages.
 
+    Furthermore, logging_context_format_string has access to all of
+    the data in a dict representation of the context.
+
+    If available, uses the context value stored in TLS - local.store.context
     """
 
     def __init__(self, *args, **kwargs):
@@ -245,6 +254,20 @@ class ContextFormatter(logging.Formatter):
                 self.conf.logging_debug_format_suffix):
             fmt += " " + self.conf.logging_debug_format_suffix
 
+        # 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:])
+
         if sys.version_info < (3, 2):
             self._fmt = fmt
         else:

oslo_log/tests/unit/test_log.py

@@ -14,6 +14,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import datetime
 import logging
 import os
 import platform
@@ -25,6 +26,7 @@ except ImportError:
 import tempfile
 import time
 
+from dateutil import tz
 import mock
 from oslo_config import cfg
 from oslo_config import fixture as fixture_config  # noqa
@@ -340,6 +342,15 @@ class JSONFormatterTestCase(LogTestBase):
         self.assertTrue(data['traceback'])
 
 
+def get_fake_datetime(retval):
+    class FakeDateTime(datetime.datetime):
+        @classmethod
+        def fromtimestamp(cls, timestamp):
+            return retval
+
+    return FakeDateTime
+
+
 class ContextFormatterTestCase(LogTestBase):
     def setUp(self):
         super(ContextFormatterTestCase, self).setUp()
@@ -463,6 +474,35 @@ class ContextFormatterTestCase(LogTestBase):
                      six.text_type(message)))
         self.assertEqual(expected, self.stream.getvalue())
 
+    @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")
+
+        message = "test"
+        expected = "2015-12-16T13:54:26.517893+00:00 %s\n" % message
+
+        self.log.info(message)
+
+        self.assertEqual(expected, self.stream.getvalue())
+
+    @mock.patch("datetime.datetime",
+                get_fake_datetime(
+                    datetime.datetime(2015, 12, 16, 13, 54, 26)))
+    @mock.patch("time.time", new=mock.Mock(return_value=1450274066.000000))
+    @mock.patch("dateutil.tz.tzlocal", new=mock.Mock(return_value=tz.tzutc()))
+    def test_rfc5424_isotime_format_no_microseconds(self):
+        self.config(logging_default_format_string="%(isotime)s %(message)s")
+
+        message = "test"
+        expected = "2015-12-16T13:54:26.000000+00:00 %s\n" % message
+
+        self.log.info(message)
+
+        self.assertEqual(expected, self.stream.getvalue())
+
 
 class ExceptionLoggingTestCase(LogTestBase):
     """Test that Exceptions are logged."""

requirements.txt

@@ -12,3 +12,4 @@ oslo.utils>=2.8.0 # Apache-2.0
 oslo.serialization>=1.10.0 # Apache-2.0
 debtcollector>=0.3.0 # Apache-2.0
 pyinotify>=0.9.6;sys_platform!='win32' and sys_platform!='darwin' and sys_platform!='sunos5' # MIT
+python-dateutil>=2.4.2