Repository: Azure/WALinuxAgent
Pull request #1737 (2019-12-16 05:15:42)

Set log time format
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description
datetime.isoformat() skips ms if ms=0, this PR replaces using isoformat with a specific ISO 8601 format that always include micro seconds.

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/1737)
<!-- Reviewable:end -->


codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1737?src=pr&el=h1) Report
> Merging [#1737](https://codecov.io/gh/Azure/WALinuxAgent/pull/1737?src=pr&el=desc) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/44d4de1079491337e9fbc98621f789ca41ee9ad1?src=pr&el=desc) will **not change** coverage.
> The diff coverage is `100%`.

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

```diff
@@           Coverage Diff            @@
##           develop    #1737   +/-   ##
========================================
  Coverage    68.21%   68.21%           
========================================
  Files           80       80           
  Lines        11617    11617           
  Branches      1635     1635           
========================================
  Hits          7924     7924           
  Misses        3356     3356           
  Partials       337      337
```


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

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1737?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/1737?src=pr&el=footer). Last update [44d4de1...e6b9103](https://codecov.io/gh/Azure/WALinuxAgent/pull/1737?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 89974cbd..99b86f30 100644
--- a/azurelinuxagent/common/logger.py
+++ b/azurelinuxagent/common/logger.py
@@ -127,7 +127,7 @@ class Logger(object):
         else:
             msg = msg_format
             # This format is based on ISO-8601, Z represents UTC (Zero offset)
-        time = datetime.utcnow().isoformat() + "Z"
+        time = datetime.utcnow().strftime(u'%Y-%m-%dT%H:%M:%S.%fZ')
         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 3d0fdffb..20c643e7 100644
--- a/tests/common/test_logger.py
+++ b/tests/common/test_logger.py
@@ -191,6 +191,30 @@ class TestLogger(AgentTestCase):
             # 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))
 
+    @patch("azurelinuxagent.common.logger.datetime")
+    def test_logger_should_log_micro_seconds(self, mock_dt):
+        # datetime.isoformat() skips ms if ms=0, this test ensures that ms is always set
+
+        file_name = "test.log"
+        file_path = os.path.join(self.tmp_dir, file_name)
+        test_logger = logger.Logger()
+        test_logger.add_appender(logger.AppenderType.FILE, logger.LogLevel.INFO, path=file_path)
+
+        ts_with_no_ms = datetime.utcnow().replace(microsecond=0)
+        mock_dt.utcnow = MagicMock(return_value=ts_with_no_ms)
+
+        test_logger.info("The time should contain milli-seconds")
+
+        with open(file_path, "r") as log_file:
+            log = log_file.read()
+            try:
+                time_in_file = datetime.strptime(log.split(logger.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 and has micro seconds in it")
+
+            self.assertEqual(ts_with_no_ms, time_in_file, "Timestamps dont match")
+
     def test_telemetry_logger(self):
         mock = MagicMock()
         appender = logger.TelemetryAppender(logger.LogLevel.WARNING, mock)