From 2fde2294d8fcf536acf640f5840c4e551b9dd433 Mon Sep 17 00:00:00 2001 From: Johannes Erdfelt Date: Thu, 5 Apr 2012 21:26:10 +0000 Subject: [PATCH] Cleanup xenapi driver logging messages to include instance Also, use the logging instance kwarg so it gets logged in a consistent format. Change-Id: I4429e9660ff72e1f79d889f89b5abbf1949720de --- nova/tests/test_xenapi.py | 20 ++-- nova/utils.py | 4 +- nova/virt/xenapi/vm_utils.py | 79 +++++++-------- nova/virt/xenapi/vmops.py | 189 +++++++++++++++++------------------ 4 files changed, 140 insertions(+), 152 deletions(-) diff --git a/nova/tests/test_xenapi.py b/nova/tests/test_xenapi.py index b15daa7e6110..9539c5cbe976 100644 --- a/nova/tests/test_xenapi.py +++ b/nova/tests/test_xenapi.py @@ -895,11 +895,11 @@ class XenAPIMigrateInstance(test.TestCase): db.migration_get_all_unconfirmed(fake_context, resize_confirm_window).AndReturn(migrations) # Found unconfirmed migrations message - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) # test success (ACTIVE/RESIZE_VERIFY) instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndReturn(instance) conn._vmops.compute_api.confirm_resize(fake_context, @@ -908,7 +908,7 @@ class XenAPIMigrateInstance(test.TestCase): # test instance that doesn't exist anymore sets migration to # error instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndRaise(exception.InstanceNotFound) vmops.LOG.warn(mox.IgnoreArg()) @@ -916,32 +916,32 @@ class XenAPIMigrateInstance(test.TestCase): # test instance in ERROR/RESIZE_VERIFY sets migration to error instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndReturn(instance) - vmops.LOG.warn(mox.IgnoreArg()) + vmops.LOG.warn(mox.IgnoreArg(), instance=instance) db.migration_update(fake_context, 3, {'status': 'error'}) # test instance in ACTIVE/REBOOTING sets migration to error instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndReturn(instance) - vmops.LOG.warn(mox.IgnoreArg()) + vmops.LOG.warn(mox.IgnoreArg(), instance=instance) db.migration_update(fake_context, 4, {'status': 'error'}) # test confirm_resize raises and doesn't set migration to error instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndReturn(instance) conn._vmops.compute_api.confirm_resize(fake_context, instance).AndRaise(test.TestingException) - vmops.LOG.error(mox.IgnoreArg()) + vmops.LOG.error(mox.IgnoreArg(), instance=instance) # test succeeds again (ACTIVE/RESIZE_VERIFY) instance = instances.pop(0) - vmops.LOG.info(mox.IgnoreArg()) + vmops.LOG.info(mox.IgnoreArg(), mox.IgnoreArg()) db.instance_get_by_uuid(fake_context, instance['uuid']).AndReturn(instance) conn._vmops.compute_api.confirm_resize(fake_context, diff --git a/nova/utils.py b/nova/utils.py index 8119861c695b..65d0c68293f0 100644 --- a/nova/utils.py +++ b/nova/utils.py @@ -1715,7 +1715,7 @@ class UndoManager(object): for undo_func in reversed(self.undo_stack): undo_func() - def rollback_and_reraise(self, msg=None): + def rollback_and_reraise(self, msg=None, **kwargs): """Rollback a series of actions then re-raise the exception. .. note:: (sirp) This should only be called within an @@ -1723,6 +1723,6 @@ class UndoManager(object): """ with save_and_reraise_exception(): if msg: - LOG.exception(msg) + LOG.exception(msg, **kwargs) self._rollback() diff --git a/nova/virt/xenapi/vm_utils.py b/nova/virt/xenapi/vm_utils.py index 1a5ad098717a..70dc64f74458 100644 --- a/nova/virt/xenapi/vm_utils.py +++ b/nova/virt/xenapi/vm_utils.py @@ -214,10 +214,8 @@ class VMHelper(xenapi.HelperBase): rec['HVM_boot_params'] = {'order': 'dc'} rec['HVM_boot_policy'] = 'BIOS order' - LOG.debug(_('Created VM %s...'), instance.name) vm_ref = session.call_xenapi('VM.create', rec) - instance_name = instance.name - LOG.debug(_('Created VM %(instance_name)s as %(vm_ref)s.') % locals()) + LOG.debug(_('Created VM'), instance=instance) return vm_ref @classmethod @@ -378,8 +376,8 @@ class VMHelper(xenapi.HelperBase): def create_snapshot(cls, session, instance, vm_ref, label): """Creates Snapshot (Template) VM, Snapshot VBD, Snapshot VDI, Snapshot VHD""" - LOG.debug(_("Snapshotting VM %(vm_ref)s with label '%(label)s'...") - % locals()) + LOG.debug(_("Snapshotting with label '%(label)s'"), locals(), + instance=instance) vm_vdi_ref, vm_vdi_rec = cls.get_vdi_for_vm_safely(session, vm_ref) sr_ref = vm_vdi_rec["SR"] @@ -391,8 +389,8 @@ class VMHelper(xenapi.HelperBase): template_vm_ref)[1] template_vdi_uuid = template_vdi_rec["uuid"] - LOG.debug(_('Created snapshot %(template_vm_ref)s from' - ' VM %(vm_ref)s.') % locals()) + LOG.debug(_('Created snapshot %(template_vm_ref)s'), locals(), + instance=instance) parent_uuid, base_uuid = _wait_for_vhd_coalesce( session, instance, sr_ref, vm_vdi_ref, original_parent_uuid) @@ -431,7 +429,7 @@ class VMHelper(xenapi.HelperBase): # NOTE(sirp): Currently we only support uploading images as VHD, there # is no RAW equivalent (yet) LOG.debug(_("Asking xapi to upload %(vdi_uuids)s as" - " ID %(image_id)s") % locals()) + " ID %(image_id)s"), locals(), instance=instance) glance_host, glance_port = glance.pick_glance_api_server() @@ -582,11 +580,9 @@ class VMHelper(xenapi.HelperBase): req_type = instance_types.get_instance_type(instance_type_id) req_size = req_type['root_gb'] - LOG.debug("Creating blank HD of size %(req_size)d gigs" - % locals()) + LOG.debug(_("Creating blank HD of size %(req_size)d gigs"), locals()) vdi_size = one_gig * req_size - LOG.debug("ISO vm create: Looking for the SR") sr_ref = cls.safe_find_sr(session) vdi_ref = cls.create_vdi(session, sr_ref, 'blank HD', vdi_size, False) @@ -755,8 +751,8 @@ class VMHelper(xenapi.HelperBase): Returns: A list of dictionaries that describe VDIs """ - LOG.debug(_("Asking xapi to fetch vhd image %(image)s") - % locals()) + LOG.debug(_("Asking xapi to fetch vhd image %(image)s"), locals(), + instance=instance) sr_ref = cls.safe_find_sr(session) vdis = cls._retry_glance_download_vhd(context, session, image) @@ -766,7 +762,8 @@ class VMHelper(xenapi.HelperBase): # 'vdi_type' can be 'os' or 'swap' right now. for vdi in vdis: LOG.debug(_("xapi 'download_vhd' returned VDI of " - "type '%(vdi_type)s' with UUID '%(vdi_uuid)s'") % vdi) + "type '%(vdi_type)s' with UUID '%(vdi_uuid)s'"), + vdi, instance=instance) cls.scan_sr(session, sr_ref) @@ -810,13 +807,12 @@ class VMHelper(xenapi.HelperBase): allowed_size_bytes = allowed_size_gb * 1024 * 1024 * 1024 LOG.debug(_("image_size_bytes=%(size_bytes)d, allowed_size_bytes=" - "%(allowed_size_bytes)d") % locals()) + "%(allowed_size_bytes)d"), locals(), instance=instance) if size_bytes > allowed_size_bytes: - LOG.info(_("Image size %(size_bytes)d exceeded" - " instance_type allowed size " - "%(allowed_size_bytes)d") - % locals()) + LOG.info(_("Image size %(size_bytes)d exceeded instance_type " + "allowed size %(allowed_size_bytes)d"), + locals(), instance=instance) raise exception.ImageTooLarge() @classmethod @@ -832,16 +828,15 @@ class VMHelper(xenapi.HelperBase): Returns: A single filename if image_type is KERNEL_RAMDISK A list of dictionaries that describe VDIs, otherwise """ - instance_id = instance.id # FIXME(sirp): Since the Glance plugin seems to be required for the # VHD disk, it may be worth using the plugin for both VHD and RAW and # DISK restores - LOG.debug(_("Fetching image %(image)s") % locals()) - LOG.debug(_("Image Type: %s"), ImageType.to_string(image_type)) + image_type_str = ImageType.to_string(image_type) + LOG.debug(_("Fetching image %(image)s, type %(image_type_str)"), + locals(), instance=instance) if image_type == ImageType.DISK_ISO: sr_ref = cls.safe_find_iso_sr(session) - LOG.debug(_("ISO: Found sr possibly containing the ISO image")) else: sr_ref = cls.safe_find_sr(session) @@ -850,7 +845,8 @@ class VMHelper(xenapi.HelperBase): meta, image_file = glance_client.get_image(image_id) virtual_size = int(meta['size']) vdi_size = virtual_size - LOG.debug(_("Size for image %(image)s: %(virtual_size)d"), locals()) + LOG.debug(_("Size for image %(image)s: %(virtual_size)d"), locals(), + instance=instance) if image_type == ImageType.DISK: # Make room for MBR. vdi_size += MBR_SIZE_BYTES @@ -875,7 +871,8 @@ class VMHelper(xenapi.HelperBase): if image_type in (ImageType.KERNEL, ImageType.RAMDISK): # We need to invoke a plugin for copying the # content of the VDI into the proper path. - LOG.debug(_("Copying VDI %s to /boot/guest on dom0"), vdi_ref) + LOG.debug(_("Copying VDI %s to /boot/guest on dom0"), + vdi_ref, instance=instance) fn = "copy_kernel_vdi" args = {} args['vdi-ref'] = vdi_ref @@ -888,7 +885,8 @@ class VMHelper(xenapi.HelperBase): # Remove the VDI as it is not needed anymore. cls.destroy_vdi(session, vdi_ref) - LOG.debug(_("Kernel/Ramdisk VDI %s destroyed"), vdi_ref) + LOG.debug(_("Kernel/Ramdisk VDI %s destroyed"), vdi_ref, + instance=instance) return [dict(vdi_type=ImageType.to_string(image_type), vdi_uuid=None, file=filename)] @@ -898,8 +896,8 @@ class VMHelper(xenapi.HelperBase): file=None)] except (cls.XenAPI.Failure, IOError, OSError) as e: # We look for XenAPI and OS failures. - LOG.exception(_("instance %s: Failed to fetch glance image"), - instance_id) + LOG.exception(_("Failed to fetch glance image"), + instance=instance) e.args = e.args + ([dict(vdi_type=ImageType. to_string(image_type), vdi_uuid=vdi_uuid, @@ -1421,8 +1419,8 @@ def _wait_for_vhd_coalesce(session, instance, sr_ref, vdi_ref, parent_uuid = get_vhd_parent_uuid(session, vdi_ref) if original_parent_uuid and (parent_uuid != original_parent_uuid): LOG.debug(_("Parent %(parent_uuid)s doesn't match original parent" - " %(original_parent_uuid)s, waiting for coalesce...") - % locals()) + " %(original_parent_uuid)s, waiting for coalesce..."), + locals(), instance=instance) else: parent_ref = session.call_xenapi("VDI.get_by_uuid", parent_uuid) base_uuid = get_vhd_parent_uuid(session, parent_ref) @@ -1569,7 +1567,7 @@ def _write_partition(virtual_size, dev): primary_last = MBR_SIZE_SECTORS + (virtual_size / SECTOR_SIZE) - 1 LOG.debug(_('Writing partition table %(primary_first)d %(primary_last)d' - ' to %(dev_path)s...') % locals()) + ' to %(dev_path)s...'), locals()) def execute(*cmd, **kwargs): return utils.execute(*cmd, **kwargs) @@ -1637,7 +1635,7 @@ def _sparse_copy(src_path, dst_path, virtual_size, block_size=4096): LOG.debug(_("Starting sparse_copy src=%(src_path)s dst=%(dst_path)s " "virtual_size=%(virtual_size)d block_size=%(block_size)d"), - locals()) + locals()) # NOTE(sirp): we need read/write access to the devices; since we don't have # the luxury of shelling out to a sudo'd command, we temporarily take @@ -1718,19 +1716,19 @@ def _find_guest_agent(base_dir, agent_rel_path): # so manipulation of files in /etc is not # required LOG.info(_('XenServer tools installed in this ' - 'image are capable of network injection. ' - 'Networking files will not be' - 'manipulated')) + 'image are capable of network injection. ' + 'Networking files will not be' + 'manipulated')) return True xe_daemon_filename = os.path.join(base_dir, 'usr', 'sbin', 'xe-daemon') if os.path.isfile(xe_daemon_filename): LOG.info(_('XenServer tools are present ' - 'in this image but are not capable ' - 'of network injection')) + 'in this image but are not capable ' + 'of network injection')) else: LOG.info(_('XenServer tools are not ' - 'installed in this image')) + 'installed in this image')) return False @@ -1745,8 +1743,7 @@ def _mounted_processing(device, key, net, metadata): try: # This try block ensures that the umount occurs if not _find_guest_agent(tmpdir, FLAGS.xenapi_agent_path): - LOG.info(_('Manipulating interface files ' - 'directly')) + LOG.info(_('Manipulating interface files directly')) # for xenapi, we don't 'inject' admin_password here, # it's handled at instance startup time disk.inject_data_into_fs(tmpdir, @@ -1756,7 +1753,7 @@ def _mounted_processing(device, key, net, metadata): utils.execute('umount', dev_path, run_as_root=True) else: LOG.info(_('Failed to mount filesystem (expected for ' - 'non-linux instances): %s') % err) + 'non-linux instances): %s') % err) def _prepare_injectables(inst, networks_info): diff --git a/nova/virt/xenapi/vmops.py b/nova/virt/xenapi/vmops.py index 6e3c79ba08bb..07d5a8cc80f0 100644 --- a/nova/virt/xenapi/vmops.py +++ b/nova/virt/xenapi/vmops.py @@ -128,8 +128,8 @@ def make_step_decorator(context, instance): step_info['current'] += 1 progress = round(float(step_info['current']) / step_info['total'] * 100) - LOG.debug(_("Updating instance '%(instance_uuid)s' progress to" - " %(progress)d") % locals()) + LOG.debug(_("Updating progress to %(progress)d"), locals(), + instance=instance) db.instance_update(context, instance_uuid, {'progress': progress}) def step_decorator(f): @@ -230,7 +230,7 @@ class VMOps(object): if vm_ref is None: raise Exception(_('Attempted to power on non-existent instance' ' bad instance id %s') % instance.id) - LOG.debug(_("Starting instance %s"), instance.name) + LOG.debug(_("Starting instance"), instance=instance) self._session.call_xenapi('VM.start_on', vm_ref, self._session.get_xenapi_host(), False, False) @@ -300,7 +300,8 @@ class VMOps(object): def undo_create_kernel_ramdisk(): if kernel_file or ramdisk_file: - LOG.debug(_("Removing kernel/ramdisk files from dom0")) + LOG.debug(_("Removing kernel/ramdisk files from dom0"), + instance=instance) self._destroy_kernel_ramdisk_plugin_call(kernel_file, ramdisk_file) undo_mgr.undo_with(undo_create_kernel_ramdisk) @@ -354,10 +355,8 @@ class VMOps(object): apply_security_group_filters_step(undo_mgr) except Exception: - instance_uuid = instance['uuid'] - msg = _("Instance %(instance_uuid)s: Failed to spawn, rolling" - " back.") % locals() - undo_mgr.rollback_and_reraise(msg=msg) + msg = _("Failed to spawn, rolling back") + undo_mgr.rollback_and_reraise(msg=msg, instance=instance) def spawn_rescue(self, context, instance, image_meta, network_info): """Spawn a rescue instance.""" @@ -436,15 +435,13 @@ class VMOps(object): vdis): ctx = nova_context.get_admin_context() - instance_uuid = instance['uuid'] - # device 0 reserved for RW disk userdevice = 0 # DISK_ISO needs two VBDs: the ISO disk and a blank RW disk if disk_image_type == vm_utils.ImageType.DISK_ISO: - LOG.debug("detected ISO image type, going to create blank VM for " - "install") + LOG.debug(_("Detected ISO image type, creating blank VM " + "for install"), instance=instance) cd_vdi_ref = first_vdi_ref first_vdi_ref = VMHelper.fetch_blank_disk(self._session, @@ -462,9 +459,8 @@ class VMOps(object): userdevice += 1 else: if instance.auto_disk_config: - LOG.debug(_("Auto configuring disk for instance" - " %(instance_uuid)s, attempting to" - " resize partition...") % locals()) + LOG.debug(_("Auto configuring disk, attempting to " + "resize partition..."), instance=instance) instance_type = db.instance_type_get(ctx, instance.instance_type_id) VMHelper.auto_configure_disk(self._session, @@ -516,40 +512,37 @@ class VMOps(object): try: injected_files = json.loads(injected_files) except ValueError: - LOG.exception( - _("Invalid value for injected_files: '%s'") - % injected_files) + LOG.exception(_("Invalid value for injected_files: %r"), + injected_files, instance=instance) injected_files = [] # Inject any files, if specified for path, contents in instance.injected_files: - LOG.debug(_("Injecting file path: '%s'") % path) + LOG.debug(_("Injecting file path: '%s'") % path, + instance=instance) self.inject_file(instance, path, contents) admin_password = instance.admin_pass # Set admin password, if necessary if admin_password and not skip_set_password: - LOG.debug(_("Setting admin password")) + LOG.debug(_("Setting admin password"), instance=instance) self.set_admin_password(instance, admin_password) # Reset network config - LOG.debug(_("Resetting network")) + LOG.debug(_("Resetting network"), instance=instance) self.reset_network(instance, vm_ref) # Set VCPU weight inst_type = db.instance_type_get(ctx, instance.instance_type_id) vcpu_weight = inst_type['vcpu_weight'] if vcpu_weight is not None: - LOG.debug(_("Setting VCPU weight")) + LOG.debug(_("Setting VCPU weight"), instance=instance) self._session.call_xenapi("VM.add_to_VCPUs_params", vm_ref, "weight", str(vcpu_weight)) def _spawn(self, instance, vm_ref): """Spawn a new instance.""" - LOG.debug(_('Starting VM %s...'), vm_ref) + LOG.debug(_('Starting VM'), instance=instance) self._start(instance, vm_ref) - instance_uuid = instance.uuid - LOG.info(_('Spawning VM %(instance_uuid)s created %(vm_ref)s.') - % locals()) ctx = nova_context.get_admin_context() agent_build = db.agent_build_get_by_triple(ctx, 'xen', @@ -565,7 +558,8 @@ class VMOps(object): 'architecture': instance.architecture}) # Wait for boot to finish - LOG.debug(_('Instance %s: waiting for running'), instance_uuid) + LOG.debug(_('Waiting for instance state to become running'), + instance=instance) expiration = time.time() + FLAGS.xenapi_running_timeout while time.time() < expiration: state = self.get_info(instance)['state'] @@ -574,18 +568,18 @@ class VMOps(object): greenthread.sleep(0.5) - LOG.debug(_('Instance %s: running'), instance_uuid) - # Update agent, if necessary # This also waits until the agent starts - LOG.debug(_("Querying agent version")) + LOG.debug(_("Querying agent version"), instance=instance) version = self.get_agent_version(instance) if version: - LOG.info(_('Instance agent version: %s') % version) + LOG.info(_('Instance agent version: %s'), version, + instance=instance) if (version and agent_build and cmp_version(version, agent_build['version']) < 0): - LOG.info(_('Updating Agent to %s') % agent_build['version']) + LOG.info(_('Updating Agent to %s'), agent_build['version'], + instance=instance) self.agent_update(instance, agent_build['url'], agent_build['md5hash']) @@ -673,15 +667,14 @@ class VMOps(object): self._destroy(instance, template_vm_ref, shutdown=False, destroy_kernel_ramdisk=False) - LOG.debug(_("Finished snapshot and upload for VM %s"), - instance['uuid']) + LOG.debug(_("Finished snapshot and upload for VM"), + instance=instance) def _create_snapshot(self, instance): #TODO(sirp): Add quiesce and VSS locking support when Windows support # is added - instance_uuid = instance.uuid - LOG.debug(_("Starting snapshot for VM %s") % instance_uuid) + LOG.debug(_("Starting snapshot for VM"), instance=instance) vm_ref = VMHelper.lookup(self._session, instance.name) label = "%s-snapshot" % instance.name @@ -690,8 +683,8 @@ class VMOps(object): self._session, instance, vm_ref, label) return template_vm_ref, template_vdi_uuids except self.XenAPI.Failure, exc: - LOG.error(_("Unable to Snapshot instance %(instance_uuid)s: " - "%(exc)s") % locals()) + LOG.error(_("Unable to Snapshot instance: %(exc)s"), locals(), + instance=instance) raise def _migrate_vhd(self, instance, vdi_uuid, dest, sr_path): @@ -726,8 +719,8 @@ class VMOps(object): # has been streamed to the destination host. progress = round(float(step) / total_steps * 100) instance_uuid = instance['uuid'] - LOG.debug(_("Updating instance '%(instance_uuid)s' progress to" - " %(progress)d") % locals()) + LOG.debug(_("Updating progress to %(progress)d"), locals(), + instance=instance) db.instance_update(context, instance_uuid, {'progress': progress}) def migrate_disk_and_power_off(self, context, instance, dest, @@ -775,7 +768,8 @@ class VMOps(object): new_gb = instance_type['root_gb'] LOG.debug(_("Resizing down VDI %(cow_uuid)s from " - "%(old_gb)dGB to %(new_gb)dGB") % locals()) + "%(old_gb)dGB to %(new_gb)dGB"), locals(), + instance=instance) # 2. Power down the instance before resizing self._shutdown(instance, vm_ref, hard=False) @@ -897,14 +891,14 @@ class VMOps(object): if virtual_size < new_disk_size: # Resize up. Simple VDI resize will do the trick LOG.debug(_("Resizing up VDI %(vdi_uuid)s from %(old_gb)dGB to " - "%(new_gb)dGB") % locals()) + "%(new_gb)dGB"), locals(), instance=instance) if self._session.product_version[0] > 5: resize_func_name = 'VDI.resize' else: resize_func_name = 'VDI.resize_online' self._session.call_xenapi(resize_func_name, vdi_ref, str(new_disk_size)) - LOG.debug(_("Resize instance %s complete") % (instance.uuid)) + LOG.debug(_("Resize complete"), instance=instance) def reboot(self, instance, reboot_type): """Reboot VM instance.""" @@ -931,8 +925,8 @@ class VMOps(object): # Send the encrypted password resp = self._make_agent_call('version', instance) if resp['returncode'] != '0': - LOG.error(_('Failed to query agent version: %(resp)r') % - locals()) + LOG.error(_('Failed to query agent version: %(resp)r'), + locals(), instance=instance) return None # Some old versions of the Windows agent have a trailing \\r\\n # (ie CRLF escaped) for some reason. Strip that off. @@ -951,10 +945,9 @@ class VMOps(object): vm_rec = self._session.call_xenapi("VM.get_record", vm_ref) if vm_rec['domid'] != domid: - LOG.info(_('domid changed from %(olddomid)s to ' - '%(newdomid)s') % { - 'olddomid': domid, - 'newdomid': vm_rec['domid']}) + newdomid = vm_rec['domid'] + LOG.info(_('domid changed from %(domid)s to %(newdomid)s'), + locals(), instance=instance) domid = vm_rec['domid'] return None @@ -966,7 +959,8 @@ class VMOps(object): args = {'url': url, 'md5sum': md5sum} resp = self._make_agent_call('agentupdate', instance, args) if resp['returncode'] != '0': - LOG.error(_('Failed to update agent: %(resp)r') % locals()) + LOG.error(_('Failed to update agent: %(resp)r'), locals(), + instance=instance) return None return resp['message'] @@ -987,7 +981,7 @@ class VMOps(object): # Successful return code from key_init is 'D0' if resp['returncode'] != 'D0': msg = _('Failed to exchange keys: %(resp)r') % locals() - LOG.error(msg) + LOG.error(msg, instance=instance) raise Exception(msg) # Some old versions of the Windows agent have a trailing \\r\\n # (ie CRLF escaped) for some reason. Strip that off. @@ -1002,7 +996,7 @@ class VMOps(object): # Successful return code from password is '0' if resp['returncode'] != '0': msg = _('Failed to update password: %(resp)r') % locals() - LOG.error(msg) + LOG.error(msg, instance=instance) raise Exception(msg) return resp['message'] @@ -1026,21 +1020,20 @@ class VMOps(object): # will be raised with the appropriate message. resp = self._make_agent_call('inject_file', instance, args) if resp['returncode'] != '0': - LOG.error(_('Failed to inject file: %(resp)r') % locals()) + LOG.error(_('Failed to inject file: %(resp)r'), locals(), + instance=instance) return None return resp['message'] def _shutdown(self, instance, vm_ref, hard=True): """Shutdown an instance.""" - instance_uuid = instance.uuid state = self.get_info(instance)['state'] if state == power_state.SHUTDOWN: - LOG.warn(_("VM %(instance_uuid)s already halted," - "skipping shutdown...") % locals()) + LOG.warn(_("VM already halted, skipping shutdown..."), + instance=instance) return - LOG.debug(_("Shutting down VM for Instance %(instance_uuid)s") - % locals()) + LOG.debug(_("Shutting down VM"), instance=instance) try: task = None if hard: @@ -1101,8 +1094,8 @@ class VMOps(object): instance_uuid = instance['uuid'] if not instance.kernel_id and not instance.ramdisk_id: # 1. No kernel or ramdisk - LOG.debug(_("Instance %(instance_uuid)s using RAW or VHD, " - "skipping kernel and ramdisk deletion") % locals()) + LOG.debug(_("Using RAW or VHD, skipping kernel and ramdisk " + "deletion"), instance=instance) return if not (instance.kernel_id and instance.ramdisk_id): @@ -1115,17 +1108,17 @@ class VMOps(object): vm_ref) self._destroy_kernel_ramdisk_plugin_call(kernel, ramdisk) - LOG.debug(_("kernel/ramdisk files removed")) + LOG.debug(_("kernel/ramdisk files removed"), instance=instance) def _destroy_vm(self, instance, vm_ref): """Destroys a VM record.""" - instance_uuid = instance['uuid'] try: self._session.call_xenapi('VM.destroy', vm_ref) except self.XenAPI.Failure, exc: LOG.exception(exc) + return - LOG.debug(_("Instance %(instance_uuid)s VM destroyed") % locals()) + LOG.debug(_("VM destroyed"), instance=instance) def _destroy_rescue_instance(self, rescue_vm_ref, original_vm_ref): """Destroy a rescue instance.""" @@ -1151,8 +1144,7 @@ class VMOps(object): destroy_* methods are internal. """ - instance_uuid = instance['uuid'] - LOG.info(_("Destroying VM for Instance %(instance_uuid)s") % locals()) + LOG.info(_("Destroying VM"), instance=instance) vm_ref = VMHelper.lookup(self._session, instance.name) @@ -1174,7 +1166,8 @@ class VMOps(object): """ if vm_ref is None: - LOG.warning(_("VM is not present, skipping destroy...")) + LOG.warning(_("VM is not present, skipping destroy..."), + instance=instance) return is_snapshot = VMHelper.is_snapshot(self._session, vm_ref) if shutdown: @@ -1301,10 +1294,10 @@ class VMOps(object): if instances_info["instance_count"] > 0: LOG.info(_("Found %(instance_count)d hung reboots " - "older than %(timeout)d seconds") % instances_info) + "older than %(timeout)d seconds") % instances_info) for instance in instances: - LOG.info(_("Automatically hard rebooting %d"), instance.id) + LOG.info(_("Automatically hard rebooting"), instance=instance) self.compute_api.reboot(ctxt, instance, "HARD") def poll_rescued_instances(self, timeout): @@ -1363,14 +1356,14 @@ class VMOps(object): if migrations_info["migration_count"] > 0: LOG.info(_("Found %(migration_count)d unconfirmed migrations " - "older than %(confirm_window)d seconds") % migrations_info) + "older than %(confirm_window)d seconds"), + migrations_info) - def _set_migration_to_error(migration_id, reason): + def _set_migration_to_error(migration_id, reason, **kwargs): msg = _("Setting migration %(migration_id)s to error: " "%(reason)s") % locals() - LOG.warn(msg) - db.migration_update( - ctxt, migration_id, {'status': 'error'}) + LOG.warn(msg, **kwargs) + db.migration_update(ctxt, migration_id, {'status': 'error'}) for migration in migrations: # NOTE(comstud): Yield to other greenthreads. Putting this @@ -1378,9 +1371,8 @@ class VMOps(object): greenthread.sleep(0) migration_id = migration['id'] instance_uuid = migration['instance_uuid'] - msg = _("Automatically confirming migration %(migration_id)s " - "for instance %(instance_uuid)s") - LOG.info(msg % locals()) + LOG.info(_("Automatically confirming migration %(migration_id)s " + "for instance %(instance_uuid)s"), locals()) try: instance = db.instance_get_by_uuid(ctxt, instance_uuid) except exception.InstanceNotFound: @@ -1388,21 +1380,22 @@ class VMOps(object): _set_migration_to_error(migration_id, reason % locals()) continue if instance['vm_state'] == vm_states.ERROR: - reason = _("Instance %(instance_uuid)s in ERROR state") - _set_migration_to_error(migration_id, reason % locals()) + reason = _("In ERROR state") + _set_migration_to_error(migration_id, reason % locals(), + instance=instance) continue if instance['task_state'] != task_states.RESIZE_VERIFY: task_state = instance['task_state'] - reason = _("Instance %(instance_uuid)s in %(task_state)s " - "task_state, not RESIZE_VERIFY.") - _set_migration_to_error(migration_id, reason % locals()) + reason = _("In %(task_state)s task_state, not RESIZE_VERIFY") + _set_migration_to_error(migration_id, reason % locals(), + instance=instance) continue try: self.compute_api.confirm_resize(ctxt, instance) except Exception, e: - msg = _("Error auto-confirming resize for instance " - "%(instance_uuid)s: %(e)s. Will retry later.") - LOG.error(msg % locals()) + msg = _("Error auto-confirming resize: %(e)s. " + "Will retry later.") + LOG.error(msg % locals(), instance=instance) def get_info(self, instance): """Return data about VM instance.""" @@ -1473,7 +1466,7 @@ class VMOps(object): self._session.call_xenapi("VM.get_record", vm_ref) else: vm_ref = VMHelper.lookup(self._session, instance.name) - LOG.debug(_("injecting network info to xs for vm: |%s|"), vm_ref) + LOG.debug(_("Injecting network info to xenstore"), instance=instance) for (network, info) in network_info: location = 'vm-data/networking/%s' % info['mac'].replace(':', '') @@ -1487,7 +1480,7 @@ class VMOps(object): def create_vifs(self, vm_ref, instance, network_info): """Creates vifs for an instance.""" - LOG.debug(_("creating vif(s) for vm: |%s|"), vm_ref) + LOG.debug(_("Creating vifs"), instance=instance) # this function raises if vm_ref is not a vm_opaque_ref self._session.call_xenapi("VM.get_record", vm_ref) @@ -1496,11 +1489,11 @@ class VMOps(object): vif_rec = self.vif_driver.plug(instance, network, info, vm_ref=vm_ref, device=device) network_ref = vif_rec['network'] - LOG.debug(_('Creating VIF for VM %(vm_ref)s,' - ' network %(network_ref)s.') % locals()) + LOG.debug(_('Creating VIF for network %(network_ref)s'), + locals(), instance=instance) vif_ref = self._session.call_xenapi('VIF.create', vif_rec) - LOG.debug(_('Created VIF %(vif_ref)s for VM %(vm_ref)s,' - ' network %(network_ref)s.') % locals()) + LOG.debug(_('Created VIF %(vif_ref)s, network %(network_ref)s'), + locals(), instance=instance) def plug_vifs(self, instance, network_info): """Set up VIF networking on the host.""" @@ -1524,7 +1517,7 @@ class VMOps(object): # NOTE(jk0): Windows hostnames can only be <= 15 chars. hostname = hostname[:15] - LOG.debug(_("injecting hostname to xs for vm: |%s|"), vm_ref) + LOG.debug(_("Injecting hostname to xenstore"), instance=instance) self.add_to_param_xenstore(vm_ref, 'vm-data/hostname', hostname) def write_to_xenstore(self, instance, path, value, vm_ref=None): @@ -1549,10 +1542,9 @@ class VMOps(object): try: return json.loads(ret) except TypeError: - instance_uuid = instance['uuid'] LOG.error(_('The agent call to %(method)s returned an invalid' - ' response: %(ret)r. VM id=%(instance_uuid)s;' - ' path=%(path)s; args=%(args)r') % locals()) + ' response: %(ret)r. path=%(path)s; args=%(args)r'), + locals(), instance=instance) return {'returncode': 'error', 'message': 'unable to deserialize response'} @@ -1562,7 +1554,6 @@ class VMOps(object): Abstracts out the process of calling a method of a xenapi plugin. Any errors raised by the plugin will in turn raise a RuntimeError here. """ - instance_uuid = instance['uuid'] vm_ref = vm_ref or self._get_vm_opaque_ref(instance) vm_rec = self._session.call_xenapi("VM.get_record", vm_ref) args = {'dom_id': vm_rec['domid']} @@ -1573,16 +1564,16 @@ class VMOps(object): err_msg = e.details[-1].splitlines()[-1] if 'TIMEOUT:' in err_msg: LOG.error(_('TIMEOUT: The call to %(method)s timed out. ' - 'VM id=%(instance_uuid)s; args=%(args)r') % locals()) + 'args=%(args)r'), locals(), instance=instance) return {'returncode': 'timeout', 'message': err_msg} elif 'NOT IMPLEMENTED:' in err_msg: LOG.error(_('NOT IMPLEMENTED: The call to %(method)s is not' - ' supported by the agent. VM id=%(instance_uuid)s;' - ' args=%(args)r') % locals()) + ' supported by the agent. args=%(args)r'), + locals(), instance=instance) return {'returncode': 'notimplemented', 'message': err_msg} else: LOG.error(_('The call to %(method)s returned an error: %(e)s. ' - 'VM id=%(instance_uuid)s; args=%(args)r') % locals()) + 'args=%(args)r'), locals(), instance=instance) return {'returncode': 'error', 'message': err_msg} return None