Repository: Azure/WALinuxAgent
Pull request #1716 (2019-11-21 00:49:31)

Added utc logging
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description
Currently the Linux agent logs in local time of the machine. Changing the logic to log in UTC.

Issue # <!-- if any -->
<!--
Please add an informative description that covers that changes made by the pull request. 
This checklist is used to make sure that common issues in a pull request are addressed.
This will expedite the process of getting your pull request merged and avoid extra work on your part to fix issues discovered during the review process.
-->

---

### PR information
- [ ] The title of the PR is clear and informative.
- [ ] There are a small number of commits, each of which has an informative message. This means that previously merged commits do not appear in the history of the PR. For information on cleaning up the commits in your pull request, [see this page](https://github.com/Azure/azure-powershell/blob/master/documentation/development-docs/cleaning-up-commits.md).
- [ ] Except for special cases involving multiple contributors, the PR is started from a fork of the main repository, not a branch.
- [ ] If applicable, the PR references the bug/issue that it fixes in the description.
- [ ] New Unit tests were added for the changes made and Travis.CI is passing.

### Quality of Code and Contribution Guidelines
- [ ] I have read the [contribution guidelines](https://github.com/Azure/WALinuxAgent/blob/master/.github/CONTRIBUTING.md).

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/azure/walinuxagent/1716)
<!-- Reviewable:end -->


codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=h1) Report
> :exclamation: No coverage uploaded for pull request base (`develop@87af104`). [Click here to learn what that means](https://docs.codecov.io/docs/error-reference#section-missing-base-commit).
> The diff coverage is `100%`.

[![Impacted file tree graph](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716/graphs/tree.svg?width=650&token=ae90E2KYCw&height=150&src=pr)](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##             develop    #1716   +/-   ##
==========================================
  Coverage           ?   68.02%           
==========================================
  Files              ?       80           
  Lines              ?    11573           
  Branches           ?     1624           
==========================================
  Hits               ?     7873           
  Misses             ?     3361           
  Partials           ?      339
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/logger.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9sb2dnZXIucHk=) | `88.66% <100%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=footer). Last update [87af104...af94354](https://codecov.io/gh/Azure/WALinuxAgent/pull/1716?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/azurelinuxagent/common/logger.py b/azurelinuxagent/common/logger.py
index 5d94afbf..43b0769e 100644
--- a/azurelinuxagent/common/logger.py
+++ b/azurelinuxagent/common/logger.py
@@ -88,7 +88,8 @@ class Logger(object):
             msg = msg_format.format(*args)
         else:
             msg = msg_format
-        time = datetime.now().strftime(u'%Y/%m/%d %H:%M:%S.%f')
+            # This format is based on ISO-8601, Z represents UTC (Zero offset)
+        time = datetime.utcnow().isoformat() + "Z"
         level_str = LogLevel.STRINGS[level]
         if self.prefix is not None:
             log_item = u"{0} {1} {2} {3}\n".format(time, level_str, self.prefix,


Test patch:
diff --git a/tests/common/test_logger.py b/tests/common/test_logger.py
index 116684d3..8159c287 100644
--- a/tests/common/test_logger.py
+++ b/tests/common/test_logger.py
@@ -16,10 +16,12 @@
 #
 
 import json
-from datetime import datetime
+import os
+from datetime import datetime, timedelta
 
 from azurelinuxagent.common import logger
 from azurelinuxagent.common.event import add_log_event
+from azurelinuxagent.common.logger import Logger, LogLevel
 from tests.tools import AgentTestCase, patch, MagicMock
 
 _MSG_INFO = "This is our test info logging message {0} {1}"
@@ -192,3 +194,23 @@ class TestLogger(AgentTestCase):
 
             elif x['name'] == 'Context3':
                 self.assertEqual(x['value'], '')
+
+    def test_logger_should_log_in_utc(self):
+        file_name = "test.log"
+        file_path = os.path.join(self.tmp_dir, file_name)
+        test_logger = Logger()
+        test_logger.add_appender(logger.AppenderType.FILE, logger.LogLevel.INFO, path=file_path)
+
+        before_write_utc = datetime.utcnow()
+        test_logger.info("The time should be in UTC")
+
+        with open(file_path, "r") as log_file:
+            log = log_file.read()
+            try:
+                time_in_file = datetime.strptime(log.split(LogLevel.STRINGS[logger.LogLevel.INFO])[0].strip()
+                                                 , u'%Y-%m-%dT%H:%M:%S.%fZ')
+            except ValueError:
+                self.fail("Ensure timestamp follows ISO-8601 format + 'Z' for UTC")
+
+            # If the time difference is > 5secs, there's a high probability that the time_in_file is in different TZ
+            self.assertTrue((time_in_file-before_write_utc) <= timedelta(seconds=5))