Repository: Azure/WALinuxAgent (python)

Issue:
ExtensionProcessing emits Unnecessary Transient Events
The ExtensionProcessing telemetry event is emitted every time the agent fails to get goal state.  This is unnecessarily noisy, and does not actually indicate any issue with the agent.  Please use the `ErrorState` class just as was done for ReportStatus to make this a more meaningful value.


Pull request description:
Telemetry updates
- fixes #1178 
- switches enduring report status failures to `ReportStatusExtended`

Patch:
diff --git a/.vscode/settings.json b/.vscode/settings.json
new file mode 100644
index 00000000..26df38bf
--- /dev/null
+++ b/.vscode/settings.json
@@ -0,0 +1,3 @@
+{
+    "python.linting.enabled": false
+}
\ No newline at end of file
diff --git a/azurelinuxagent/common/errorstate.py b/azurelinuxagent/common/errorstate.py
index 750aa77b..52e2ddd5 100644
--- a/azurelinuxagent/common/errorstate.py
+++ b/azurelinuxagent/common/errorstate.py
@@ -1,10 +1,10 @@
 from datetime import datetime, timedelta
 
-ERROR_STATE_DELTA = timedelta(minutes=15)
-
+ERROR_STATE_DELTA_DEFAULT = timedelta(minutes=15)
+ERROR_STATE_DELTA_INSTALL = timedelta(minutes=5)
 
 class ErrorState(object):
-    def __init__(self, min_timedelta = ERROR_STATE_DELTA):
+    def __init__(self, min_timedelta=ERROR_STATE_DELTA_DEFAULT):
         self.min_timedelta = min_timedelta
 
         self.count = 0
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index afdbc222..1c26a139 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -52,6 +52,7 @@ class WALAEventOperation:
     Enable = "Enable"
     ExtensionProcessing = "ExtensionProcessing"
     Firewall = "Firewall"
+    GetArtifactExtended = "GetArtifactExtended"
     HealthCheck = "HealthCheck"
     HeartBeat = "HeartBeat"
     HostPlugin = "HostPlugin"
@@ -64,6 +65,7 @@ class WALAEventOperation:
     Provision = "Provision"
     ProvisionGuestAgent = "ProvisionGuestAgent"
     ReportStatus = "ReportStatus"
+    ReportStatusExtended = "ReportStatusExtended"
     Restart = "Restart"
     SkipUpdate = "SkipUpdate"
     UnhandledError = "UnhandledError"
diff --git a/azurelinuxagent/common/osutil/default.py b/azurelinuxagent/common/osutil/default.py
index 0d637b54..d08daea1 100644
--- a/azurelinuxagent/common/osutil/default.py
+++ b/azurelinuxagent/common/osutil/default.py
@@ -662,12 +662,12 @@ class DefaultOSUtil(object):
 
     def get_mac_addr(self):
         """
-        Convienience function, returns mac addr bound to
+        Convenience function, returns mac addr bound to
         first non-loopback interface.
         """
-        ifname=''
-        while len(ifname) < 2 :
-            ifname=self.get_first_if()[0]
+        ifname = ''
+        while len(ifname) < 2:
+            ifname = self.get_first_if()[0]
         addr = self.get_if_mac(ifname)
         return textutil.hexstr_to_bytearray(addr)
 
@@ -737,16 +737,15 @@ class DefaultOSUtil(object):
         if primary in ifaces:
             return primary, ifaces[primary]
 
-        logger.warn(('Primary interface {0} not found in ifconf list'), primary)
+        logger.warn('Primary interface {0} not found in ifconf list', primary)
         for iface_name in ifaces.keys():
             if not self.is_loopback(iface_name):
                 if not self.disable_route_warning:
                     logger.info("Choosing non-primary {0}".format(iface_name))
                 return iface_name, ifaces[iface_name]
 
-        msg = 'No non-loopback interface found in ifconf list'
-        logger.warn(msg)
-        raise Exception(msg)
+        logger.warn('No non-loopback interface found in ifconf list')
+        return '', ''
 
 
     def get_primary_interface(self):
@@ -908,7 +907,10 @@ class DefaultOSUtil(object):
         return True
 
     def get_if_name(self):
-        return self.get_first_if()[0]
+        ifname = ''
+        while len(ifname) < 2:
+            ifname = self.get_first_if()[0]
+        return ifname
 
     def get_ip4_addr(self):
         return self.get_first_if()[1]
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index 8bdbe065..04647721 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -36,9 +36,9 @@ import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
 import azurelinuxagent.common.utils.fileutil as fileutil
 import azurelinuxagent.common.version as version
-from azurelinuxagent.common.errorstate import ErrorState, ERROR_STATE_DELTA
+from azurelinuxagent.common.errorstate import ErrorState, ERROR_STATE_DELTA_DEFAULT, ERROR_STATE_DELTA_INSTALL
 
-from azurelinuxagent.common.event import add_event, WALAEventOperation, elapsed_milliseconds
+from azurelinuxagent.common.event import add_event, WALAEventOperation, elapsed_milliseconds, report_event
 from azurelinuxagent.common.exception import ExtensionError, ProtocolError
 from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.protocol.restapi import ExtHandlerStatus, \
@@ -191,21 +191,28 @@ class ExtHandlersHandler(object):
         self.log_process = False
 
         self.report_status_error_state = ErrorState()
+        self.get_artifact_error_state = ErrorState(min_timedelta=ERROR_STATE_DELTA_INSTALL)
 
     def run(self):
         self.ext_handlers, etag = None, None
         try:
             self.protocol = self.protocol_util.get_protocol()
             self.ext_handlers, etag = self.protocol.get_ext_handlers()
+            self.get_artifact_error_state.reset()
         except Exception as e:
-            msg = u"Exception retrieving extension handlers: {0}".format(
-                ustr(e))
-            logger.warn(msg)
-            add_event(AGENT_NAME,
-                      version=CURRENT_VERSION,
-                      op=WALAEventOperation.ExtensionProcessing,
-                      is_success=False,
-                      message=msg)
+            msg = u"Exception retrieving extension handlers: {0}".format(ustr(e))
+            self.get_artifact_error_state.incr()
+
+            if self.get_artifact_error_state.is_triggered():
+                add_event(AGENT_NAME,
+                          version=CURRENT_VERSION,
+                          op=WALAEventOperation.GetArtifactExtended,
+                          is_success=False,
+                          message="Failed to get extension artifact for over "
+                                  "{0): {1}".format(self.get_artifact_error_state.min_timedelta, msg))
+                self.get_artifact_error_state.reset()
+            else:
+                logger.warn(msg)
             return
 
         try:
@@ -352,6 +359,7 @@ class ExtHandlersHandler(object):
 
             self.set_log_upgrade_guid(ext_handler, True)
             ext_handler_i.decide_version(target_state=state)
+            self.get_artifact_error_state.reset()
             if not ext_handler_i.is_upgrade and self.last_etag == etag:
                 if self.log_etag:
                     ext_handler_i.logger.verbose("Version {0} is current for etag {1}",
@@ -380,8 +388,18 @@ class ExtHandlersHandler(object):
                 message = u"Unknown ext handler state:{0}".format(state)
                 raise ExtensionError(message)
         except Exception as e:
-            ext_handler_i.set_handler_status(message=ustr(e), code=-1)
-            ext_handler_i.report_event(message=ustr(e), is_success=False)
+            msg = ustr(e)
+            ext_handler_i.set_handler_status(message=msg, code=-1)
+
+            self.get_artifact_error_state.incr()
+            if self.get_artifact_error_state.is_triggered():
+                report_event(op=WALAEventOperation.GetArtifactExtended,
+                             message="Failed to get artifact for over "
+                                     "{0}: {1}".format(self.get_artifact_error_state.min_timedelta, msg),
+                             is_success=False)
+                self.get_artifact_error_state.reset()
+            else:
+                ext_handler_i.logger.warn(msg)
     
     def handle_enable(self, ext_handler_i):
         self.log_process = True
@@ -468,11 +486,11 @@ class ExtHandlersHandler(object):
 
         if self.report_status_error_state.is_triggered():
             message = "Failed to report vm agent status for more than {0}"\
-                .format(ERROR_STATE_DELTA)
+                .format(self.report_status_error_state.min_timedelta)
 
             add_event(AGENT_NAME,
                 version=CURRENT_VERSION,
-                op=WALAEventOperation.ExtensionProcessing,
+                op=WALAEventOperation.ReportStatusExtended,
                 is_success=False,
                 message=message)
 


Test patch:
diff --git a/tests/common/osutil/test_default.py b/tests/common/osutil/test_default.py
index cbd01ee0..7db80271 100644
--- a/tests/common/osutil/test_default.py
+++ b/tests/common/osutil/test_default.py
@@ -124,7 +124,7 @@ class TestOSUtil(AgentTestCase):
         fake_ifaces = {'lo':'127.0.0.1'}
         with patch.object(osutil.DefaultOSUtil, 'get_primary_interface', return_value='bogus0'):
             with patch.object(osutil.DefaultOSUtil, '_get_all_interfaces', return_value=fake_ifaces):
-                self.assertRaises(Exception, osutil.DefaultOSUtil().get_first_if)
+                self.assertEqual(('', ''), osutil.DefaultOSUtil().get_first_if())
 
     def test_isloopback(self):
         self.assertTrue(osutil.DefaultOSUtil().is_loopback('lo'))
diff --git a/tests/ga/test_extension.py b/tests/ga/test_extension.py
index 276d57e7..7cb51668 100644
--- a/tests/ga/test_extension.py
+++ b/tests/ga/test_extension.py
@@ -541,16 +541,44 @@ class TestExtension(AgentTestCase):
         self._assert_ext_status(protocol.report_ext_status, "success", 0)
 
     @patch('azurelinuxagent.ga.exthandlers.add_event')
-    def test_ext_handler_download_failure(self, mock_add_event, *args):
+    def test_ext_handler_download_failure_transient(self, mock_add_event, *args):
         test_data = WireProtocolData(DATA_FILE)
         exthandlers_handler, protocol = self._create_mock(test_data, *args)
         protocol.download_ext_handler_pkg = Mock(side_effect=ProtocolError)
 
         exthandlers_handler.run()
+        self.assertEquals(0, mock_add_event.call_count)
+
+    @patch('azurelinuxagent.common.errorstate.ErrorState.is_triggered')
+    @patch('azurelinuxagent.ga.exthandlers.add_event')
+    def test_ext_handler_report_status_permanent(self, mock_add_event, mock_error_state, *args):
+        test_data = WireProtocolData(DATA_FILE)
+        exthandlers_handler, protocol = self._create_mock(test_data, *args)
+        protocol.report_vm_status = Mock(side_effect=ProtocolError)
+
+        mock_error_state.return_value = True
+        exthandlers_handler.run()
+        self.assertEquals(5, mock_add_event.call_count)
         args, kw = mock_add_event.call_args
         self.assertEquals(False, kw['is_success'])
-        self.assertEquals("OSTCExtensions.ExampleHandlerLinux", kw['name'])
-        self.assertEquals("Download", kw['op'])
+        self.assertTrue("Failed to report vm agent status" in kw['message'])
+        self.assertEquals("ReportStatusExtended", kw['op'])
+
+    @patch('azurelinuxagent.common.errorstate.ErrorState.is_triggered')
+    @patch('azurelinuxagent.common.event.add_event')
+    def test_ext_handler_download_failure_permanent(self, mock_add_event, mock_error_state, *args):
+        test_data = WireProtocolData(DATA_FILE)
+        exthandlers_handler, protocol = self._create_mock(test_data, *args)
+        protocol.get_ext_handler_pkgs = Mock(side_effect=ProtocolError)
+
+        mock_error_state.return_value = True
+        exthandlers_handler.run()
+        self.assertEquals(1, mock_add_event.call_count)
+        args, kw = mock_add_event.call_args_list[0]
+        self.assertEquals(False, kw['is_success'])
+        self.assertTrue("Failed to get ext handler pkgs" in kw['message'])
+        self.assertTrue("Failed to get artifact" in kw['message'])
+        self.assertEquals("GetArtifactExtended", kw['op'])
 
     @patch('azurelinuxagent.ga.exthandlers.fileutil')
     def test_ext_handler_io_error(self, mock_fileutil, *args):