Repository: Azure/WALinuxAgent

Issue:
Socket timeout causes blacklist
Found in logs, we need to handle this case more gracefully:
```
2017/11/17 11:47:16.626326 WARNING Agent WALinuxAgent-2.2.18 failed with exception: The read operation timed out
2017/11/17 11:47:16.705491 WARNING Traceback (most recent call last):
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/ga/update.py", line 271, in run
    exthandlers_handler.run()
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/ga/exthandlers.py", line 198, in run
    self.handle_ext_handlers(etag)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/ga/exthandlers.py", line 285, in handle_ext_handlers
    self.handle_ext_handler(ext_handler, etag)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/ga/exthandlers.py", line 291, in handle_ext_handler
    ext_handler_i.decide_version()
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/ga/exthandlers.py", line 432, in decide_version
    pkg_list = self.protocol.get_ext_handler_pkgs(self.ext_handler)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/common/protocol/wire.py", line 148, in get_ext_handler_pkgs
    man = self.client.get_ext_manifest(ext_handler, goal_state)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/common/protocol/wire.py", line 809, in get_ext_manifest
    xml_text = self.fetch_manifest(ext_handler.versionUris)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/common/protocol/wire.py", line 606, in fetch_manifest
    response = self.fetch(version.uri)
  File "bin/WALinuxAgent-2.2.18-py2.7.egg/azurelinuxagent/common/protocol/wire.py", line 653, in fetch
    return self.decode_config(resp.read())
  File "/usr/lib/python3.4/http/client.py", line 541, in read
    s = self._safe_read(self.length)
  File "/usr/lib/python3.4/http/client.py", line 691, in _safe_read
    chunk = self.fp.read(min(amt, MAXAMOUNT))
  File "/usr/lib/python3.4/socket.py", line 374, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3.4/ssl.py", line 769, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/lib/python3.4/ssl.py", line 641, in read
    v = self._sslobj.read(len, buffer)
socket.timeout: The read operation timed out

2017/11/17 11:47:16.784583 WARNING Agent WALinuxAgent-2.2.18 launched with command 'python3 -u bin/WALinuxAgent-2.2.18-py2.7.egg -run-exthandlers' returned code: 1
2017/11/17 11:47:16.785549 WARNING Agent WALinuxAgent-2.2.18 is permanently blacklisted
```
This type of timeout should not be causing a blacklist.

Discussion:

Patch:
diff --git a/azurelinuxagent/common/protocol/restapi.py b/azurelinuxagent/common/protocol/restapi.py
index 275cedb0..540ec5d9 100644
--- a/azurelinuxagent/common/protocol/restapi.py
+++ b/azurelinuxagent/common/protocol/restapi.py
@@ -321,9 +321,9 @@ class Protocol(DataContract):
     def get_artifacts_profile(self):
         raise NotImplementedError()
 
-    def download_ext_handler_pkg(self, uri, headers=None):
+    def download_ext_handler_pkg(self, uri, headers=None, use_proxy=True):
         try:
-            resp = restutil.http_get(uri, use_proxy=True, headers=headers)
+            resp = restutil.http_get(uri, headers=headers, use_proxy=use_proxy)
             if restutil.request_succeeded(resp):
                 return resp.read()
         except Exception as e:
diff --git a/azurelinuxagent/common/protocol/wire.py b/azurelinuxagent/common/protocol/wire.py
index a92e0b89..2dc5297c 100644
--- a/azurelinuxagent/common/protocol/wire.py
+++ b/azurelinuxagent/common/protocol/wire.py
@@ -172,7 +172,7 @@ class WireProtocol(Protocol):
             logger.warn("Download did not succeed, falling back to host plugin")
             host = self.client.get_host_plugin()
             uri, headers = host.get_artifact_request(uri, host.manifest_uri)
-            package = super(WireProtocol, self).download_ext_handler_pkg(uri, headers=headers)
+            package = super(WireProtocol, self).download_ext_handler_pkg(uri, headers=headers, use_proxy=False)
         return package
 
     def report_provision_status(self, provision_status):
diff --git a/azurelinuxagent/ga/env.py b/azurelinuxagent/ga/env.py
index 0456cb06..26487818 100644
--- a/azurelinuxagent/ga/env.py
+++ b/azurelinuxagent/ga/env.py
@@ -86,7 +86,7 @@ class EnvHandler(object):
                     version=CURRENT_VERSION,
                     op=WALAEventOperation.Firewall,
                     is_success=success,
-                    log_event=True)
+                    log_event=False)
 
             timeout = conf.get_root_device_scsi_timeout()
             if timeout is not None:
diff --git a/azurelinuxagent/ga/monitor.py b/azurelinuxagent/ga/monitor.py
index e3ef292f..9b90aa7b 100644
--- a/azurelinuxagent/ga/monitor.py
+++ b/azurelinuxagent/ga/monitor.py
@@ -203,7 +203,8 @@ class MonitorHandler(object):
                     version=CURRENT_VERSION,
                     op=WALAEventOperation.HeartBeat,
                     is_success=True,
-                    message=msg)
+                    message=msg,
+                    log_event=False)
 
                 counter += 1
 
@@ -222,7 +223,7 @@ class MonitorHandler(object):
                         version=CURRENT_VERSION,
                         op=WALAEventOperation.HttpErrors,
                         is_success=False,
-                        msg=msg)
+                        message=msg)
 
             try:
                 self.collect_and_send_events()
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index 26009299..80870cae 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -295,7 +295,7 @@ class UpdateHandler(object):
                         duration=elapsed_milliseconds(utc_start),
                         message="Incarnation {0}".format(
                                             exthandlers_handler.last_etag),
-                        log_event=True)
+                        log_event=False)
 
                 time.sleep(GOAL_STATE_INTERVAL)
 
@@ -704,13 +704,13 @@ class GuestAgent(object):
         version = None
         if path is not None:
             m = AGENT_DIR_PATTERN.match(path)
-            if m == None:
+            if m is None:
                 raise UpdateError(u"Illegal agent directory: {0}".format(path))
             version = m.group(1)
         elif self.pkg is not None:
             version = pkg.version
 
-        if version == None:
+        if version is None:
             raise UpdateError(u"Illegal agent version: {0}".format(version))
         self.version = FlexibleVersion(version)
 
@@ -727,6 +727,13 @@ class GuestAgent(object):
             if isinstance(e, ResourceGoneError):
                 raise
 
+            # The agent was improperly blacklisting versions due to a timeout
+            # encountered while downloading a later version. Errors of type
+            # socket.error are IOError, so this should provide sufficient
+            # protection against a large class of I/O operation failures.
+            if isinstance(e, IOError):
+                raise
+
             # Note the failure, blacklist the agent if the package downloaded
             # - An exception with a downloaded package indicates the package
             #   is corrupt (e.g., missing the HandlerManifest.json file)
diff --git a/azurelinuxagent/pa/provision/cloudinit.py b/azurelinuxagent/pa/provision/cloudinit.py
index 22c3f9ca..fa47799a 100644
--- a/azurelinuxagent/pa/provision/cloudinit.py
+++ b/azurelinuxagent/pa/provision/cloudinit.py
@@ -64,7 +64,7 @@ class CloudInitProvisionHandler(ProvisionHandler):
             logger.info("Finished provisioning")
 
             self.report_ready(thumbprint)
-            self.report_event("Provision succeed",
+            self.report_event("Provisioning with cloud-init succeeded",
                 is_success=True,
                 duration=elapsed_milliseconds(utc_start))
             self.report_event(self.create_guest_state_telemetry_messsage(),
diff --git a/azurelinuxagent/pa/provision/default.py b/azurelinuxagent/pa/provision/default.py
index 5d6f1565..44e171b4 100644
--- a/azurelinuxagent/pa/provision/default.py
+++ b/azurelinuxagent/pa/provision/default.py
@@ -89,7 +89,7 @@ class ProvisionHandler(object):
 
             self.write_provisioned()
 
-            self.report_event("Provision succeeded",
+            self.report_event("Provisioning succeeded",
                 is_success=True,
                 duration=elapsed_milliseconds(utc_start))
 
diff --git a/azurelinuxagent/pa/provision/factory.py b/azurelinuxagent/pa/provision/factory.py
index d87765f3..9e88618f 100644
--- a/azurelinuxagent/pa/provision/factory.py
+++ b/azurelinuxagent/pa/provision/factory.py
@@ -16,9 +16,7 @@
 #
 
 import azurelinuxagent.common.conf as conf
-import azurelinuxagent.common.logger as logger
 
-from azurelinuxagent.common.utils.textutil import Version
 from azurelinuxagent.common.version import DISTRO_NAME, DISTRO_VERSION, \
                                      DISTRO_FULL_NAME
 


Test patch:
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index 88535f5b..a40278c7 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -387,6 +387,30 @@ class TestGuestAgent(UpdateTestCase):
         self.assertTrue(agent.is_blacklisted)
         self.assertEqual(agent.is_blacklisted, agent.error.is_blacklisted)
 
+    @patch("azurelinuxagent.ga.update.GuestAgent._ensure_downloaded")
+    @patch("azurelinuxagent.ga.update.GuestAgent._ensure_loaded")
+    def test_resource_gone_error_not_blacklisted(self, mock_loaded, mock_downloaded):
+        try:
+            mock_downloaded.side_effect = ResourceGoneError()
+            agent = GuestAgent(path=self.agent_path)
+            self.assertFalse(agent.is_blacklisted)
+        except ResourceGoneError:
+            pass
+        except:
+            self.fail("Exception was not expected!")
+
+    @patch("azurelinuxagent.ga.update.GuestAgent._ensure_downloaded")
+    @patch("azurelinuxagent.ga.update.GuestAgent._ensure_loaded")
+    def test_ioerror_not_blacklisted(self, mock_loaded, mock_downloaded):
+        try:
+            mock_downloaded.side_effect = IOError()
+            agent = GuestAgent(path=self.agent_path)
+            self.assertFalse(agent.is_blacklisted)
+        except IOError:
+            pass
+        except:
+            self.fail("Exception was not expected!")
+
     @patch("azurelinuxagent.ga.update.GuestAgent._ensure_downloaded")
     @patch("azurelinuxagent.ga.update.GuestAgent._ensure_loaded")
     def test_is_downloaded(self, mock_loaded, mock_downloaded):
@@ -1550,6 +1574,7 @@ class ProtocolMock(object):
         self.call_counts["update_goal_state"] += 1
         self.goal_state_forced = self.goal_state_forced or forced
 
+
 class ResponseMock(Mock):
     def __init__(self, status=restutil.httpclient.OK, response=None, reason=None):
         Mock.__init__(self)
@@ -1579,5 +1604,6 @@ class TimeMock(Mock):
         self.next_time += self.time_increment
         return current_time
 
+
 if __name__ == '__main__':
     unittest.main()
diff --git a/tests/pa/test_provision.py b/tests/pa/test_provision.py
index ab0a9102..2c2d2c9b 100644
--- a/tests/pa/test_provision.py
+++ b/tests/pa/test_provision.py
@@ -151,7 +151,7 @@ class TestProvision(AgentTestCase):
 
         ph.run()
 
-        call1 = call("Provision succeeded", duration=ANY, is_success=True)
+        call1 = call("Provisioning succeeded", duration=ANY, is_success=True)
         call2 = call(ANY, is_success=True, operation=WALAEventOperation.GuestState)
         ph.report_event.assert_has_calls([call1, call2])