Merge ~raharper/cloud-init:logging-gmtime into cloud-init:master

[Ryan Harper]

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

[Server Team CI bot (server-team-bot)]

FAILED: Continuous integration, rev:e8c2885ff24e74af027dc297bed85c1d744c039c
https://jenkins.ubuntu.com/server/job/cloud-init-ci/149/
Executed test runs:
    SUCCESS: Checkout
    FAILED: Unit & Style Tests

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/149/rebuild

review: Needs Fixing (continuous-integration)

[Chad Smith (chad.smith)]

Looks good, I'm going to keep beating the "unit test coverage" drum on this. Can we add an initial unit test for log in
cloudinit/tests/test_log for this? I'd like to get to a point where we have at least some unit test coverage on every module in cloudinit.
Maybe this nit isn't worth it though, your call.

I tested on systems w/ localtime set mountain and things look good.

review: Approve

[Chad Smith (chad.smith)]

minor flake8 fix as you'll see from CI

[Scott Moser (smoser)]

lets add a unit test and then i approve.

just do a log, and verify the format comes out correctly.

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:89508f822bfb81f831bf04bad03175c482ef994b
https://jenkins.ubuntu.com/server/job/cloud-init-ci/187/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    SUCCESS: MAAS Compatability Testing
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/187/rebuild

review: Approve (continuous-integration)

[Scott Moser (smoser)]

I think your test case has fence post errors at the end of a minute. I, if we read it now() in the 59th second and the log message happens in the next second the test will fail. Right?

One way to combat this would be to get a before timestamp and an after timestamp. Then parse the log message time stamp and assert that before >= log >= after.

[Ryan Harper (raharper)]

On Tue, Aug 22, 2017 at 10:17 PM, Scott Moser <email address hidden> wrote:

> I think your test case has fence post errors at the end of a minute. I, if
> we read it now() in the 59th second and the log message happens in the next
> second the test will fail. Right?
>
> One way to combat this would be to get a before timestamp and an after
> timestamp. Then parse the log message time stamp and assert that before >=
> log >= after.
>

Good suggestion. I'll fix

>
> --
> https://code.launchpad.net/~raharper/cloud-init/+git/
> cloud-init/+merge/329122
> You are the owner of ~raharper/cloud-init:logging-gmtime.
>

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:7c790cbcc882dc164a8fbfdb0b352c18b74614b3
https://jenkins.ubuntu.com/server/job/cloud-init-ci/189/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    SUCCESS: MAAS Compatability Testing
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/189/rebuild

review: Approve (continuous-integration)

[Scott Moser (smoser)]

As long as AssertGreater and friends work in a python2.6 (tools/run-centos 6) i approve.
just make sure of that and then merge.
thanks!
(i do not know that they don't, i just hadn't used these before).

review: Approve

diff --git a/cloudinit/log.py b/cloudinit/log.py
index 3861709..1d75c9f 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 0000000..68fb4b8
--- /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)