Repository: Azure/WALinuxAgent
Pull request #1919 (2020-06-25 22:02:15)

Move AutoUpdate reporting to HeartBeat event
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description

1. AutoUpdate needs to be reported more frequently than just on system startup (#1907) in order to know how many VMs in our fleet are not updating due to potential issues or due to AutoUpdate being set to false.
2. Move AutoUpdate reporting to HeartBeat event which is emitted and logged locally every half an hour.
3. Emit HeartBeat in the beginning of the exthandlers thread.

Local log message:
`2020-06-25T21:01:19.140669Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.48.1 is running as the goal state agent [DEBUG HeartbeatCounter: 1;HeartbeatId: BC244091-DA90-476D-A49D-6184F6A4125D;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1]`


<!--
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).

codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919?src=pr&el=h1) Report
> Merging [#1919](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919?src=pr&el=desc) into [release-2.2.49](https://codecov.io/gh/Azure/WALinuxAgent/commit/9f3dca0194c5909acebcf236707651af4011d61e&el=desc) will **decrease** coverage by `0.01%`.
> The diff coverage is `100.00%`.

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

```diff
@@                Coverage Diff                 @@
##           release-2.2.49    #1919      +/-   ##
==================================================
- Coverage           69.47%   69.46%   -0.02%     
==================================================
  Files                  85       85              
  Lines               11870    11868       -2     
  Branches             1667     1667              
==================================================
- Hits                 8247     8244       -3     
- Misses               3252     3253       +1     
  Partials              371      371              
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/event.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9ldmVudC5weQ==) | `85.93% <ø> (-0.04%)` | :arrow_down: |
| [azurelinuxagent/ga/update.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2dhL3VwZGF0ZS5weQ==) | `87.61% <100.00%> (-0.18%)` | :arrow_down: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919?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/1919?src=pr&el=footer). Last update [9f3dca0...f2629f5](https://codecov.io/gh/Azure/WALinuxAgent/pull/1919?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index e5860d90..6b2fdb50 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -70,7 +70,6 @@ class WALAEventOperation:
     AgentBlacklisted = "AgentBlacklisted"
     AgentEnabled = "AgentEnabled"
     ArtifactsProfileBlob = "ArtifactsProfileBlob"
-    AutoUpdate = "AutoUpdate"
     CGroupsCleanUp = "CGroupsCleanUp"
     CGroupsDebug = "CGroupsDebug"
     CGroupsInfo = "CGroupsInfo"
@@ -180,7 +179,6 @@ class EventStatus(object):
 
 __event_status__ = EventStatus()
 __event_status_operations__ = [
-        WALAEventOperation.AutoUpdate,
         WALAEventOperation.ReportStatus
     ]
 
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index 77656525..6fec60ee 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -266,7 +266,7 @@ class UpdateHandler(object):
                 PY_VERSION_MINOR, PY_VERSION_MICRO)
             logger.info(os_info_msg)
             add_event(AGENT_NAME, op=WALAEventOperation.OSInfo, message=os_info_msg)
-
+            
             # Launch monitoring threads
             from azurelinuxagent.ga.monitor import get_monitor_handler
             monitor_thread = get_monitor_handler()
@@ -350,7 +350,6 @@ class UpdateHandler(object):
                             message="Incarnation {0}".format(exthandlers_handler.last_etag))
 
                 self._send_heartbeat_telemetry(protocol)
-
                 time.sleep(goal_state_interval)
 
         except Exception as e:
@@ -446,11 +445,6 @@ class UpdateHandler(object):
                 logger.info(message)
                 add_event(AGENT_NAME, op=WALAEventOperation.ConfigurationChange, message=message)
 
-            # Always report the value of AutoUpdate
-            auto_update_enabled = conf.get_autoupdate_enabled()
-            logger.info("AutoUpdate.Enabled: {0}}", auto_update_enabled)
-            add_event(op=WALAEventOperation.AutoUpdate, is_success=auto_update_enabled, log_event=False)
-
         except Exception as e:
             logger.warn("Failed to log changes in configuration: {0}", ustr(e))
 
@@ -672,7 +666,6 @@ class UpdateHandler(object):
     def _upgrade_available(self, protocol, base_version=CURRENT_VERSION):
         # Ignore new agents if updating is disabled
         if not conf.get_autoupdate_enabled():
-            logger.warn(u"Agent auto-update is disabled.")
             return False
 
         now = time.time()
@@ -756,13 +749,21 @@ class UpdateHandler(object):
 
         if datetime.utcnow() >= (self._last_telemetry_heartbeat + UpdateHandler.TELEMETRY_HEARTBEAT_PERIOD):
             dropped_packets = self.osutil.get_firewall_dropped_packets(protocol.get_endpoint())
-            msg = "{0};{1};{2};{3}".format(self._heartbeat_counter, self._heartbeat_id, dropped_packets, self._heartbeat_update_goal_state_error_count)
+            auto_update_enabled = 1 if conf.get_autoupdate_enabled() else 0
+            telemetry_msg = "{0};{1};{2};{3};{4}".format(self._heartbeat_counter, self._heartbeat_id, dropped_packets,
+                                                         self._heartbeat_update_goal_state_error_count, auto_update_enabled)
 
-            add_event(name=AGENT_NAME, version=CURRENT_VERSION, op=WALAEventOperation.HeartBeat, is_success=True, message=msg, log_event=False)
+            add_event(name=AGENT_NAME, version=CURRENT_VERSION, op=WALAEventOperation.HeartBeat, is_success=True,
+                      message=telemetry_msg, log_event=False)
             self._heartbeat_counter += 1
             self._heartbeat_update_goal_state_error_count = 0
 
-            logger.info(u"[HEARTBEAT] Agent {0} is running as the goal state agent", CURRENT_AGENT)
+            debug_log_msg = "[DEBUG HeartbeatCounter: {0};HeartbeatId: {1};DroppedPackets: {2};" \
+                            "UpdateGSErrors: {3};AutoUpdate: {4}]".format(self._heartbeat_counter,
+                                                                          self._heartbeat_id, dropped_packets,
+                                                                          self._heartbeat_update_goal_state_error_count,
+                                                                          auto_update_enabled)
+            logger.info(u"[HEARTBEAT] Agent {0} is running as the goal state agent {1}", CURRENT_AGENT, debug_log_msg)
             self._last_telemetry_heartbeat = datetime.utcnow()
 
 


Test patch:
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index 209b0524..c745ca6c 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -1476,10 +1476,8 @@ class TestUpdate(UpdateTestCase):
         update_handler.last_telemetry_heartbeat = datetime.utcnow() - timedelta(hours=1)
         update_handler._send_heartbeat_telemetry(mock_protocol)
         self.assertEqual(1, patch_add_event.call_count)
-        self.assertTrue(
-            any(call_args[0] == "[HEARTBEAT] Agent {0} is running as the goal state agent" for call_args in patch_info.call_args),
-            "The heartbeat was not written to the agent's log"
-        )
+        self.assertTrue(any(call_args[0] == "[HEARTBEAT] Agent {0} is running as the goal state agent {1}"
+                            for call_args in patch_info.call_args), "The heartbeat was not written to the agent's log")
 
 
 class MonitorThreadTest(AgentTestCase):