From 84a7945bca43205ce2c92cdd34b27da12749d24f Mon Sep 17 00:00:00 2001 From: Alex Kavanagh Date: Fri, 1 Jun 2018 15:40:14 +0100 Subject: [PATCH] Fix broken debug logs and modernise string interpolation Some of the debug logs were not actually outputing the instance; it was just tagged in the LOF.(...) command. Also took the opportunity to modernise to '.format()' the string interpolation to meet current guidelines. Change-Id: I99c56ff738713140b2af16199e9e58b39bb4e396 Closes-Bug: #1657339 --- nova/virt/lxd/driver.py | 53 ++++++----- nova/virt/lxd/flavor.py | 6 +- nova/virt/lxd/session.py | 87 +++++++++---------- nova/virt/lxd/storage.py | 4 +- nova/virt/lxd/vif.py | 10 ++- .../tests/scenario/manager.py | 81 +++++++++-------- .../tests/scenario/test_volume_ops.py | 2 +- tools/db/schema_diff.py | 14 +-- 8 files changed, 131 insertions(+), 126 deletions(-) diff --git a/nova/virt/lxd/driver.py b/nova/virt/lxd/driver.py index 38ff0857..ec486ba7 100644 --- a/nova/virt/lxd/driver.py +++ b/nova/virt/lxd/driver.py @@ -123,10 +123,9 @@ def _last_bytes(file_like_object, num): def _neutron_failed_callback(event_name, instance): - LOG.error('Neutron Reported failure on event ' - '%(event)s for instance %(uuid)s', - {'event': event_name, 'uuid': instance.name}, - instance=instance) + LOG.error("Neutron Reported failure on event " + "{event} for instance {uuid}" + .format(event=event_name, uuid=instance.name)) if CONF.vif_plugging_is_fatal: raise exception.VirtualInterfaceCreateException() @@ -140,7 +139,7 @@ def _get_cpu_info(): cpuinfo = {} out, err = utils.execute('lscpu') if err: - msg = _('Unable to parse lscpu output.') + msg = _("Unable to parse lscpu output.") raise exception.NovaException(msg) cpu = [line.strip('\n') for line in out.splitlines()] @@ -211,7 +210,7 @@ def _get_zpool_info(pool_or_dataset): pool_or_dataset, run_as_root=True) if err: - msg = _('Unable to parse zfs output.') + msg = _("Unable to parse zfs output.") raise exception.NovaException(msg) value = int(value.strip()) return value @@ -280,7 +279,7 @@ def _sync_glance_image_to_lxd(client, context, image_ref): image = IMAGE_API.get(context, image_ref) if image.get('disk_format') not in ACCEPTABLE_IMAGE_FORMATS: raise exception.ImageUnacceptable( - image_id=image_ref, reason=_('Bad image format')) + image_id=image_ref, reason=_("Bad image format")) IMAGE_API.download(context, image_ref, dest_path=image_file) # It is possible that LXD already have the same image @@ -307,10 +306,10 @@ def _sync_glance_image_to_lxd(client, context, image_ref): fingerprint = lxdimage_fingerprint() if client.images.exists(fingerprint): - LOG.info( - 'Image with fingerprint %(fingerprint)s already exists' - 'but not accessible by alias %(alias)s, add alias', - {'fingerprint': fingerprint, 'alias': image_ref}) + LOG.info("Image with fingerprint {fingerprint} already " + "exists but not accessible by alias {alias}, " + "add alias" + .format(fingerprint=fingerprint, alias=image_ref)) lxdimage = client.images.get(fingerprint) lxdimage.add_alias(image_ref, '') return True @@ -341,9 +340,9 @@ def _sync_glance_image_to_lxd(client, context, image_ref): return False if imagefile_has_metadata(image_file): - LOG.info('Image %(alias)s already has metadata, ' - 'skipping metadata injection...', - {'alias': image_ref}) + LOG.info("Image {alias} already has metadata, " + "skipping metadata injection..." + .format(alias=image_ref)) with open(image_file, 'rb') as image: image = client.images.create(image, wait=True) else: @@ -462,7 +461,7 @@ class LXDDriver(driver.ComputeDriver): try: self.client = pylxd.Client() except lxd_exceptions.ClientConnectionFailed as e: - msg = _('Unable to connect to LXD daemon: %s') % e + msg = _("Unable to connect to LXD daemon: {}").format(e) raise exception.HostNotFound(msg) self._after_reboot() @@ -543,8 +542,9 @@ class LXDDriver(driver.ComputeDriver): error_callback=_neutron_failed_callback): self.plug_vifs(instance, network_info) except eventlet.timeout.Timeout: - LOG.warn('Timeout waiting for vif plugging callback for ' - 'instance %(uuid)s', {'uuid': instance['name']}) + LOG.warn("Timeout waiting for vif plugging callback for " + "instance {uuid}" + .format(uuid=instance['name'])) if CONF.vif_plugging_is_fatal: self.destroy( context, instance, network_info, block_device_info) @@ -637,9 +637,9 @@ class LXDDriver(driver.ComputeDriver): rescued_container.delete(wait=True) except lxd_exceptions.LXDAPIException as e: if e.response.status_code == 404: - LOG.warning('Failed to delete instance. ' - 'Container does not exist for %(instance)s.', - {'instance': instance.name}) + LOG.warning("Failed to delete instance. " + "Container does not exist for {instance}." + .format(instance=instance.name)) else: raise finally: @@ -673,9 +673,9 @@ class LXDDriver(driver.ComputeDriver): self.client.profiles.get(instance.name).delete() except lxd_exceptions.LXDAPIException as e: if e.response.status_code == 404: - LOG.warning('Failed to delete instance. ' - 'Profile does not exist for %(instance)s.', - {'instance': instance.name}) + LOG.warning("Failed to delete instance. " + "Profile does not exist for {instance}." + .format(instance=instance.name)) else: raise @@ -1200,7 +1200,7 @@ class LXDDriver(driver.ComputeDriver): def check_can_live_migrate_source(self, context, instance, dest_check_data, block_device_info=None): if not CONF.lxd.allow_live_migration: - msg = _('Live migration is not enabled.') + msg = _("Live migration is not enabled.") LOG.error(msg, instance=instance) raise exception.MigrationPreCheckError(reason=msg) return dest_check_data @@ -1272,9 +1272,8 @@ class LXDDriver(driver.ComputeDriver): cdb.make_drive(iso_path) except processutils.ProcessExecutionError as e: with excutils.save_and_reraise_exception(): - LOG.error('Creating config drive failed with ' - 'error: %s', - e, instance=instance) + LOG.error("Creating config drive failed with error: {}" + .format(e)) configdrive_dir = os.path.join( nova.conf.CONF.instances_path, instance.name, 'configdrive') diff --git a/nova/virt/lxd/flavor.py b/nova/virt/lxd/flavor.py index f94a44be..6d93e8ad 100644 --- a/nova/virt/lxd/flavor.py +++ b/nova/virt/lxd/flavor.py @@ -65,7 +65,7 @@ def _isolated(instance, client): if 'id_map' in extensions: return {'security.idmap.isolated': 'True'} else: - msg = _('Host does not support isolated instances') + msg = _("Host does not support isolated instances") raise exception.NovaException(msg) @@ -118,7 +118,7 @@ def _root(instance, client, *_): if 'storage' in extensions: device['pool'] = CONF.lxd.pool else: - msg = _('Host does not have storage pool support') + msg = _("Host does not have storage pool support") raise exception.NovaException(msg) return {'root': device} @@ -142,7 +142,7 @@ def _ephemeral_storage(instance, client, __, block_info): if 'storage' in extensions: device['pool'] = CONF.lxd.pool else: - msg = _('Host does not have storage pool support') + msg = _("Host does not have storage pool support") raise exception.NovaException(msg) devices[ephemeral['virtual_name']] = device return devices diff --git a/nova/virt/lxd/session.py b/nova/virt/lxd/session.py index da1ab0f5..9988e9ff 100644 --- a/nova/virt/lxd/session.py +++ b/nova/virt/lxd/session.py @@ -52,7 +52,7 @@ class LXDAPISession(object): except Exception as ex: # notify the compute host that the connection failed # via an rpc call - LOG.exception('Connection to LXD failed') + LOG.exception("Connection to LXD failed") payload = dict(ip=CONF.host, method='_connect', reason=ex) @@ -70,13 +70,11 @@ class LXDAPISession(object): :param config: LXD container config as a dict :param instance: nova instance object :param host: perform initialization on perfered host - """ - LOG.debug('container_init called for instance', instance=instance) try: - LOG.info('Creating container %(instance)s with' - ' %(image)s', {'instance': instance.name, - 'image': instance.image_ref}) + LOG.info("Creating container {instance} with {image}" + .format(instance=instance.name, + image=instance.image_ref)) client = self.get_session(host=host) (state, data) = client.container_init(config) @@ -88,20 +86,17 @@ class LXDAPISession(object): msg = data.get('err') or data['metadata'] raise exception.NovaException(msg) - LOG.info('Successfully created container %(instance)s with' - ' %(image)s', {'instance': instance.name, - 'image': instance.image_ref}) + LOG.info("Successfully created container {instance} with {image}" + .format(instance=instance.name, + image=instance.image_ref)) except lxd_exceptions.APIError as ex: - msg = _('Failed to communicate with LXD API %(instance)s:' - ' %(reason)s') % {'instance': instance.name, - 'reason': ex} + msg = (_("Failed to communicate with LXD API {instance}: {reason}") + .format(instance=instance.name, reason=ex)) raise exception.NovaException(msg) except Exception as ex: with excutils.save_and_reraise_exception(): - LOG.error( - 'Failed to create container %(instance)s: %(reason)s', - {'instance': instance.name, - 'reason': ex}, instance=instance) + LOG.error("Failed to create container {instance}: {reason}" + .format(instance=instance.name, reason=ex)) # # Operation methods @@ -113,42 +108,40 @@ class LXDAPISession(object): :param operation_id: The operation to wait for. :param instance: nova instace object """ - LOG.debug('wait_for_container for instance', instance=instance) + LOG.debug("wait_for_container for instance: {}".format(instance)) try: client = self.get_session(host=host) if not client.wait_container_operation(operation_id, 200, -1): - msg = _('Container creation timed out') + msg = _("Container creation timed out") raise exception.NovaException(msg) except lxd_exceptions.APIError as ex: - msg = _('Failed to communicate with LXD API %(instance)s:' - '%(reason)s') % {'instance': instance.image_ref, - 'reason': ex} + msg = _("Failed to communicate with LXD API {instance}: " + "{reason}").format(instance=instance.image_ref, + reason=ex) LOG.error(msg) raise exception.NovaException(msg) except Exception as e: with excutils.save_and_reraise_exception(): - LOG.error('Error from LXD during operation wait' - '%(instance)s: %(reason)s', - {'instance': instance.image_ref, 'reason': e}, - instance=instance) + LOG.error("Error from LXD during operation wait " + "{instance}: {reason}" + .format(instance=instance.image_ref, reason=e)) def operation_info(self, operation_id, instance, host=None): - LOG.debug('operation_info called for instance', instance=instance) + LOG.debug("operation_info called for instance {}".format(instance)) try: client = self.get_session(host=host) return client.operation_info(operation_id) except lxd_exceptions.APIError as ex: - msg = _('Failed to communicate with LXD API %(instance)s:' - ' %(reason)s') % {'instance': instance.image_ref, - 'reason': ex} + msg = _("Failed to communicate with LXD API {instance}:" + " {reason}").format(instance=instance.image_ref, + reason=ex) LOG.error(msg) raise exception.NovaException(msg) except Exception as e: with excutils.save_and_reraise_exception(): - LOG.error('Error from LXD during operation_info ' - '%(instance)s: %(reason)s', - {'instance': instance.image_ref, 'reason': e}, - instance=instance) + LOG.error("Error from LXD during operation_info " + "{instance}: {reason}" + .format(instance=instance.image_ref, reason=e)) # # Migrate methods @@ -162,28 +155,26 @@ class LXDAPISession(object): :return: dictionary of the container keys """ - LOG.debug('container_migrate called for instance', instance=instance) + LOG.debug("container_migrate called for instance {}".format(instance)) try: - LOG.info('Migrating instance %(instance)s with ' - '%(image)s', {'instance': instance_name, - 'image': instance.image_ref}) + LOG.info("Migrating instance {instance} with {image}" + .format(instance=instance_name, + image=instance.image_ref)) client = self.get_session() (state, data) = client.container_migrate(instance_name) - LOG.info('Successfully initialized migration for instance ' - '%(instance)s with %(image)s', - {'instance': instance.name, - 'image': instance.image_ref}) + LOG.info("Successfully initialized migration for instance " + "{instance} with {image}" + .format(instance=instance.name, + image=instance.image_ref)) return (state, data) except lxd_exceptions.APIError as ex: - msg = _('Failed to communicate with LXD API %(instance)s:' - ' %(reason)s') % {'instance': instance.name, - 'reason': ex} + msg = _("Failed to communicate with LXD API {instance}:" + " {reason}").format(instance=instance.name, + reason=ex) raise exception.NovaException(msg) except Exception as ex: with excutils.save_and_reraise_exception(): - LOG.error( - 'Failed to migrate container %(instance)s: %(' - 'reason)s', {'instance': instance.name, - 'reason': ex}, instance=instance) + LOG.error("Failed to migrate container {instance}: {reason}" + .format(instance=instance.name, reason=ex)) diff --git a/nova/virt/lxd/storage.py b/nova/virt/lxd/storage.py index ce3612be..cadbff63 100644 --- a/nova/virt/lxd/storage.py +++ b/nova/virt/lxd/storage.py @@ -83,8 +83,8 @@ def attach_ephemeral(client, block_device_info, lxd_config, instance): cmd = ('mount', '-t', 'ext4', lvm_path, storage_dir) utils.execute(*cmd, run_as_root=True) else: - reason = _('Unsupport LXD storage detected. Supported' - ' storage drivers are zfs and btrfs.') + reason = _("Unsupport LXD storage detected. Supported" + " storage drivers are zfs and btrfs.") raise exception.NovaException(reason) utils.execute( diff --git a/nova/virt/lxd/vif.py b/nova/virt/lxd/vif.py index 66d30c33..492a822a 100644 --- a/nova/virt/lxd/vif.py +++ b/nova/virt/lxd/vif.py @@ -150,11 +150,12 @@ def _post_plug_wiring(instance, vif): network infrastructure """ - LOG.debug("Performing post plug wiring for VIF %s", vif) + LOG.debug("Performing post plug wiring for VIF {}".format(vif)) vif_type = vif['type'] try: POST_PLUG_WIRING[vif_type](instance, vif) + LOG.debug("Post plug wiring step for VIF {} done".format(vif)) except KeyError: LOG.debug("No post plug wiring step " "for vif type: {}".format(vif_type)) @@ -190,11 +191,12 @@ def _post_unplug_wiring(instance, vif): network interfaces assocaited with a lxd container. """ - LOG.debug("Performing post unplug wiring for VIF %s", vif) + LOG.debug("Performing post unplug wiring for VIF {}".format(vif)) vif_type = vif['type'] try: POST_UNPLUG_WIRING[vif_type](instance, vif) + LOG.debug("Post unplug wiring for VIF {} done".format(vif)) except KeyError: LOG.debug("No post unplug wiring step " "for vif type: {}".format(vif_type)) @@ -264,5 +266,5 @@ class LXDGenericVifDriver(object): try: network_utils.delete_net_dev(dev) except processutils.ProcessExecutionError: - LOG.exception("Failed while unplugging vif", - instance=instance) + LOG.exception("Failed while unplugging vif for instance: {}" + .format(instance)) diff --git a/nova_lxd_tempest_plugin/tests/scenario/manager.py b/nova_lxd_tempest_plugin/tests/scenario/manager.py index 79189daf..d504b811 100644 --- a/nova_lxd_tempest_plugin/tests/scenario/manager.py +++ b/nova_lxd_tempest_plugin/tests/scenario/manager.py @@ -256,8 +256,8 @@ class ScenarioTest(tempest.test.BaseTestCase): name = data_utils.rand_name(class_name + '-volume-type') randomized_name = data_utils.rand_name('scenario-type-' + name) - LOG.debug("Creating a volume type: %s on backend %s", - randomized_name, backend_name) + LOG.debug("Creating a volume type: {name} on backend {backend}" + .format(name=randomized_name, backend=backend_name)) extra_specs = {} if backend_name: extra_specs = {"volume_backend_name": backend_name} @@ -350,9 +350,10 @@ class ScenarioTest(tempest.test.BaseTestCase): try: linux_client.validate_authentication() except Exception as e: - message = ('Initializing SSH connection to %(ip)s failed. ' - 'Error: %(error)s' % {'ip': ip_address, - 'error': e}) + message = ("Initializing SSH connection to {ip} failed. " + "Error: {error}" + .format(ip=ip_address, + error=e)) caller = test_utils.find_test_caller() if caller: message = '(%s) %s' % (caller, message) @@ -399,10 +400,16 @@ class ScenarioTest(tempest.test.BaseTestCase): img_container_format = CONF.scenario.img_container_format img_disk_format = CONF.scenario.img_disk_format img_properties = CONF.scenario.img_properties - LOG.debug("paths: img: %s, container_format: %s, disk_format: %s, " - "properties: %s, ami: %s, ari: %s, aki: %s", - img_path, img_container_format, img_disk_format, - img_properties, ami_img_path, ari_img_path, aki_img_path) + LOG.debug("paths: img: {img}, container_format: {cf}, " + "disk_format: {df}, properties: {props}, ami: {ami}, " + "ari: {ari}, aki: {aki}" + .format(img=img_path, + cf=img_container_format, + df=img_disk_format, + props=img_properties, + ami=ami_img_path, + ari=ari_img_path, + aki=aki_img_path)) try: image = self._image_create('scenario-img', img_container_format, @@ -417,13 +424,13 @@ class ScenarioTest(tempest.test.BaseTestCase): image = self._image_create('scenario-ami', 'ami', path=ami_img_path, properties=properties) - LOG.debug("image:%s", image) + LOG.debug("image: {}".format(image)) return image def _log_console_output(self, servers=None): if not CONF.compute_feature_enabled.console_output: - LOG.debug('Console output not supported, cannot log') + LOG.debug("Console output not supported, cannot log") return if not servers: servers = self.servers_client.list_servers() @@ -432,16 +439,16 @@ class ScenarioTest(tempest.test.BaseTestCase): try: console_output = self.servers_client.get_console_output( server['id'])['output'] - LOG.debug('Console output for %s\nbody=\n%s', - server['id'], console_output) + LOG.debug("Console output for {}\nbody=\n{}" + .format(server['id'], console_output)) except lib_exc.NotFound: - LOG.debug("Server %s disappeared(deleted) while looking " - "for the console log", server['id']) + LOG.debug("Server {} disappeared(deleted) while looking " + "for the console log".format(server['id'])) def _log_net_info(self, exc): # network debug is called as part of ssh init if not isinstance(exc, lib_exc.SSHTimeout): - LOG.debug('Network information on a devstack host') + LOG.debug("Network information on a devstack host") def create_server_snapshot(self, server, name=None): # Glance client @@ -450,7 +457,8 @@ class ScenarioTest(tempest.test.BaseTestCase): _images_client = self.compute_images_client if name is None: name = data_utils.rand_name(self.__class__.__name__ + 'snapshot') - LOG.debug("Creating a snapshot image for server: %s", server['name']) + LOG.debug("Creating a snapshot image for server: {}" + .format(server['name'])) image = _images_client.create_image(server['id'], name=name) image_id = image.response['location'].split('images/')[1] waiters.wait_for_image_status(_image_client, image_id, 'active') @@ -486,8 +494,8 @@ class ScenarioTest(tempest.test.BaseTestCase): 'available') image_name = snapshot_image['name'] self.assertEqual(name, image_name) - LOG.debug("Created snapshot image %s for server %s", - image_name, server['name']) + LOG.debug("Created snapshot image {} for server {}" + .format(image_name, server['name'])) return snapshot_image def nova_volume_attach(self, server, volume_to_attach): @@ -517,8 +525,11 @@ class ScenarioTest(tempest.test.BaseTestCase): rebuild_kwargs = rebuild_kwargs or {} - LOG.debug("Rebuilding server (id: %s, image: %s, preserve eph: %s)", - server_id, image, preserve_ephemeral) + LOG.debug("Rebuilding server (id: {_id}, image: {image}, " + "preserve eph: {ephemeral})" + .format(_id=server_id, + image=image, + ephemeral=preserve_ephemeral)) self.servers_client.rebuild_server( server_id=server_id, image_ref=image, preserve_ephemeral=preserve_ephemeral, @@ -550,18 +561,20 @@ class ScenarioTest(tempest.test.BaseTestCase): return (proc.returncode == 0) == should_succeed caller = test_utils.find_test_caller() - LOG.debug('%(caller)s begins to ping %(ip)s in %(timeout)s sec and the' - ' expected result is %(should_succeed)s', { - 'caller': caller, 'ip': ip_address, 'timeout': timeout, - 'should_succeed': - 'reachable' if should_succeed else 'unreachable' - }) + LOG.debug("{caller} begins to ping {ip} in {timeout} sec and the" + " expected result is {should_succeed}" + .format(caller=caller, + ip=ip_address, + timeout=timeout, + should_succeed=('reachable' if should_succeed + else 'unreachable')) result = test_utils.call_until_true(ping, timeout, 1) - LOG.debug('%(caller)s finishes ping %(ip)s in %(timeout)s sec and the ' - 'ping result is %(result)s', { - 'caller': caller, 'ip': ip_address, 'timeout': timeout, - 'result': 'expected' if result else 'unexpected' - }) + LOG.debug("{caller} finishes ping {ip} in {timeout} sec and the " + "ping result is {result}" + .format(caller=caller, + ip=ip_address, + timeout=timeout, + result='expected' if result else 'unexpected')) return result def check_vm_connectivity(self, ip_address, @@ -599,8 +612,8 @@ class ScenarioTest(tempest.test.BaseTestCase): msg=None, servers=None, mtu=None): # The target login is assumed to have been configured for # key-based authentication by cloud-init. - LOG.debug('checking network connections to IP %s with user: %s', - ip_address, username) + LOG.debug("checking network connections to IP {} with user: {}" + .format(ip_address, username)) try: self.check_vm_connectivity(ip_address, username, diff --git a/nova_lxd_tempest_plugin/tests/scenario/test_volume_ops.py b/nova_lxd_tempest_plugin/tests/scenario/test_volume_ops.py index fcf64b80..a3e64437 100644 --- a/nova_lxd_tempest_plugin/tests/scenario/test_volume_ops.py +++ b/nova_lxd_tempest_plugin/tests/scenario/test_volume_ops.py @@ -65,7 +65,7 @@ class LXDVolumeScenario(manager.ScenarioTest): def _func(): part = ssh.get_partitions() - LOG.debug("Partitions:%s" % part) + LOG.debug("Partitions: {}".format(part)) return CONF.compute.volume_device_name in part if not test_utils.call_until_true(_func, diff --git a/tools/db/schema_diff.py b/tools/db/schema_diff.py index 058cb893..dbeded87 100755 --- a/tools/db/schema_diff.py +++ b/tools/db/schema_diff.py @@ -73,8 +73,8 @@ def dump_db(db_driver, db_name, db_url, migration_version, dump_filename): def diff_files(filename1, filename2): - pipeline = ['diff -U 3 %(filename1)s %(filename2)s' - % {'filename1': filename1, 'filename2': filename2}] + pipeline = ["diff -U 3 {filename1} {filename2}" + .format(filename1=filename1, filename2=filename2)] # Use colordiff if available if subprocess.call(['which', 'colordiff']) == 0: @@ -99,8 +99,8 @@ class Mysql(object): def dump(self, name, dump_filename): subprocess.check_call( - 'mysqldump -u root %(name)s > %(dump_filename)s' - % {'name': name, 'dump_filename': dump_filename}, + "mysqldump -u root {name} > {dump_filename}" + .format(name=name, dump_filename=dump_filename), shell=True) @@ -114,8 +114,8 @@ class Postgresql(object): def dump(self, name, dump_filename): subprocess.check_call( - 'pg_dump %(name)s > %(dump_filename)s' - % {'name': name, 'dump_filename': dump_filename}, + "pg_dump {name} > {dump_filename}" + .format(name=name, dump_filename=dump_filename), shell=True) @@ -123,7 +123,7 @@ def _get_db_driver_class(db_url): try: return globals()[db_url.split('://')[0].capitalize()] except KeyError: - raise Exception(_("database %s not supported") % db_url) + raise Exception(_("database {] not supported").format(db_url)) # Migrate