Configure logging module to always use UTC time.

Currently the python logging module will default to a local time which may
contain an TZ offset in the values it produces, but the logged time format
does not contain the offset. Switching to UTC time for logging produces
consistent values in the cloud-init.log file and avoids issues when the
timezone is changed during boot.

LP: #1713158

2 files changed, 63 insertions, 0 deletions

diff --git a/cloudinit/log.py b/cloudinit/log.py
index 3861709e..1d75c9ff 100644
--- a/cloudinit/log.py
+++ b/cloudinit/log.py
@@ -19,6 +19,8 @@ import sys
 import six
 from six import StringIO
 
+import time
+
 # Logging levels for easy access
 CRITICAL = logging.CRITICAL
 FATAL = logging.FATAL
@@ -32,6 +34,9 @@ NOTSET = logging.NOTSET
 # Default basic format
 DEF_CON_FORMAT = '%(asctime)s - %(filename)s[%(levelname)s]: %(message)s'
 
+# Always format logging timestamps as UTC time
+logging.Formatter.converter = time.gmtime
+
 
 def setupBasicLogging(level=DEBUG):
     root = logging.getLogger()
diff --git a/tests/unittests/test_log.py b/tests/unittests/test_log.py
new file mode 100644
index 00000000..68fb4b8d
--- /dev/null
+++ b/tests/unittests/test_log.py
@@ -0,0 +1,58 @@
+# This file is part of cloud-init. See LICENSE file for license information.
+
+"""Tests for cloudinit.log """
+
+from .helpers import CiTestCase
+from cloudinit.analyze.dump import CLOUD_INIT_ASCTIME_FMT
+from cloudinit import log as ci_logging
+import datetime
+import logging
+import six
+import time
+
+
+class TestCloudInitLogger(CiTestCase):
+
+    def setUp(self):
+        # set up a logger like cloud-init does in setupLogging, but instead
+        # of sys.stderr, we'll plug in a StringIO() object so we can see
+        # what gets logged
+        logging.Formatter.converter = time.gmtime
+        self.ci_logs = six.StringIO()
+        self.ci_root = logging.getLogger()
+        console = logging.StreamHandler(self.ci_logs)
+        console.setFormatter(logging.Formatter(ci_logging.DEF_CON_FORMAT))
+        console.setLevel(ci_logging.DEBUG)
+        self.ci_root.addHandler(console)
+        self.ci_root.setLevel(ci_logging.DEBUG)
+        self.LOG = logging.getLogger('test_cloudinit_logger')
+
+    def test_logger_uses_gmtime(self):
+        """Test that log message have timestamp in UTC (gmtime)"""
+
+        # Log a message, extract the timestamp from the log entry
+        # convert to datetime, and compare to a utc timestamp before
+        # and after the logged message.
+
+        # Due to loss of precision in the LOG timestamp, subtract and add
+        # time to the utc stamps for comparison
+        #
+        # utc_before: 2017-08-23 14:19:42.569299
+        # parsed dt : 2017-08-23 14:19:43.069000
+        # utc_after : 2017-08-23 14:19:43.570064
+
+        utc_before = datetime.datetime.utcnow() - datetime.timedelta(0, 0.5)
+        self.LOG.error('Test message')
+        utc_after = datetime.datetime.utcnow() + datetime.timedelta(0, 0.5)
+
+        # extract timestamp from log:
+        # 2017-08-23 14:19:43,069 - test_log.py[ERROR]: Test message
+        logstr = self.ci_logs.getvalue().splitlines()[0]
+        timestampstr = logstr.split(' - ')[0]
+        parsed_dt = datetime.datetime.strptime(timestampstr,
+                                               CLOUD_INIT_ASCTIME_FMT)
+
+        self.assertLess(utc_before, parsed_dt)
+        self.assertLess(parsed_dt, utc_after)
+        self.assertLess(utc_before, utc_after)
+        self.assertGreater(utc_after, parsed_dt)