Repository: Azure/WALinuxAgent
Pull request #932 (2017-11-01 18:56:04)

Address issues and improve errors
[#929] -- wire.py#update_goal_state does not handle out-of-date GoalState errors

Improved HTTP error messages
Added HTTP IOError event
Convert internal error numbers into useful names

Signed-off-by: Brendan Dixon <brendandixon@me.com>


Patch:
diff --git a/azurelinuxagent/common/event.py b/azurelinuxagent/common/event.py
index de2c3939..108cf009 100644
--- a/azurelinuxagent/common/event.py
+++ b/azurelinuxagent/common/event.py
@@ -57,6 +57,7 @@ class WALAEventOperation:
     HealthCheck = "HealthCheck"
     HeartBeat = "HeartBeat"
     HostPlugin = "HostPlugin"
+    HttpErrors = "HttpErrors"
     Install = "Install"
     InitializeHostPlugin = "InitializeHostPlugin"
     Partition = "Partition"
diff --git a/azurelinuxagent/common/exception.py b/azurelinuxagent/common/exception.py
index 17c6ce05..2e5a78a4 100644
--- a/azurelinuxagent/common/exception.py
+++ b/azurelinuxagent/common/exception.py
@@ -26,8 +26,8 @@ class AgentError(Exception):
     Base class of agent error.
     """
 
-    def __init__(self, errno, msg, inner=None):
-        msg = u"[{0}] {1}".format(errno, msg)
+    def __init__(self, msg, inner=None):
+        msg = u"[{0}] {1}".format(type(self).__name__, msg)
         if inner is not None:
             msg = u"{0}\nInner error: {1}".format(msg, inner)
         super(AgentError, self).__init__(msg)
@@ -39,7 +39,7 @@ class AgentConfigError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(AgentConfigError, self).__init__('000001', msg, inner)
+        super(AgentConfigError, self).__init__(msg, inner)
 
 
 class AgentNetworkError(AgentError):
@@ -48,7 +48,7 @@ class AgentNetworkError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(AgentNetworkError, self).__init__('000002', msg, inner)
+        super(AgentNetworkError, self).__init__(msg, inner)
 
 
 class ExtensionError(AgentError):
@@ -57,7 +57,7 @@ class ExtensionError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(ExtensionError, self).__init__('000003', msg, inner)
+        super(ExtensionError, self).__init__(msg, inner)
 
 
 class ProvisionError(AgentError):
@@ -66,7 +66,7 @@ class ProvisionError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(ProvisionError, self).__init__('000004', msg, inner)
+        super(ProvisionError, self).__init__(msg, inner)
 
 
 class ResourceDiskError(AgentError):
@@ -75,7 +75,7 @@ class ResourceDiskError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(ResourceDiskError, self).__init__('000005', msg, inner)
+        super(ResourceDiskError, self).__init__(msg, inner)
 
 
 class DhcpError(AgentError):
@@ -84,7 +84,7 @@ class DhcpError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(DhcpError, self).__init__('000006', msg, inner)
+        super(DhcpError, self).__init__(msg, inner)
 
 class OSUtilError(AgentError):
     """
@@ -92,7 +92,7 @@ class OSUtilError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(OSUtilError, self).__init__('000007', msg, inner)
+        super(OSUtilError, self).__init__(msg, inner)
 
 
 class ProtocolError(AgentError):
@@ -101,7 +101,7 @@ class ProtocolError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(ProtocolError, self).__init__('000008', msg, inner)
+        super(ProtocolError, self).__init__(msg, inner)
 
 
 class ProtocolNotFoundError(ProtocolError):
@@ -119,7 +119,7 @@ class HttpError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(HttpError, self).__init__('000009', msg, inner)
+        super(HttpError, self).__init__(msg, inner)
 
 
 class EventError(AgentError):
@@ -128,7 +128,7 @@ class EventError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(EventError, self).__init__('000010', msg, inner)
+        super(EventError, self).__init__(msg, inner)
 
 
 class CryptError(AgentError):
@@ -137,7 +137,7 @@ class CryptError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(CryptError, self).__init__('000011', msg, inner)
+        super(CryptError, self).__init__(msg, inner)
 
 
 class UpdateError(AgentError):
@@ -146,7 +146,7 @@ class UpdateError(AgentError):
     """
 
     def __init__(self, msg=None, inner=None):
-        super(UpdateError, self).__init__('000012', msg, inner)
+        super(UpdateError, self).__init__(msg, inner)
 
 
 class ResourceGoneError(HttpError):
@@ -155,4 +155,6 @@ class ResourceGoneError(HttpError):
     """
 
     def __init__(self, msg=None, inner=None):
+        if msg is None:
+            msg = "Resource is gone"
         super(ResourceGoneError, self).__init__(msg, inner)
diff --git a/azurelinuxagent/common/protocol/util.py b/azurelinuxagent/common/protocol/util.py
index 3071d7a5..b3ec373c 100644
--- a/azurelinuxagent/common/protocol/util.py
+++ b/azurelinuxagent/common/protocol/util.py
@@ -26,16 +26,18 @@ import threading
 
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
+import azurelinuxagent.common.utils.fileutil as fileutil
+
 from azurelinuxagent.common.exception import ProtocolError, OSUtilError, \
                                       ProtocolNotFoundError, DhcpError
 from azurelinuxagent.common.future import ustr
-import azurelinuxagent.common.utils.fileutil as fileutil
 from azurelinuxagent.common.osutil import get_osutil
 from azurelinuxagent.common.dhcp import get_dhcp_handler
 from azurelinuxagent.common.protocol.ovfenv import OvfEnv
 from azurelinuxagent.common.protocol.wire import WireProtocol
 from azurelinuxagent.common.protocol.metadata import MetadataProtocol, \
                                                      METADATA_ENDPOINT
+from azurelinuxagent.common.utils.restutil import IOErrorCounter
 
 OVF_FILE_NAME = "ovf-env.xml"
 TAG_FILE_NAME = "useMetadataEndpoint.tag"
@@ -175,17 +177,20 @@ class ProtocolUtil(object):
         self.clear_protocol()
 
         for retry in range(0, MAX_RETRY):
-            for protocol in protocols:
+            for protocol_name in protocols:
                 try:
-                    if protocol == "WireProtocol":
-                        return self._detect_wire_protocol()
-                    
-                    if protocol == "MetadataProtocol":
-                        return self._detect_metadata_protocol()
+                    protocol = self._detect_wire_protocol() \
+                                if protocol_name == "WireProtocol" \
+                                else self._detect_metadata_protocol()
+
+                    IOErrorCounter.set_protocol_endpoint(
+                        endpoint=protocol.endpoint)
+
+                    return protocol
 
                 except ProtocolError as e:
                     logger.info("Protocol endpoint not found: {0}, {1}", 
-                                protocol, e)
+                                protocol_name, e)
 
             if retry < MAX_RETRY -1:
                 logger.info("Retry detect protocols: retry={0}", retry)
diff --git a/azurelinuxagent/common/protocol/wire.py b/azurelinuxagent/common/protocol/wire.py
index 35f58889..f76e9e2a 100644
--- a/azurelinuxagent/common/protocol/wire.py
+++ b/azurelinuxagent/common/protocol/wire.py
@@ -74,10 +74,6 @@ class UploadError(HttpError):
     pass
 
 
-class WireProtocolResourceGone(ProtocolError):
-    pass
-
-
 class WireProtocol(Protocol):
     """Slim layer to adapt wire protocol data to metadata protocol interface"""
 
@@ -548,20 +544,21 @@ class WireClient(object):
             # Never use the HTTP proxy for wireserver
             kwargs['use_proxy'] = False
             resp = http_req(*args, **kwargs)
+
+            if restutil.request_failed(resp):
+                msg = "[Wireserver Failed] URI {0} ".format(args[0])
+                if resp is not None:
+                    msg += " [HTTP Failed] Status Code {0}".format(resp.status)
+                raise ProtocolError(msg)
+
+        # If the GoalState is stale, pass along the exception to the caller
+        except ResourceGoneError:
+            raise
+
         except Exception as e:
             raise ProtocolError("[Wireserver Exception] {0}".format(
                 ustr(e)))
 
-        if resp is not None and resp.status == httpclient.GONE:
-            msg = args[0] if len(args) > 0 else ""
-            raise WireProtocolResourceGone(msg)
-
-        elif restutil.request_failed(resp):
-            msg = "[Wireserver Failed] URI {0} ".format(args[0])
-            if resp is not None:
-                msg += " [HTTP Failed] Status Code {0}".format(resp.status)
-            raise ProtocolError(msg)
-
         return resp
 
     def decode_config(self, data):
@@ -703,26 +700,31 @@ class WireClient(object):
         self.ext_conf = ExtensionsConfig(xml_text)
 
     def update_goal_state(self, forced=False, max_retry=3):
-        uri = GOAL_STATE_URI.format(self.endpoint)
-        xml_text = self.fetch_config(uri, self.get_header())
-        goal_state = GoalState(xml_text)
-
         incarnation_file = os.path.join(conf.get_lib_dir(),
                                         INCARNATION_FILE_NAME)
-
-        if not forced:
-            last_incarnation = None
-            if os.path.isfile(incarnation_file):
-                last_incarnation = fileutil.read_file(incarnation_file)
-            new_incarnation = goal_state.incarnation
-            if last_incarnation is not None and \
-                            last_incarnation == new_incarnation:
-                # Goalstate is not updated.
-                return
+        uri = GOAL_STATE_URI.format(self.endpoint)
 
         # Start updating goalstate, retry on 410
+        fetch_goal_state = True
         for retry in range(0, max_retry):
             try:
+                if fetch_goal_state:
+                    fetch_goal_state = False
+
+                    xml_text = self.fetch_config(uri, self.get_header())
+                    goal_state = GoalState(xml_text)
+
+                    if not forced:
+                        last_incarnation = None
+                        if os.path.isfile(incarnation_file):
+                            last_incarnation = fileutil.read_file(
+                                                    incarnation_file)
+                        new_incarnation = goal_state.incarnation
+                        if last_incarnation is not None and \
+                                        last_incarnation == new_incarnation:
+                            # Goalstate is not updated.
+                            return
+
                 self.goal_state = goal_state
                 file_name = GOAL_STATE_FILE_NAME.format(goal_state.incarnation)
                 goal_state_file = os.path.join(conf.get_lib_dir(), file_name)
@@ -732,22 +734,30 @@ class WireClient(object):
                 self.update_certs(goal_state)
                 self.update_ext_conf(goal_state)
                 self.save_cache(incarnation_file, goal_state.incarnation)
+
                 if self.host_plugin is not None:
                     self.host_plugin.container_id = goal_state.container_id
                     self.host_plugin.role_config_name = goal_state.role_config_name
                 self.purge_cache()
+
                 return
 
-            except ProtocolError:
+            except ResourceGoneError:
+                logger.info("GoalState is stale -- re-fetching")
+                fetch_goal_state = True
+
+            except Exception as e:
+                log_method = logger.info \
+                                if type(e) is ProtocolError \
+                                else logger.warn
+                log_method(
+                    "Exception processing GoalState-related files: {0}".format(
+                        ustr(e)))
+
                 if retry < max_retry-1:
                     continue
                 raise
 
-            except WireProtocolResourceGone:
-                logger.info("Incarnation is out of date. Update goalstate.")
-                xml_text = self.fetch_config(uri, self.get_header())
-                goal_state = GoalState(xml_text)
-
         raise ProtocolError("Exceeded max retry updating goal state")
 
     def purge_cache(self):
diff --git a/azurelinuxagent/common/utils/cryptutil.py b/azurelinuxagent/common/utils/cryptutil.py
index 33c070ba..b34c1a58 100644
--- a/azurelinuxagent/common/utils/cryptutil.py
+++ b/azurelinuxagent/common/utils/cryptutil.py
@@ -67,6 +67,9 @@ class CryptUtil(object):
                "").format(self.openssl_cmd, p7m_file, trans_prv_file, 
                           trans_cert_file, self.openssl_cmd, pem_file)
         shellutil.run(cmd)
+        rc = shellutil.run(cmd)
+        if rc != 0:
+            logger.error("Failed to decrypt {0}".format(p7m_file))
 
     def crt_to_ssh(self, input_file, output_file):
         shellutil.run("ssh-keygen -i -m PKCS8 -f {0} >> {1}".format(input_file,
diff --git a/azurelinuxagent/common/utils/restutil.py b/azurelinuxagent/common/utils/restutil.py
index d833db4d..807be29c 100644
--- a/azurelinuxagent/common/utils/restutil.py
+++ b/azurelinuxagent/common/utils/restutil.py
@@ -18,6 +18,7 @@
 #
 
 import os
+import threading
 import time
 import traceback
 
@@ -78,6 +79,42 @@ RETRY_EXCEPTIONS = [
 HTTP_PROXY_ENV = "http_proxy"
 HTTPS_PROXY_ENV = "https_proxy"
 
+DEFAULT_PROTOCOL_ENDPOINT='168.63.129.16'
+HOST_PLUGIN_PORT = 32526
+
+
+class IOErrorCounter(object):
+    _lock = threading.RLock()
+    _protocol_endpoint = DEFAULT_PROTOCOL_ENDPOINT
+    _counts = {"hostplugin":0, "protocol":0, "other":0}
+
+    @staticmethod
+    def increment(host=None, port=None):
+        with IOErrorCounter._lock:
+            if host == IOErrorCounter._protocol_endpoint:
+                if port == HOST_PLUGIN_PORT:
+                    IOErrorCounter._counts["hostplugin"] += 1
+                else:
+                    IOErrorCounter._counts["protocol"] += 1
+            else:
+                IOErrorCounter._counts["other"] += 1
+
+    @staticmethod
+    def get_and_reset():
+        with IOErrorCounter._lock:
+            counts = IOErrorCounter._counts.copy()
+            IOErrorCounter.reset()
+            return counts
+
+    @staticmethod
+    def reset():
+        with IOErrorCounter._lock:
+            IOErrorCounter._counts = {"hostplugin":0, "protocol":0, "other":0}
+
+    @staticmethod
+    def set_protocol_endpoint(endpoint=DEFAULT_PROTOCOL_ENDPOINT):
+        IOErrorCounter._protocol_endpoint = endpoint
+
 
 def _compute_delay(retry_attempt=1, delay=DELAY_IN_SECONDS):
     fib = (1, 1)
@@ -231,7 +268,7 @@ def http_request(method,
                         else _compute_delay(retry_attempt=attempt,
                                             delay=retry_delay)
 
-            logger.info("[HTTP Retry] "
+            logger.verbose("[HTTP Retry] "
                         "Attempt {0} of {1} will delay {2} seconds: {3}",
                         attempt+1,
                         max_retry,
@@ -256,8 +293,8 @@ def http_request(method,
 
             if request_failed(resp):
                 if _is_retry_status(resp.status, retry_codes=retry_codes):
-                    msg = '[HTTP Retry] HTTP {0} Status Code {1}'.format(
-                        method, resp.status)
+                    msg = '[HTTP Retry] {0} {1} -- Status Code {2}'.format(
+                        method, url, resp.status)
                     # Note if throttled and ensure a safe, minimum number of
                     # retry attempts
                     if _is_throttle_status(resp.status):
@@ -271,16 +308,19 @@ def http_request(method,
             return resp
 
         except httpclient.HTTPException as e:
-            msg = '[HTTP Failed] HTTP {0} HttpException {1}'.format(method, e)
+            msg = '[HTTP Failed] {0} {1} -- HttpException {2}'.format(
+                method, url, e)
             if _is_retry_exception(e):
                 continue
             break
 
         except IOError as e:
-            msg = '[HTTP Failed] HTTP {0} IOError {1}'.format(method, e)
+            IOErrorCounter.increment(host=host, port=port)
+            msg = '[HTTP Failed] {0} {1} -- IOError {2}'.format(
+                method, url, e)
             continue
 
-    raise HttpError(msg)
+    raise HttpError("{0} -- {1} attempts made".format(msg,attempt))
 
 
 def http_get(url, headers=None, use_proxy=False,
diff --git a/azurelinuxagent/common/version.py b/azurelinuxagent/common/version.py
index b145da76..3b817e20 100644
--- a/azurelinuxagent/common/version.py
+++ b/azurelinuxagent/common/version.py
@@ -113,7 +113,7 @@ def get_distro():
 
 AGENT_NAME = "WALinuxAgent"
 AGENT_LONG_NAME = "Azure Linux Agent"
-AGENT_VERSION = '2.2.18.4'
+AGENT_VERSION = '2.2.18.7'
 AGENT_LONG_VERSION = "{0}-{1}".format(AGENT_NAME, AGENT_VERSION)
 AGENT_DESCRIPTION = """
 The Azure Linux Agent supports the provisioning and running of Linux
diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py
index 2cec5d15..e3ef292f 100644
--- a/azurelinuxagent/ga/monitor.py
+++ b/azurelinuxagent/ga/monitor.py
@@ -36,6 +36,7 @@ from azurelinuxagent.common.protocol.restapi import TelemetryEventParam, \
                                                     TelemetryEventList, \
                                                     TelemetryEvent, \
                                                     set_properties
+from azurelinuxagent.common.utils.restutil import IOErrorCounter
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, getattrib
 from azurelinuxagent.common.version import DISTRO_NAME, DISTRO_VERSION, \
             DISTRO_CODE_NAME, AGENT_LONG_VERSION, \
@@ -191,7 +192,7 @@ class MonitorHandler(object):
             if datetime.datetime.utcnow() >= (last_heartbeat + period):
                 last_heartbeat = datetime.datetime.utcnow()
                 incarnation = protocol.get_incarnation()
-                dropped_packages = self.osutil.get_firewall_dropped_packets(
+                dropped_packets = self.osutil.get_firewall_dropped_packets(
                                                     protocol.endpoint)
 
                 msg = "{0};{1};{2};{3}".format(
@@ -205,6 +206,24 @@ class MonitorHandler(object):
                     message=msg)
 
                 counter += 1
+
+                ioerrors = IOErrorCounter.get_and_reset()
+                hostplugin_errors = ioerrors.get("hostplugin")
+                protocol_errors = ioerrors.get("protocol")
+                other_errors = ioerrors.get("other")
+
+                if hostplugin_errors > 0 or \
+                    protocol_errors > 0 or \
+                    other_errors > 0:
+                    msg = "hostplugin:{0};protocol:{1};other:{2}".format(
+                        hostplugin_errors, protocol_errors, other_errors)
+                    add_event(
+                        name=AGENT_NAME,
+                        version=CURRENT_VERSION,
+                        op=WALAEventOperation.HttpErrors,
+                        is_success=False,
+                        msg=msg)
+
             try:
                 self.collect_and_send_events()
             except Exception as e:


Test patch:
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index a9b70f77..0c24151d 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -649,6 +649,7 @@ class TestUpdate(UpdateTestCase):
         UpdateTestCase.setUp(self)
         self.event_patch = patch('azurelinuxagent.common.event.add_event')
         self.update_handler = get_update_handler()
+        self.update_handler.protocol_util = Mock()
 
     def test_creation(self):
         self.assertTrue(self.update_handler.running)
diff --git a/tests/utils/test_rest_util.py b/tests/utils/test_rest_util.py
index 1dd940ad..bde0c3d0 100644
--- a/tests/utils/test_rest_util.py
+++ b/tests/utils/test_rest_util.py
@@ -24,9 +24,70 @@ from azurelinuxagent.common.exception import HttpError, \
 import azurelinuxagent.common.utils.restutil as restutil
 
 from azurelinuxagent.common.future import httpclient, ustr
+
 from tests.tools import *
 
 
+class TestIOErrorCounter(AgentTestCase):
+    def test_increment_hostplugin(self):
+        restutil.IOErrorCounter.reset()
+        restutil.IOErrorCounter.set_protocol_endpoint()
+
+        restutil.IOErrorCounter.increment(
+            restutil.DEFAULT_PROTOCOL_ENDPOINT, restutil.HOST_PLUGIN_PORT)
+
+        counts = restutil.IOErrorCounter.get_and_reset()
+        self.assertEqual(1, counts["hostplugin"])
+        self.assertEqual(0, counts["protocol"])
+        self.assertEqual(0, counts["other"])
+
+    def test_increment_protocol(self):
+        restutil.IOErrorCounter.reset()
+        restutil.IOErrorCounter.set_protocol_endpoint()
+
+        restutil.IOErrorCounter.increment(
+            restutil.DEFAULT_PROTOCOL_ENDPOINT, 80)
+
+        counts = restutil.IOErrorCounter.get_and_reset()
+        self.assertEqual(0, counts["hostplugin"])
+        self.assertEqual(1, counts["protocol"])
+        self.assertEqual(0, counts["other"])
+
+    def test_increment_other(self):
+        restutil.IOErrorCounter.reset()
+        restutil.IOErrorCounter.set_protocol_endpoint()
+
+        restutil.IOErrorCounter.increment(
+            '169.254.169.254', 80)
+
+        counts = restutil.IOErrorCounter.get_and_reset()
+        self.assertEqual(0, counts["hostplugin"])
+        self.assertEqual(0, counts["protocol"])
+        self.assertEqual(1, counts["other"])
+
+    def test_get_and_reset(self):
+        restutil.IOErrorCounter.reset()
+        restutil.IOErrorCounter.set_protocol_endpoint()
+
+        restutil.IOErrorCounter.increment(
+            restutil.DEFAULT_PROTOCOL_ENDPOINT, restutil.HOST_PLUGIN_PORT)
+        restutil.IOErrorCounter.increment(
+            restutil.DEFAULT_PROTOCOL_ENDPOINT, restutil.HOST_PLUGIN_PORT)
+        restutil.IOErrorCounter.increment(
+            restutil.DEFAULT_PROTOCOL_ENDPOINT, 80)
+        restutil.IOErrorCounter.increment(
+            '169.254.169.254', 80)
+        restutil.IOErrorCounter.increment(
+            '169.254.169.254', 80)
+
+        counts = restutil.IOErrorCounter.get_and_reset()
+        self.assertEqual(2, counts.get("hostplugin"))
+        self.assertEqual(1, counts.get("protocol"))
+        self.assertEqual(2, counts.get("other"))
+        self.assertEqual(
+           {"hostplugin":0, "protocol":0, "other":0},
+            restutil.IOErrorCounter._counts)
+
 class TestHttpOperations(AgentTestCase):
     def test_parse_url(self):
         test_uri = "http://abc.def/ghi#hash?jkl=mn"