azurecloud: fix issues with instances not starting (#205)

The azurecloud platform did not always start instances
during collect runs.  This was a result of two issues. First
the image class _instance method did not invoke the start()
method which then allowed collect stage to attempt to run
scripts without an endpoint.  Second, azurecloud used the
image_id as both an instance handle (which is typically
vmName in azure api) as well as an image handle (for image
capture).  Resolve this by adding a .vm_name property to
the AzureCloudInstance and reference this property in
AzureCloudImage.

Also in this branch

- Fix error encoding user-data when value is None
- Add additional logging in AzureCloud platform
- Update logging format to print pathname,funcName and line number
  This greatly eases debugging.

LP: #1861921

5 files changed, 36 insertions, 21 deletions

diff --git a/tests/cloud_tests/__init__.py b/tests/cloud_tests/__init__.py
index dd436989..6c632f99 100644
--- a/tests/cloud_tests/__init__.py
+++ b/tests/cloud_tests/__init__.py
@@ -22,7 +22,8 @@ def _initialize_logging():
     logger = logging.getLogger(__name__)
     logger.setLevel(logging.DEBUG)
     formatter = logging.Formatter(
-        '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+        '%(asctime)s - %(pathname)s:%(funcName)s:%(lineno)s '
+        '[%(levelname)s]: %(message)s')
 
     console = logging.StreamHandler()
     console.setLevel(logging.DEBUG)
diff --git a/tests/cloud_tests/platforms/azurecloud/image.py b/tests/cloud_tests/platforms/azurecloud/image.py
index 96a946f3..aad2bca1 100644
--- a/tests/cloud_tests/platforms/azurecloud/image.py
+++ b/tests/cloud_tests/platforms/azurecloud/image.py
@@ -21,26 +21,26 @@ class AzureCloudImage(Image):
         @param image_id: image id used to boot instance
         """
         super(AzureCloudImage, self).__init__(platform, config)
-        self.image_id = image_id
         self._img_instance = None
+        self.image_id = image_id
 
     @property
     def _instance(self):
         """Internal use only, returns a running instance"""
-        LOG.debug('creating instance')
         if not self._img_instance:
             self._img_instance = self.platform.create_instance(
                 self.properties, self.config, self.features,
                 self.image_id, user_data=None)
+            self._img_instance.start(wait=True, wait_for_cloud_init=True)
         return self._img_instance
 
     def destroy(self):
         """Delete the instance used to create a custom image."""
-        LOG.debug('deleting VM that was used to create image')
         if self._img_instance:
-            LOG.debug('Deleting instance %s', self._img_instance.name)
+            LOG.debug('Deleting backing instance %s',
+                      self._img_instance.vm_name)
             delete_vm = self.platform.compute_client.virtual_machines.delete(
-                self.platform.resource_group.name, self.image_id)
+                self.platform.resource_group.name, self._img_instance.vm_name)
             delete_vm.wait()
 
         super(AzureCloudImage, self).destroy()
@@ -48,7 +48,7 @@ class AzureCloudImage(Image):
     def _execute(self, *args, **kwargs):
         """Execute command in image, modifying image."""
         LOG.debug('executing commands on image')
-        self._instance.start()
+        self._instance.start(wait=True)
         return self._instance._execute(*args, **kwargs)
 
     def push_file(self, local_path, remote_path):
@@ -72,21 +72,26 @@ class AzureCloudImage(Image):
         Otherwise runs the clean script, deallocates, generalizes
         and creates custom image from instance.
         """
-        LOG.debug('creating image from VM')
+        LOG.debug('creating snapshot of image')
         if not self._img_instance:
+            LOG.debug('No existing image, snapshotting base image')
             return AzureCloudSnapshot(self.platform, self.properties,
                                       self.config, self.features,
-                                      self.image_id, delete_on_destroy=False)
+                                      self._instance.vm_name,
+                                      delete_on_destroy=False)
 
+        LOG.debug('creating snapshot from instance: %s', self._img_instance)
         if self.config.get('boot_clean_script'):
             self._img_instance.run_script(self.config.get('boot_clean_script'))
 
+        LOG.debug('deallocating instance %s', self._instance.vm_name)
         deallocate = self.platform.compute_client.virtual_machines.deallocate(
-            self.platform.resource_group.name, self.image_id)
+            self.platform.resource_group.name, self._instance.vm_name)
         deallocate.wait()
 
+        LOG.debug('generalizing instance %s', self._instance.vm_name)
         self.platform.compute_client.virtual_machines.generalize(
-            self.platform.resource_group.name, self.image_id)
+            self.platform.resource_group.name, self._instance.vm_name)
 
         image_params = {
             "location": self.platform.location,
@@ -96,13 +101,16 @@ class AzureCloudImage(Image):
                 }
             }
         }
+        LOG.debug('updating resource group image %s', self._instance.vm_name)
         self.platform.compute_client.images.create_or_update(
-            self.platform.resource_group.name, self.image_id,
+            self.platform.resource_group.name, self._instance.vm_name,
             image_params)
 
+        LOG.debug('destroying self')
         self.destroy()
 
+        LOG.debug('snapshot complete')
         return AzureCloudSnapshot(self.platform, self.properties, self.config,
-                                  self.features, self.image_id)
+                                  self.features, self._instance.vm_name)
 
 # vi: ts=4 expandtab
diff --git a/tests/cloud_tests/platforms/azurecloud/instance.py b/tests/cloud_tests/platforms/azurecloud/instance.py
index 3d77a1a7..f1e28a96 100644
--- a/tests/cloud_tests/platforms/azurecloud/instance.py
+++ b/tests/cloud_tests/platforms/azurecloud/instance.py
@@ -41,6 +41,7 @@ class AzureCloudInstance(Instance):
         self.ssh_ip = None
         self.instance = None
         self.image_id = image_id
+        self.vm_name = 'ci-azure-i-%s' % self.platform.tag
         self.user_data = user_data
         self.ssh_key_file = os.path.join(
             platform.config['data_dir'], platform.config['private_key'])
@@ -74,16 +75,18 @@ class AzureCloudInstance(Instance):
                 self.image_id
             )
             image_exists = True
-            LOG.debug('image found, launching instance')
+            LOG.debug('image found, launching instance, image_id=%s',
+                      self.image_id)
         except CloudError:
-            LOG.debug(
-                'image not found, launching instance with base image')
+            LOG.debug(('image not found, launching instance with base image, '
+                       'image_id=%s'), self.image_id)
             pass
 
         vm_params = {
+            'name': self.vm_name,
             'location': self.platform.location,
             'os_profile': {
-                'computer_name': 'CI',
+                'computer_name': 'CI-%s' % self.platform.tag,
                 'admin_username': self.ssh_username,
                 "customData": self.user_data,
                 "linuxConfiguration": {
@@ -129,7 +132,9 @@ class AzureCloudInstance(Instance):
         try:
             self.instance = self.platform.compute_client.virtual_machines.\
                 create_or_update(self.platform.resource_group.name,
-                                 self.image_id, vm_params)
+                                 self.vm_name, vm_params)
+            LOG.debug('creating instance %s from image_id=%s', self.vm_name,
+                      self.image_id)
         except CloudError:
             raise RuntimeError('failed creating instance:\n{}'.format(
                 traceback.format_exc()))
diff --git a/tests/cloud_tests/platforms/azurecloud/platform.py b/tests/cloud_tests/platforms/azurecloud/platform.py
index 77f159eb..cb62a74b 100644
--- a/tests/cloud_tests/platforms/azurecloud/platform.py
+++ b/tests/cloud_tests/platforms/azurecloud/platform.py
@@ -74,8 +74,9 @@ class AzureCloudPlatform(Platform):
         @param user_data: test user-data to pass to instance
         @return_value: cloud_tests.instances instance
         """
-        user_data = str(base64.b64encode(
-            user_data.encode('utf-8')), 'utf-8')
+        if user_data is not None:
+            user_data = str(base64.b64encode(
+                user_data.encode('utf-8')), 'utf-8')
 
         return AzureCloudInstance(self, properties, config, features,
                                   image_id, user_data)
diff --git a/tests/cloud_tests/setup_image.py b/tests/cloud_tests/setup_image.py
index a8aaba15..69e66e3f 100644
--- a/tests/cloud_tests/setup_image.py
+++ b/tests/cloud_tests/setup_image.py
@@ -229,7 +229,7 @@ def setup_image(args, image):
     except Exception as e:
         info = "N/A (%s)" % e
 
-    LOG.info('setting up %s (%s)', image, info)
+    LOG.info('setting up image %s (info %s)', image, info)
     res = stage.run_stage(
         'set up for {}'.format(image), calls, continue_after_error=False)
     return res