Repository: Azure/WALinuxAgent (python)

Issue:
Timing Issue with cloud-init and host keys
Under some circumstances, provisioning can fail waiting for cloud-init to regenerate SSH host keys:
```
2017/02/08 23:03:23.712479 INFO Wait for ssh host key to be generated.
2017/02/08 23:03:23.756726 ERROR run cmd 'ssh-keygen -lf /etc/ssh/ssh_host_rsa_key.pub' failed
2017/02/08 23:03:23.762243 ERROR Error Code:255
2017/02/08 23:03:23.766393 ERROR Result:ssh-keygen: /etc/ssh/ssh_host_rsa_key.pub: No such file or directory
 
2017/02/08 23:03:23.775621 ERROR Provision failed: (000004)**Failed to generate ssh host key: ret=255, out= ssh-keygen: /etc/ssh/ssh_host_rsa_key.pub: No such file or directory**
```
Waagent checks the thumbprint of the host rsa pub file to validate that the key is regenerated. If the file doesn't exist, it waits up to 5 minutes for it to be generated. Based on the logs, the sequence of events seems to be

1. Waagent confirms existence of the file
2. Cloud-init deletes the file and begins generating a new file
3. Waagent tries and fails to get the thumbprint because the file doesn't exist

One or both of the following should be implemented:
1. Use more caution when exiting from this function with error. If the thumbprint operation finds that the file doesn't exist (when it was just confirmed to exist by other means), we should try again.
2. If the expectation is that the SSH host keys are deleted before provisioning, then waagent -deprovision should delete them.


Pull request description:
retry get thumbprint if key is deleted
When cloud-init provisions the vm in Ubuntu, we wait for the ssh key to be present on disk. It is possible to hit a race condition where we fail to get the thumbprint before the key is regenerated. If this happens we should retry.

- fixes #591 

/cc @brendandixon @jinhyunr 

Patch:
diff --git a/azurelinuxagent/common/protocol/hostplugin.py b/azurelinuxagent/common/protocol/hostplugin.py
index 4c4c2290..bdae56e2 100644
--- a/azurelinuxagent/common/protocol/hostplugin.py
+++ b/azurelinuxagent/common/protocol/hostplugin.py
@@ -80,10 +80,10 @@ class HostPluginProtocol(object):
     def get_artifact_request(self, artifact_url, artifact_manifest_url=None):
         if not self.ensure_initialized():
             logger.error("host plugin channel is not available")
-            return
+            return None, None
         if textutil.is_str_none_or_whitespace(artifact_url):
             logger.error("no extension artifact url was provided")
-            return
+            return None, None
 
         url = URI_FORMAT_GET_EXTENSION_ARTIFACT.format(self.endpoint,
                                                        HOST_PLUGIN_PORT)
diff --git a/azurelinuxagent/common/rdma.py b/azurelinuxagent/common/rdma.py
index ba9a0294..226482d3 100644
--- a/azurelinuxagent/common/rdma.py
+++ b/azurelinuxagent/common/rdma.py
@@ -133,14 +133,14 @@ class RDMAHandler(object):
         """Load the kernel driver, this depends on the proper driver
            to be installed with the install_driver() method"""
         logger.info("RDMA: probing module '%s'" % self.driver_module_name)
-        result = shellutil.run('modprobe %s' % self.driver_module_name)
+        result = shellutil.run('modprobe --first-time %s' % self.driver_module_name)
         if result != 0:
             error_msg = 'Could not load "%s" kernel module. '
-            error_msg += 'Run "modprobe %s" as root for more details'
+            error_msg += 'Run "modprobe --first-time %s" as root for more details'
             logger.error(
                 error_msg % (self.driver_module_name, self.driver_module_name)
             )
-            return
+            return False
         logger.info('RDMA: Loaded the kernel driver successfully.')
         return True
 
@@ -158,6 +158,7 @@ class RDMAHandler(object):
             logger.info('RDMA: module loaded.')
             return True
         logger.info('RDMA: module not loaded.')
+        return False
 
     def reboot_system(self):
         """Reboot the system. This is required as the kernel module for
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index c563cc85..9b99d041 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -341,7 +341,7 @@ class ExtHandlerInstance(object):
         self.logger = logger.Logger(logger.DEFAULT_LOGGER, prefix)
         
         try:
-            fileutil.mkdir(self.get_log_dir(), mode=0o744)
+            fileutil.mkdir(self.get_log_dir(), mode=0o755)
         except IOError as e:
             self.logger.error(u"Failed to create extension log dir: {0}", e)
 
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index ed05135c..59bc70c5 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -701,11 +701,15 @@ class GuestAgent(object):
             if self._fetch(uri.uri):
                 break
             else:
-                if self.host is not None:
+                if self.host is not None and self.host.ensure_initialized():
                     logger.warn("Download unsuccessful, falling back to host plugin")
                     uri, headers = self.host.get_artifact_request(uri.uri, self.host.manifest_uri)
-                    if self._fetch(uri, headers=headers):
+                    if uri is not None \
+                            and headers is not None \
+                            and self._fetch(uri, headers=headers):
                         break
+                else:
+                    logger.warn("Download unsuccessful, host plugin not available")
 
         if not os.path.isfile(self.get_agent_pkg_path()):
             msg = u"Unable to download Agent {0} from any URI".format(self.name)
diff --git a/azurelinuxagent/pa/provision/ubuntu.py b/azurelinuxagent/pa/provision/ubuntu.py
index 60b9a89a..a71df374 100644
--- a/azurelinuxagent/pa/provision/ubuntu.py
+++ b/azurelinuxagent/pa/provision/ubuntu.py
@@ -89,8 +89,14 @@ class UbuntuProvisionHandler(ProvisionHandler):
         path = '/etc/ssh/ssh_host_{0}_key.pub'.format(keypair_type)
         for retry in range(0, max_retry):
             if os.path.isfile(path):
-                return self.get_ssh_host_key_thumbprint(keypair_type)
+                logger.info("ssh host key found at: {0}".format(path))
+                try:
+                    thumbprint = self.get_ssh_host_key_thumbprint(keypair_type)
+                    logger.info("Thumbprint obtained from : {0}".format(path))
+                    return thumbprint
+                except ProvisionError:
+                    logger.warn("Could not get thumbprint from {0}".format(path))
             if retry < max_retry - 1:
-                logger.info("Wait for ssh host key be generated: {0}", path)
+                logger.info("Wait for ssh host key be generated: {0}".format(path))
                 time.sleep(5)
         raise ProvisionError("ssh host key is not generated.")
diff --git a/azurelinuxagent/pa/rdma/centos.py b/azurelinuxagent/pa/rdma/centos.py
index 8ad09c54..214f9ead 100644
--- a/azurelinuxagent/pa/rdma/centos.py
+++ b/azurelinuxagent/pa/rdma/centos.py
@@ -173,8 +173,7 @@ class CentOSRDMAHandler(RDMAHandler):
             'user mode', self.rdma_user_mode_package_name, umod_pkg_path)
 
         logger.info("RDMA: driver packages installed")
-        self.load_driver_module()
-        if not self.is_driver_loaded():
+        if not self.load_driver_module() or not self.is_driver_loaded():
             logger.info("RDMA: driver module is not loaded; reboot required")
             self.reboot_system()
         else:
diff --git a/azurelinuxagent/pa/rdma/suse.py b/azurelinuxagent/pa/rdma/suse.py
index f0d8d0f5..d31b2b08 100644
--- a/azurelinuxagent/pa/rdma/suse.py
+++ b/azurelinuxagent/pa/rdma/suse.py
@@ -93,8 +93,7 @@ class SUSERDMAHandler(RDMAHandler):
                 msg = 'RDMA: Successfully installed "%s" from '
                 msg += 'configured repositories'
                 logger.info(msg % complete_name)
-                self.load_driver_module()
-                if requires_reboot:
+                if not self.load_driver_module() or requires_reboot:
                     self.reboot_system()
                 return True
         else:
@@ -119,8 +118,7 @@ class SUSERDMAHandler(RDMAHandler):
                     msg = 'RDMA: Successfully installed "%s" from '
                     msg += 'local package cache'
                     logger.info(msg % (local_package))
-                    self.load_driver_module()
-                    if requires_reboot:
+                    if not self.load_driver_module() or requires_reboot:
                         self.reboot_system()
                     return True
             else:


Test patch:
diff --git a/tests/ga/test_update.py b/tests/ga/test_update.py
index a431a9b6..5277e594 100644
--- a/tests/ga/test_update.py
+++ b/tests/ga/test_update.py
@@ -17,30 +17,10 @@
 
 from __future__ import print_function
 
-import copy
-import glob
-import json
-import os
-import platform
-import random
-import re
-import subprocess
-import sys
-import tempfile
-import zipfile
-
-from tests.protocol.mockwiredata import *
-from tests.tools import *
-
-import azurelinuxagent.common.logger as logger
-import azurelinuxagent.common.utils.fileutil as fileutil
-
-from azurelinuxagent.common.exception import UpdateError
-from azurelinuxagent.common.protocol.restapi import *
+from azurelinuxagent.common.protocol.hostplugin import *
 from azurelinuxagent.common.protocol.wire import *
-from azurelinuxagent.common.utils.flexible_version import FlexibleVersion
-from azurelinuxagent.common.version import AGENT_NAME, AGENT_VERSION
 from azurelinuxagent.ga.update import *
+from tests.tools import *
 
 NO_ERROR = {
     "last_failure" : 0.0,
@@ -194,7 +174,7 @@ class UpdateTestCase(AgentTestCase):
             self.copy_agents(get_agent_pkgs()[0])
             self.expand_agents()
             count -= 1
-        
+
         # Determine the most recent agent version
         versions = self.agent_versions()
         src_v = FlexibleVersion(str(versions[0]))
@@ -290,11 +270,11 @@ class TestGuestAgentError(UpdateTestCase):
 
         for i in range(0, MAX_FAILURE):
             err.mark_failure()
-        
+
         # Agent failed >= MAX_FAILURE, it should be blacklisted
         self.assertTrue(err.is_blacklisted)
         self.assertEqual(MAX_FAILURE, err.failure_count)
-        
+
         # Clear old failure does not clear recent failure
         err.clear_old_failure()
         self.assertTrue(err.is_blacklisted)
@@ -396,7 +376,7 @@ class TestGuestAgent(UpdateTestCase):
         self.assertFalse(agent.is_available)
         agent._unpack()
         self.assertTrue(agent.is_available)
-        
+
         agent.mark_failure(is_fatal=True)
         self.assertFalse(agent.is_available)
         return
@@ -409,7 +389,7 @@ class TestGuestAgent(UpdateTestCase):
         agent._unpack()
         self.assertFalse(agent.is_blacklisted)
         self.assertEqual(agent.is_blacklisted, agent.error.is_blacklisted)
-        
+
         agent.mark_failure(is_fatal=True)
         self.assertTrue(agent.is_blacklisted)
         self.assertEqual(agent.is_blacklisted, agent.error.is_blacklisted)
@@ -525,7 +505,7 @@ class TestGuestAgent(UpdateTestCase):
         self.assertFalse(os.path.isdir(self.agent_path))
 
         mock_http_get.return_value= ResponseMock(status=restutil.httpclient.SERVICE_UNAVAILABLE)
-        
+
         pkg = ExtHandlerPackage(version=str(get_agent_version()))
         pkg.uris.append(ExtHandlerPackageUri())
         agent = GuestAgent(pkg=pkg)
@@ -546,6 +526,8 @@ class TestGuestAgent(UpdateTestCase):
 
         ext_uri = 'ext_uri'
         host_uri = 'host_uri'
+        api_uri = URI_FORMAT_GET_API_VERSIONS.format(host_uri, HOST_PLUGIN_PORT)
+        art_uri = URI_FORMAT_GET_EXTENSION_ARTIFACT.format(host_uri, HOST_PLUGIN_PORT)
         mock_host = HostPluginProtocol(host_uri,
                                        'container_id',
                                        'role_config')
@@ -555,13 +537,29 @@ class TestGuestAgent(UpdateTestCase):
         agent = GuestAgent(pkg=pkg)
         agent.host = mock_host
 
+        # ensure fallback fails gracefully, no http
+        self.assertRaises(UpdateError, agent._download)
+        self.assertEqual(mock_http_get.call_count, 2)
+        self.assertEqual(mock_http_get.call_args_list[0][0][0], ext_uri)
+        self.assertEqual(mock_http_get.call_args_list[1][0][0], api_uri)
+
+        # ensure fallback fails gracefully, artifact api failure
         with patch.object(HostPluginProtocol,
-                          "get_artifact_request",
-                          return_value=[host_uri, {}]):
+                          "ensure_initialized",
+                          return_value=True):
             self.assertRaises(UpdateError, agent._download)
-            self.assertEqual(mock_http_get.call_count, 2)
-            self.assertEqual(mock_http_get.call_args_list[0][0][0], ext_uri)
-            self.assertEqual(mock_http_get.call_args_list[1][0][0], host_uri)
+            self.assertEqual(mock_http_get.call_count, 4)
+            self.assertEqual(mock_http_get.call_args_list[2][0][0], ext_uri)
+            self.assertEqual(mock_http_get.call_args_list[3][0][0], art_uri)
+
+            # ensure fallback works as expected
+            with patch.object(HostPluginProtocol,
+                              "get_artifact_request",
+                              return_value=[art_uri, {}]):
+                self.assertRaises(UpdateError, agent._download)
+                self.assertEqual(mock_http_get.call_count, 6)
+                self.assertEqual(mock_http_get.call_args_list[4][0][0], ext_uri)
+                self.assertEqual(mock_http_get.call_args_list[5][0][0], art_uri)
 
     @patch("azurelinuxagent.ga.update.restutil.http_get")
     def test_ensure_downloaded(self, mock_http_get):
@@ -688,7 +686,7 @@ class TestUpdate(UpdateTestCase):
             protocol=None,
             versions=None,
             count=5):
-        
+
         latest_version = self.prepare_agents(count=count)
         if versions is None or len(versions) <= 0:
             versions = [latest_version]
@@ -741,7 +739,7 @@ class TestUpdate(UpdateTestCase):
         self.prepare_agents()
         agent_count = self.agent_count()
         self.assertEqual(5, agent_count)
-        
+
         agent_versions = self.agent_versions()[:3]
         self.assertTrue(self._test_upgrade_available(versions=agent_versions))
         self.assertEqual(len(agent_versions), len(self.update_handler.agents))
@@ -793,7 +791,7 @@ class TestUpdate(UpdateTestCase):
                 return iterations[0] < invocations
 
             mock_util.check_pid_alive = Mock(side_effect=iterator)
-            
+
             with patch('os.getpid', return_value=42):
                 with patch('time.sleep', return_value=None) as mock_sleep:
                     self.update_handler._ensure_no_orphans(orphan_wait_interval=interval)
@@ -1178,7 +1176,7 @@ class TestUpdate(UpdateTestCase):
         #   reference. Incrementing an item of a list changes an item to
         #   which the code has a reference.
         #   See http://stackoverflow.com/questions/26408941/python-nested-functions-and-variable-scope
-        iterations = [0] 
+        iterations = [0]
         def iterator(*args, **kwargs):
             iterations[0] += 1
             if iterations[0] >= invocations: