Repository: Azure/WALinuxAgent
Pull request #700 (2017-05-04 19:33:20)

Correct HandlerState status check (#699) and clean-up reported events
Correct HandlerState status check #699.
Add GoalState telemetry #470.
Clean-up reported events
Signed-off-by: Brendan Dixon <brendandixon@me.com>


Patch:
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index ce79adfa..6d1cc6da 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -24,7 +24,11 @@ import time
 import datetime
 import threading
 import platform
+
+from datetime import datetime
+
 import azurelinuxagent.common.logger as logger
+
 from azurelinuxagent.common.exception import EventError, ProtocolError
 from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.protocol.restapi import TelemetryEventParam, \
@@ -45,6 +49,7 @@ class WALAEventOperation:
     HeartBeat = "HeartBeat"
     Install = "Install"
     InitializeHostPlugin = "InitializeHostPlugin"
+    ProcessGoalState = "ProcessGoalState"
     Provision = "Provision"
     ReportStatus = "ReportStatus"
     Restart = "Restart"
@@ -111,6 +116,11 @@ class EventLogger(object):
 __event_logger__ = EventLogger()
 
 
+def elapsed_milliseconds(utc_start):
+    d = datetime.utcnow() - utc_start
+    return int(((d.days * 24 * 60 * 60 + d.seconds) * 1000) + \
+                    (d.microseconds / 1000.0))
+
 def report_event(op, is_success=True, message=''):
     from azurelinuxagent.common.version import AGENT_NAME, CURRENT_VERSION
     add_event(AGENT_NAME,
diff --git a/azurelinuxagent/common/protocol/wire.py b/azurelinuxagent/common/protocol/wire.py
index 11a18f93..f94c6926 100644
--- a/azurelinuxagent/common/protocol/wire.py
+++ b/azurelinuxagent/common/protocol/wire.py
@@ -21,16 +21,18 @@ import os
 import re
 import time
 import xml.sax.saxutils as saxutils
+
 import azurelinuxagent.common.conf as conf
+import azurelinuxagent.common.utils.fileutil as fileutil
+import azurelinuxagent.common.utils.textutil as textutil
+
 from azurelinuxagent.common.exception import ProtocolNotFoundError
 from azurelinuxagent.common.future import httpclient, bytebuffer
+from azurelinuxagent.common.protocol.hostplugin import HostPluginProtocol
+from azurelinuxagent.common.protocol.restapi import *
+from azurelinuxagent.common.utils.cryptutil import CryptUtil
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, \
     findtext, getattrib, gettext, remove_bom, get_bytes_from_pem, parse_json
-import azurelinuxagent.common.utils.fileutil as fileutil
-import azurelinuxagent.common.utils.textutil as textutil
-from azurelinuxagent.common.utils.cryptutil import CryptUtil
-from azurelinuxagent.common.protocol.restapi import *
-from azurelinuxagent.common.protocol.hostplugin import HostPluginProtocol
 
 VERSION_INFO_URI = "http://{0}/?comp=versions"
 GOAL_STATE_URI = "http://{0}/machine/?comp=goalstate"
@@ -376,28 +378,20 @@ class StatusBlob(object):
         self.type = blob_type
 
     def upload(self, url):
-        # TODO upload extension only if content has changed
-        upload_successful = False
         try:
+            if not self.type in ["BlockBlob", "PageBlob"]:
+                raise ProtocolError("Illegal blob type: {0}".format(self.type))
+
             if self.type == "BlockBlob":
                 self.put_block_blob(url, self.data)
-            elif self.type == "PageBlob":
-                self.put_page_blob(url, self.data)
-            elif self.type == "" or self.type is None:
-                raise ProtocolError("Missing blob type")
             else:
-                raise ProtocolError("Unknown blob type: {0}".format(self.type))
-        except HttpError as e:
-            message = "Initial upload failed [{0}]".format(e)
-            logger.warn(message)
-            from azurelinuxagent.common.event import WALAEventOperation, report_event
-            report_event(op=WALAEventOperation.ReportStatus,
-                         is_success=False,
-                         message=message)
-        else:
-            logger.verbose("Uploading status blob succeeded")
-            upload_successful = True
-        return upload_successful
+                self.put_page_blob(url, self.data)
+            return True
+
+        except Exception as e:
+            logger.verbose("Initial status upload failed: {0}", e)
+
+        return False
 
     def get_block_blob_headers(self, blob_size):
         return {
@@ -829,15 +823,33 @@ class WireClient(object):
 
     def upload_status_blob(self):
         ext_conf = self.get_ext_conf()
-        if ext_conf.status_upload_blob is not None:
-            uploaded = False
+
+        blob_uri = ext_conf.status_upload_blob
+        blob_type = ext_conf.status_upload_blob_type
+
+        if blob_uri is not None:
+
+            if not blob_type in ["BlockBlob", "PageBlob"]:
+                self.report_status_event(
+                    "{0} is an unsupported blob type",
+                    blob_type)
+                return
+
             try:
-                self.status_blob.prepare(ext_conf.status_upload_blob_type)
-                if not HostPluginProtocol.is_default_channel():
-                    uploaded = self.status_blob.upload(ext_conf.status_upload_blob)
-            except (HttpError, ProtocolError):
-                # errors have already been logged
-                pass
+                self.status_blob.prepare(blob_type)
+            except Exception as e:
+                self.report_status_event(
+                    "Exception creating status blob: {0}",
+                    e)
+                return
+
+            uploaded = False
+            if not HostPluginProtocol.is_default_channel():
+                try:
+                    uploaded = self.status_blob.upload(blob_uri)
+                except HttpError as e:
+                    pass
+
             if not uploaded:
                 host = self.get_host_plugin()
                 host.put_vm_status(self.status_blob,
@@ -932,6 +944,16 @@ class WireClient(object):
             if len(buf[provider_id]) > 0:
                 self.send_event(provider_id, buf[provider_id])
 
+    def report_status_event(self, message, *args):
+        from azurelinuxagent.common.event import report_event, \
+                WALAEventOperation
+
+        message = message.format(*args)
+        logger.warn(message)
+        report_event(op=WALAEventOperation.ReportStatus,
+                    is_success=False,
+                    message=message)
+
     def get_header(self):
         return {
             "x-ms-agent-name": "WALinuxAgent",
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index e5914fd9..b44ed6d4 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -553,26 +553,14 @@ class ExtHandlerInstance(object):
 
             separator = path.rfind('-')
             version = FlexibleVersion(path[separator+1:])
-            existing_state = os.path.join(path, 'config', 'HandlerState')
-            should_remove = False
+            state_path = os.path.join(path, 'config', 'HandlerState')
 
-            if not os.path.exists(existing_state):
-                should_remove = True
-            else:
-                with open(existing_state) as fh:
-                    existing_state_text = fh.read()
-                    if existing_state_text is None or \
-                       existing_state == ExtHandlerState.NotInstalled:
-                        should_remove = True
-
-            if should_remove:
-                logger.warn("Extension directory does not contain a valid "
-                            "status, removing [{0}]".format(path))
-                shutil.rmtree(path, ignore_errors=True)
+            if not os.path.exists(state_path) or \
+                fileutil.read_file(state_path) == \
+                    ExtHandlerState.NotInstalled:
+                logger.verbose("Ignoring version of uninstalled extension: "
+                    "{0}".format(path))
                 continue
-            else:
-                logger.verbose("Extension directory contains valid status "
-                               "[{0}]".format(path))
 
             if lastest_version is None or lastest_version < version:
                 lastest_version = version
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index 203bb417..8d9478fb 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -30,13 +30,17 @@ import time
 import traceback
 import zipfile
 
+from datetime import datetime
+
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
 import azurelinuxagent.common.utils.fileutil as fileutil
 import azurelinuxagent.common.utils.restutil as restutil
 import azurelinuxagent.common.utils.textutil as textutil
 
-from azurelinuxagent.common.event import add_event, WALAEventOperation
+from azurelinuxagent.common.event import add_event, \
+                                    elapsed_milliseconds, \
+                                    WALAEventOperation
 from azurelinuxagent.common.exception import UpdateError, ProtocolError
 from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.osutil import get_osutil
@@ -69,7 +73,6 @@ ORPHAN_WAIT_INTERVAL = 15 * 60 * 60
 
 AGENT_SENTINAL_FILE = "current_version"
 
-
 def get_update_handler():
     return UpdateHandler()
 
@@ -254,7 +257,16 @@ class UpdateHandler(object):
                             self.agents[0].name)
                     break
 
+                utc_start = datetime.utcnow()
+
                 exthandlers_handler.run()
+
+                add_event(
+                    AGENT_NAME,
+                    version=CURRENT_VERSION,
+                    op=WALAEventOperation.ProcessGoalState,
+                    is_success=True,
+                    duration=elapsed_milliseconds(utc_start))
                 
                 time.sleep(GOAL_STATE_INTERVAL)
 


Test patch:
diff --git a/tests/protocol/test_hostplugin.py b/tests/protocol/test_hostplugin.py
index ef91998b..e203615a 100644
--- a/tests/protocol/test_hostplugin.py
+++ b/tests/protocol/test_hostplugin.py
@@ -33,6 +33,7 @@ import azurelinuxagent.common.protocol.wire as wire
 import azurelinuxagent.common.protocol.hostplugin as hostplugin
 
 from azurelinuxagent.common import event
+from azurelinuxagent.common.exception import ProtocolError, HttpError
 from azurelinuxagent.common.protocol.hostplugin import API_VERSION
 from azurelinuxagent.common.utils import restutil
 
@@ -128,8 +129,10 @@ class TestHostPlugin(AgentTestCase):
                     wire_protocol_client.get_goal_state = Mock(return_value=test_goal_state)
                     wire_protocol_client.ext_conf = wire.ExtensionsConfig(None)
                     wire_protocol_client.ext_conf.status_upload_blob = sas_url
+                    wire_protocol_client.ext_conf.status_upload_blob_type = page_blob_type
                     wire_protocol_client.status_blob.set_vm_status(status)
                     wire_protocol_client.upload_status_blob()
+                    self.assertEqual(patch_upload.call_count, 1)
                     self.assertTrue(patch_put.call_count == 1,
                                     "Fallback was not engaged")
                     self.assertTrue(patch_put.call_args[0][0] == sas_url)
@@ -156,6 +159,7 @@ class TestHostPlugin(AgentTestCase):
                     client.get_goal_state = Mock(return_value=test_goal_state)
                     client.ext_conf = wire.ExtensionsConfig(None)
                     client.ext_conf.status_upload_blob = sas_url
+                    client.ext_conf.status_upload_blob_type = page_blob_type
                     client.status_blob.set_vm_status(status)
                     client.upload_status_blob()
                     self.assertTrue(patch_put.call_count == 1,
diff --git a/tests/protocol/test_wire.py b/tests/protocol/test_wire.py
index c9799fdd..016dc348 100644
--- a/tests/protocol/test_wire.py
+++ b/tests/protocol/test_wire.py
@@ -152,11 +152,12 @@ class TestWireProtocolGetters(AgentTestCase):
         wire_protocol_client = WireProtocol(wireserver_url).client
         wire_protocol_client.ext_conf = ExtensionsConfig(None)
         wire_protocol_client.ext_conf.status_upload_blob = testurl
+        wire_protocol_client.ext_conf.status_upload_blob_type = testtype
         wire_protocol_client.status_blob.vm_status = vmstatus
 
         with patch.object(WireClient, "get_goal_state") as patch_get_goal_state:
             with patch.object(HostPluginProtocol, "put_vm_status") as patch_host_ga_plugin_upload:
-                with patch.object(StatusBlob, "upload", return_value=True) as patch_default_upload:
+                with patch.object(StatusBlob, "upload") as patch_default_upload:
                     HostPluginProtocol.set_default_channel(False)
                     wire_protocol_client.upload_status_blob()
 
@@ -190,7 +191,21 @@ class TestWireProtocolGetters(AgentTestCase):
                     self.assertTrue(HostPluginProtocol.is_default_channel())
                     HostPluginProtocol.set_default_channel(False)
 
-    def test_upload_status_blob_error_reporting(self, *args):
+    def test_upload_status_blob_reports_type_error(self, *args):
+        vmstatus = VMStatus(message="Ready", status="Ready")
+        wire_protocol_client = WireProtocol(wireserver_url).client
+        wire_protocol_client.ext_conf = ExtensionsConfig(None)
+        wire_protocol_client.ext_conf.status_upload_blob = testurl
+        wire_protocol_client.ext_conf.status_upload_blob_type = "NotALegalType"
+        wire_protocol_client.status_blob.vm_status = vmstatus
+        goal_state = GoalState(WireProtocolData(DATA_FILE).goal_state)
+
+        with patch.object(WireClient, "report_status_event") as mock_event:
+            wire_protocol_client.upload_status_blob()
+
+            self.assertEqual(mock_event.call_count, 1)
+
+    def test_upload_status_blob_reports_prepare_error(self, *args):
         vmstatus = VMStatus(message="Ready", status="Ready")
         wire_protocol_client = WireProtocol(wireserver_url).client
         wire_protocol_client.ext_conf = ExtensionsConfig(None)
@@ -199,23 +214,13 @@ class TestWireProtocolGetters(AgentTestCase):
         wire_protocol_client.status_blob.vm_status = vmstatus
         goal_state = GoalState(WireProtocolData(DATA_FILE).goal_state)
 
-        with patch.object(HostPluginProtocol,
-                          "ensure_initialized",
-                          return_value=True):
-            with patch.object(StatusBlob,
-                            "put_block_blob",
-                            side_effect=HttpError("error")):
-                with patch.object(HostPluginProtocol,
-                                "put_vm_status"):
-                    with patch.object(event,
-                                    "add_event") as patch_add_event:
-                        HostPluginProtocol.set_default_channel(False)
-                        wire_protocol_client.get_goal_state = Mock(return_value=goal_state)
-                        wire_protocol_client.upload_status_blob()
-                        wire_protocol_client.get_goal_state.assert_called_once()
-                        self.assertTrue(patch_add_event.call_count == 1)
-                        self.assertTrue(patch_add_event.call_args_list[0][1]['op'] == 'ReportStatus')
-                        self.assertFalse(HostPluginProtocol.is_default_channel())
+        with patch.object(StatusBlob, "prepare",
+                    side_effect=Exception) as mock_prepare:
+            with patch.object(WireClient, "report_status_event") as mock_event:
+                wire_protocol_client.upload_status_blob()
+
+                mock_prepare.assert_called_once()
+                mock_event.assert_called_once()
 
     def test_get_in_vm_artifacts_profile_blob_not_available(self, *args):
         wire_protocol_client = WireProtocol(wireserver_url).client