Repository: Azure/WALinuxAgent
Pull request #1771 (2020-01-31 22:40:08)

Enable timer for nosetests
<!-- DO NOT DELETE THIS TEMPLATE -->

## Description

Enable `nose-timer`, a plugin for `nosetests` that outputs the execution time of each test. This can help us identify and optimize slow running tests. The plugin is compatible with Python 2.7+.

Check out the Travis run on this PR for an example output.

<!--
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/1771)
<!-- Reviewable:end -->


codecov[bot]: # [Codecov](https://codecov.io/gh/Azure/WALinuxAgent/pull/1771?src=pr&el=h1) Report
> Merging [#1771](https://codecov.io/gh/Azure/WALinuxAgent/pull/1771?src=pr&el=desc) into [develop](https://codecov.io/gh/Azure/WALinuxAgent/commit/780a50457904dd48a818d35d984548546fc53c88?src=pr&el=desc) will **decrease** coverage by `<.01%`.
> The diff coverage is `n/a`.

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

```diff
@@             Coverage Diff             @@
##           develop    #1771      +/-   ##
===========================================
- Coverage    68.65%   68.64%   -0.01%     
===========================================
  Files           82       82              
  Lines        11732    11732              
  Branches      1645     1645              
===========================================
- Hits          8055     8054       -1     
  Misses        3326     3326              
- Partials       351      352       +1
```


| [Impacted Files](https://codecov.io/gh/Azure/WALinuxAgent/pull/1771?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [azurelinuxagent/common/protocol/wire.py](https://codecov.io/gh/Azure/WALinuxAgent/pull/1771/diff?src=pr&el=tree#diff-YXp1cmVsaW51eGFnZW50L2NvbW1vbi9wcm90b2NvbC93aXJlLnB5) | `77.68% <0%> (-0.1%)` | :arrow_down: |

------

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

pgombar: > thanks!
> do you know how to enable this on pycharm?

1. install the package `nose-timer`. in pycharm, go to Preferences > Project > Project Interpreter and search for it there.
2. set the command-line argument `--with-timer` in the Run/Debug Configurations menu like so:
![image](https://user-images.githubusercontent.com/9109950/73613953-8d462800-45af-11ea-9afb-45e2aa8b052a.png)


Patch:
diff --git a/.travis.yml b/.travis.yml
index fa672d3e..e1a250ef 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -3,7 +3,7 @@ os: linux
 dist: xenial
 language: python
 env:
-  - NOSEOPTS="--verbose" SETUPOPTS=""
+  - NOSEOPTS="--verbose --with-timer" SETUPOPTS=""
   # Add SETUPOPTS="check flake8" to enable flake8 checks
 
 matrix:
@@ -24,7 +24,7 @@ matrix:
     - python: 3.7
       env:
         - >-
-          NOSEOPTS="--verbose --with-coverage --cover-inclusive
+          NOSEOPTS="--verbose --with-coverage --with-timer --cover-inclusive
           --cover-min-percentage=60 --cover-branches
           --cover-package=azurelinuxagent --cover-xml"
           SETUPOPTS=""
diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py
index b66f315a..ae208925 100644
--- a/azurelinuxagent/ga/monitor.py
+++ b/azurelinuxagent/ga/monitor.py
@@ -234,11 +234,11 @@ class MonitorHandler(object):
         agent or the extensions. We don't have control over extension's events parameters, but we will override
         any values they might have set for sys_info parameters.
         """
-        if self.last_event_collection is None:
-            self.last_event_collection = datetime.datetime.utcnow() - MonitorHandler.EVENT_COLLECTION_PERIOD
+        try:
+            if self.last_event_collection is None:
+                self.last_event_collection = datetime.datetime.utcnow() - MonitorHandler.EVENT_COLLECTION_PERIOD
 
-        if datetime.datetime.utcnow() >= (self.last_event_collection + MonitorHandler.EVENT_COLLECTION_PERIOD):
-            try:
+            if datetime.datetime.utcnow() >= (self.last_event_collection + MonitorHandler.EVENT_COLLECTION_PERIOD):
                 event_list = TelemetryEventList()
                 event_dir = os.path.join(conf.get_lib_dir(), "events")
                 event_files = os.listdir(event_dir)
@@ -267,10 +267,10 @@ class MonitorHandler(object):
                     self.protocol.report_event(event_list)
                 except ProtocolError as e:
                     logger.error("{0}", ustr(e))
-            except Exception as e:
-                logger.warn("Failed to send events: {0}", ustr(e))
+        except Exception as e:
+            logger.warn("Failed to send events: {0}", ustr(e))
 
-            self.last_event_collection = datetime.datetime.utcnow()
+        self.last_event_collection = datetime.datetime.utcnow()
 
     def daemon(self, init_data=False):
 
@@ -285,15 +285,18 @@ class MonitorHandler(object):
                         MonitorHandler.HOST_PLUGIN_HEARTBEAT_PERIOD,
                         MonitorHandler.IMDS_HEARTBEAT_PERIOD).seconds
         while self.should_run:
-            self.protocol.update_host_plugin_from_goal_state()
-            self.send_telemetry_heartbeat()
-            self.poll_telemetry_metrics()
-            self.send_telemetry_metrics()   # This will be removed in favor of poll_telemetry_metrics() and it'll directly send the perf data for each cgroup.
-            self.collect_and_send_events()
-            self.send_host_plugin_heartbeat()
-            self.send_imds_heartbeat()
-            self.log_altered_network_configuration()
-            self.reset_loggers()
+            try:
+                self.protocol.update_host_plugin_from_goal_state()
+                self.send_telemetry_heartbeat()
+                self.poll_telemetry_metrics()
+                self.send_telemetry_metrics()   # This will be removed in favor of poll_telemetry_metrics() and it'll directly send the perf data for each cgroup.
+                self.collect_and_send_events()
+                self.send_host_plugin_heartbeat()
+                self.send_imds_heartbeat()
+                self.log_altered_network_configuration()
+                self.reset_loggers()
+            except Exception as e:
+                logger.warn("An error occurred in the monitor thread main loop; will skip the current iteration.\n{0}", ustr(e))
             time.sleep(min_delta)
 
     def reset_loggers(self):
@@ -302,16 +305,18 @@ class MonitorHandler(object):
         For reference, please check azurelinuxagent.common.logger.Logger and
         azurelinuxagent.common.event.EventLogger classes
         """
-        time_now = datetime.datetime.utcnow()
-        if not self.last_reset_loggers_time:
-            self.last_reset_loggers_time = time_now
+        try:
+            time_now = datetime.datetime.utcnow()
+            if not self.last_reset_loggers_time:
+                self.last_reset_loggers_time = time_now
 
-        if time_now >= (self.last_reset_loggers_time +
-                        MonitorHandler.RESET_LOGGERS_PERIOD):
-            try:
+            if time_now >= (self.last_reset_loggers_time + MonitorHandler.RESET_LOGGERS_PERIOD):
                 logger.reset_periodic()
-            finally:
-                self.last_reset_loggers_time = time_now
+
+        except Exception as e:
+            logger.warn("Failed to clear periodic loggers: {0}", ustr(e))
+
+        self.last_reset_loggers_time = time_now
 
     def add_sysinfo(self, event):
         """
@@ -345,11 +350,11 @@ class MonitorHandler(object):
         successfully called and validated a response in the last IMDS_HEALTH_PERIOD.
         """
 
-        if self.last_imds_heartbeat is None:
-            self.last_imds_heartbeat = datetime.datetime.utcnow() - MonitorHandler.IMDS_HEARTBEAT_PERIOD
+        try:
+            if self.last_imds_heartbeat is None:
+                self.last_imds_heartbeat = datetime.datetime.utcnow() - MonitorHandler.IMDS_HEARTBEAT_PERIOD
 
-        if datetime.datetime.utcnow() >= (self.last_imds_heartbeat + MonitorHandler.IMDS_HEARTBEAT_PERIOD):
-            try:
+            if datetime.datetime.utcnow() >= (self.last_imds_heartbeat + MonitorHandler.IMDS_HEARTBEAT_PERIOD):
                 is_currently_healthy, response = self.imds_client.validate()
 
                 if is_currently_healthy:
@@ -362,29 +367,29 @@ class MonitorHandler(object):
 
                 self.health_service.report_imds_status(is_healthy, response)
 
-            except Exception as e:
-                msg = "Exception sending imds heartbeat: {0}".format(ustr(e))
-                add_event(
-                    name=AGENT_NAME,
-                    version=CURRENT_VERSION,
-                    op=WALAEventOperation.ImdsHeartbeat,
-                    is_success=False,
-                    message=msg,
-                    log_event=False)
+        except Exception as e:
+            msg = "Exception sending imds heartbeat: {0}".format(ustr(e))
+            add_event(
+                name=AGENT_NAME,
+                version=CURRENT_VERSION,
+                op=WALAEventOperation.ImdsHeartbeat,
+                is_success=False,
+                message=msg,
+                log_event=False)
 
-            self.last_imds_heartbeat = datetime.datetime.utcnow()
+        self.last_imds_heartbeat = datetime.datetime.utcnow()
 
     def send_host_plugin_heartbeat(self):
         """
         Send a health signal every HOST_PLUGIN_HEARTBEAT_PERIOD. The signal is 'Healthy' when we have been able to
         communicate with HostGAPlugin at least once in the last HOST_PLUGIN_HEALTH_PERIOD.
         """
-        if self.last_host_plugin_heartbeat is None:
-            self.last_host_plugin_heartbeat = datetime.datetime.utcnow() - MonitorHandler.HOST_PLUGIN_HEARTBEAT_PERIOD
+        try:
+            if self.last_host_plugin_heartbeat is None:
+                self.last_host_plugin_heartbeat = datetime.datetime.utcnow() - MonitorHandler.HOST_PLUGIN_HEARTBEAT_PERIOD
 
-        if datetime.datetime.utcnow() >= (
+            if datetime.datetime.utcnow() >= (
                 self.last_host_plugin_heartbeat + MonitorHandler.HOST_PLUGIN_HEARTBEAT_PERIOD):
-            try:
                 host_plugin = self.protocol.client.get_host_plugin()
                 host_plugin.ensure_initialized()
                 is_currently_healthy = host_plugin.get_health()
@@ -408,25 +413,24 @@ class MonitorHandler(object):
                         message='{0} since successful heartbeat'.format(self.host_plugin_errorstate.fail_time),
                         log_event=False)
 
-            except Exception as e:
-                msg = "Exception sending host plugin heartbeat: {0}".format(ustr(e))
-                add_event(
-                    name=AGENT_NAME,
-                    version=CURRENT_VERSION,
-                    op=WALAEventOperation.HostPluginHeartbeat,
-                    is_success=False,
-                    message=msg,
-                    log_event=False)
+        except Exception as e:
+            msg = "Exception sending host plugin heartbeat: {0}".format(ustr(e))
+            add_event(
+                name=AGENT_NAME,
+                version=CURRENT_VERSION,
+                op=WALAEventOperation.HostPluginHeartbeat,
+                is_success=False,
+                message=msg,
+                log_event=False)
 
             self.last_host_plugin_heartbeat = datetime.datetime.utcnow()
 
     def send_telemetry_heartbeat(self):
+        try:
+            if self.last_telemetry_heartbeat is None:
+                self.last_telemetry_heartbeat = datetime.datetime.utcnow() - MonitorHandler.TELEMETRY_HEARTBEAT_PERIOD
 
-        if self.last_telemetry_heartbeat is None:
-            self.last_telemetry_heartbeat = datetime.datetime.utcnow() - MonitorHandler.TELEMETRY_HEARTBEAT_PERIOD
-
-        if datetime.datetime.utcnow() >= (self.last_telemetry_heartbeat + MonitorHandler.TELEMETRY_HEARTBEAT_PERIOD):
-            try:
+            if datetime.datetime.utcnow() >= (self.last_telemetry_heartbeat + MonitorHandler.TELEMETRY_HEARTBEAT_PERIOD):
                 io_errors = IOErrorCounter.get_and_reset()
                 hostplugin_errors = io_errors.get("hostplugin")
                 protocol_errors = io_errors.get("protocol")
@@ -442,10 +446,10 @@ class MonitorHandler(object):
                         is_success=True,
                         message=msg,
                         log_event=False)
-            except Exception as e:
-                logger.warn("Failed to send heartbeat: {0}", ustr(e))
+        except Exception as e:
+            logger.warn("Failed to send heartbeat: {0}", ustr(e))
 
-            self.last_telemetry_heartbeat = datetime.datetime.utcnow()
+        self.last_telemetry_heartbeat = datetime.datetime.utcnow()
 
     def poll_telemetry_metrics(self):
         """
@@ -461,7 +465,6 @@ class MonitorHandler(object):
             if time_now >= (self.last_cgroup_polling_telemetry +
                             MonitorHandler.CGROUP_TELEMETRY_POLLING_PERIOD):
                 metrics = CGroupsTelemetry.poll_all_tracked()
-                self.last_cgroup_polling_telemetry = time_now
 
                 if metrics:
                     for metric in metrics:
@@ -469,21 +472,22 @@ class MonitorHandler(object):
         except Exception as e:
             logger.warn("Could not poll all the tracked telemetry due to {0}", ustr(e))
 
+        self.last_cgroup_polling_telemetry = datetime.datetime.utcnow()
+
     def send_telemetry_metrics(self):
         """
         The send_telemetry_metrics would soon be removed in favor of sending performance metrics directly.
 
         :return:
         """
-        time_now = datetime.datetime.utcnow()
-
         try:  # If there is an issue in reporting, it should not take down whole monitor thread.
+            time_now = datetime.datetime.utcnow()
+
             if not self.last_cgroup_report_telemetry:
                 self.last_cgroup_report_telemetry = time_now
 
             if time_now >= (self.last_cgroup_report_telemetry + MonitorHandler.CGROUP_TELEMETRY_REPORTING_PERIOD):
                 performance_metrics = CGroupsTelemetry.report_all_tracked()
-                self.last_cgroup_report_telemetry = time_now
 
                 if performance_metrics:
                     message = generate_extension_metrics_telemetry_dictionary(schema_version=1.0,
@@ -497,6 +501,8 @@ class MonitorHandler(object):
         except Exception as e:
             logger.warn("Could not report all the tracked telemetry due to {0}", ustr(e))
 
+        self.last_cgroup_report_telemetry = datetime.datetime.utcnow()
+
     def log_altered_network_configuration(self):
         """
         Check various pieces of network configuration and, if altered since the last check, log the new state.


Test patch:
diff --git a/test-requirements.txt b/test-requirements.txt
index ad91e71c..d658cf0c 100644
--- a/test-requirements.txt
+++ b/test-requirements.txt
@@ -2,4 +2,5 @@ codecov
 coverage
 flake8; python_version >= '2.7'
 mock
-nose
\ No newline at end of file
+nose
+nose-timer; python_version >= '2.7'
\ No newline at end of file
diff --git a/tests/ga/test_monitor.py b/tests/ga/test_monitor.py
index ed9202f0..ad44934b 100644
--- a/tests/ga/test_monitor.py
+++ b/tests/ga/test_monitor.py
@@ -318,6 +318,38 @@ class TestMonitor(AgentTestCase):
         self.assertEqual(12, counter)
         os.environ.pop(CONTAINER_ID_ENV_VARIABLE)
 
+    def test_main_loop_should_handle_exceptions_retrieving_goal_state(self, *_):
+        monitor_handler = get_monitor_handler()
+
+        with patch("azurelinuxagent.common.logger.warn") as mock_warn:
+            with patch.object(monitor_handler, 'protocol') as mock_protocol:
+                mock_protocol.update_host_plugin_from_goal_state = Mock(side_effect=Exception("A TEST EXCEPTION"))
+
+                with patch("azurelinuxagent.ga.monitor.time") as mock_time:
+                    # time.sleep is called at the end of each iteration of the main loop; we use it to stop the
+                    # loop after a few iterations (this ensures that the test doesn't run for ever and is also
+                    # a check that the loop does not stop after the first error)
+                    def mock_sleep(_):
+                        mock_sleep.iterations += 1
+                        if mock_sleep.iterations >= 3:
+                            monitor_handler.stop()
+                    mock_sleep.iterations = 0
+
+                    mock_time.sleep = Mock(side_effect=mock_sleep)
+
+                    # run the main loop
+                    monitor_handler.daemon(init_data=False)
+
+                    self.assertEqual(mock_sleep.iterations, 3)
+
+                    self.assertEquals(mock_warn.call_count, 3)
+
+                    for call_args in mock_warn.call_args_list:
+                        args, kwargs = call_args
+                        self.assertEquals(len(args), 2)
+                        self.assertIn("A TEST EXCEPTION", args[1])
+
+
     @patch("azurelinuxagent.ga.monitor.MonitorHandler.send_telemetry_heartbeat")
     @patch("azurelinuxagent.ga.monitor.MonitorHandler.collect_and_send_events")
     @patch("azurelinuxagent.ga.monitor.MonitorHandler.send_host_plugin_heartbeat")