Add debug info for deploy/delete/resize

To make debug process conveniently , add more debug logs into
deploy/delete/resize methods , at the top of method and at the
end of the method , to make the process clearly , and print exception
stacktrace if necessary.

The log info should be like this :
1. Enter to $method instance of $instance_uuid
2. Exit to $method instance of $instance_uuid

Change-Id: I6678976c09ba923a0ada68a37a706642c18ed0f0
(cherry picked from commit 13085fefd5)

nova-powervc/powervc/nova/driver/compute/manager.py

@@ -606,10 +606,13 @@ class PowerVCCloudManager(manager.Manager):
         :param force_delete: If True, the instance will be deleted even if the
                task state is set to 'deleting'.
         """
+        LOG.debug(_('Enter to unregister instance of %s .') % local_instance)
 
         # If the instance does not exist then ignore
         if not local_instance:
             LOG.debug(_('Instance does not exist locally'))
+            LOG.debug(_('Exit to unregister instance of %s .')
+                      % local_instance)
             return
 
         instance_ref = local_instance
@@ -624,6 +627,9 @@ class PowerVCCloudManager(manager.Manager):
                 {'task_state': task_states.DELETING, 'progress': 0})
             notifications.send_update(ctx, old_ref, instance_ref,
                                       service='powervc')
+            LOG.debug(_("Sent a notification for the updated state of %s,"
+                        "event type is %s")
+                      % (instance_ref.get('uuid'), 'powervc'))
 
         # Delete the instance from the local database
         try:
@@ -646,6 +652,11 @@ class PowerVCCloudManager(manager.Manager):
         compute.utils.notify_about_instance_usage(
             self.notifier, ctx, instance_ref, 'delete.sync', network_info={},
             system_metadata={}, extra_usage_info={})
+        LOG.debug(_('Send a notification about instance deletion of %s,'
+                    'event type is %s')
+                  % (instance_ref.get('uuid'), 'delete.sync'))
+        LOG.debug(_('Exit to unregister instance of %s .')
+                  % local_instance.get('uuid'))
 
     def _is_pvc_instance(self, ctx, local_instance):
         """
@@ -1521,6 +1532,9 @@ class PowerVCCloudManager(manager.Manager):
         """Remove the local instance if it's not performing a task and
         its vm_state is not BUILDING|DELETED|SOFT_DELETED|DELETING(force).
         """
+        LOG.debug(_('Enter to remove local instance of %s')
+                  % local_instance.get('uuid'))
+
         local_task_state = local_instance.get('task_state')
         local_vm_state = local_instance.get('vm_state')
         LOG.debug(_('Remove local instance %(ins)s, vm_state: %(vm)s, '
@@ -1546,6 +1560,8 @@ class PowerVCCloudManager(manager.Manager):
             local_vm_state != vm_states.BUILDING
         ):
             self._unregister_instance(context, local_instance)
+            LOG.debug(_('Exit to remove local instance of %s')
+                      % local_instance.get('uuid'))
             return True
 
         LOG.debug(_('Skip remove local_instance %(ins)s from local DB, because'
@@ -1757,8 +1773,8 @@ class PowerVCCloudManager(manager.Manager):
                     count_updated_instances += 1
             except Exception, e:
                 count_errors += 1
-                LOG.error(_("_periodic_instance_sync pvc to local: ") + str(e))
-
+                LOG.exception(_("_periodic_instance_sync pvc to local: %s")
+                              % e)
         # Sync. from local nova DB to PowerVC, to remove invalid instances
         # that are not in PowerVC anymore. This only happens during a full
         # sync of all instances.
@@ -1775,8 +1791,8 @@ class PowerVCCloudManager(manager.Manager):
                         count_deleted_instances += 1
             except Exception, e:
                 count_errors += 1
-                LOG.error(_("_periodic_instance_sync local to pvc: " + str(e)))
-
+                LOG.exception(_("_periodic_instance_sync local to pvc: %s")
+                              % e)
         LOG.info(_("""
                     *******************************
                     Instance sync. is complete.

nova-powervc/powervc/nova/driver/virt/powervc/driver.py

@@ -232,8 +232,7 @@ class PowerVCDriver(driver.ComputeDriver):
         :param block_device_info: Information about block devices to be
                                   attached to the instance.
         """
-        LOG.info(_("Deploying instance %(uuid)s") % instance)
-
+        LOG.info(_("Begin to deploy the instance %(uuid)s") % instance)
         # get PowerVC Image id
         pvcimage = self._get_pvc_image_uuid(image_meta)
 
@@ -286,8 +285,8 @@ class PowerVCDriver(driver.ComputeDriver):
                 self._clean_vm_and_save_fault_message(e, e.message,
                                                       context, instance)
 
-        LOG.debug("Succeeded to created instance to spawn: %s" % createdServer)
-
+        LOG.info("Finish to create the instance to spawn: %s successfully"
+                 % createdServer)
         return createdServer
 
     def _clean_vm_and_save_fault_message(self, exp, message, context,
@@ -346,7 +345,10 @@ class PowerVCDriver(driver.ComputeDriver):
         :param destroy_disks: Indicates if disks should be destroyed
 
         """
-        return self._service.destroy(instance)
+        LOG.debug(_("Enter to destroy instance of %(uuid)s") % instance)
+        responseValue = self._service.destroy(instance)
+        LOG.debug(_("Exit to destroy instance of %(uuid)s") % instance)
+        return responseValue
 
     def reboot(self, context, instance, network_info, reboot_type,
                block_device_info=None, bad_volumes_callback=None):
@@ -564,6 +566,7 @@ class PowerVCDriver(driver.ComputeDriver):
         :param power_on: True if the instance should be powered on, False
                          otherwise
         """
+        LOG.debug(_("Enter to resize instance of %(uuid)s") % instance)
         returnvalue = False
 
         if resize_instance:
@@ -586,7 +589,7 @@ class PowerVCDriver(driver.ComputeDriver):
         start the instance directly.
         Based on the above reason, remove the 'power-on' operation.
         """
-
+        LOG.debug(_("Exit to resize instance of %(uuid)s") % instance)
         return returnvalue
 
     def confirm_migration(self, migration, instance, network_info):

nova-powervc/powervc/nova/driver/virt/powervc/service.py

@@ -674,6 +674,8 @@ class PowerVCService(object):
         userdata = instance.user_data   # already base64 encoded by local OS
 
         if not isDefer:
+            LOG.debug(_('Enter to invoke powervc api to deploy instance'
+                        'of %s, isDefer status is %s') % (name, isDefer))
             createdServer = \
                 self._manager.create(name=name,
                                      image=imageUUID,
@@ -688,7 +690,11 @@ class PowerVCService(object):
                                      nics=nics,
                                      hypervisor=hypervisorID,
                                      availability_zone=availability_zone)
+            LOG.debug(_('Exit to invoke powervc api to deploy instance of %s,'
+                        'isDefer status is %s') % (name, isDefer))
         else:
+            LOG.debug(_('Enter to invoke powervc api to deploy instance of %s,'
+                        'isDefer status is %s') % (name, isDefer))
             createdServer = self._manager.create(name=name,
                                                  image=imageUUID,
                                                  flavor=flavorDict,
@@ -701,6 +707,8 @@ class PowerVCService(object):
                                                  # key_data = key_data,
                                                  config_drive=config_drive,
                                                  nics=nics)
+            LOG.debug(_('Exit to invoke powervc api to deploy instance of %s,'
+                        'isDefer status is %s') % (name, isDefer))
 
         LOG.debug(_('Created Server: %s' % createdServer))
         LOG.debug(_(
@@ -813,7 +821,11 @@ class PowerVCService(object):
                       % server_instance.id)
             return True
 
+        LOG.debug(_("Enter to invoke powervc api to delete instance of %s")
+                  % server)
         delete_response = self._manager.delete(server)
+        LOG.debug(_("Exit to invoke powervc api to delete instance of %s")
+                  % server)
 
         self._validate_response(delete_response)
 
@@ -930,8 +942,11 @@ class PowerVCService(object):
         :para body: the body of rest request
 
         """
+        LOG.debug(_("Enter to invoke powervc api to resize instance of %s")
+                  % server.id)
         response = self._manager._resize_pvc(server, props)
-
+        LOG.debug(_("Exit to invoke powervc api to resize instance of %s")
+                  % server.id)
         return response
 
     def resize_instance(self, context, migration, instance,

nova-powervc/test/nova/driver/virt/powervc/test_driver.py

@@ -370,7 +370,7 @@ class PowerVCDriverTestCase(test.NoDBTestCase):
         pvc_driver._service.update_correct_host = MagicMock()
         context = 0
         migration = 0
-        instance = 0
+        instance = {'uuid': '582124fc-2ebb-441c-8418-c742078d2738'}
         disk_info = 0
         network_info = 0
         image_meta = 0