From 3eadd939bb1ef1dcb27402672d06691958a585ca Mon Sep 17 00:00:00 2001 From: Yuriy Nesenenko Date: Wed, 18 Mar 2015 13:45:48 +0200 Subject: [PATCH] Fix logging to catch original exceptions and tracebacks We should log the original exceptions information and tracebacks with LOG.exception instead of LOG.error. Otherwise, it can be difficult to determine the root issue. Also, the module cinder/volume/flows/manager/create_volume.py is fixed according to Logging guidelines http://docs.openstack.org/developer/oslo.i18n/guidelines.html Closes-Bug: #1309177 Change-Id: I01d7667ddb9f7698efcf412a40f76809852cfaa1 --- cinder/volume/flows/manager/create_volume.py | 93 +++++++++----------- 1 file changed, 44 insertions(+), 49 deletions(-) diff --git a/cinder/volume/flows/manager/create_volume.py b/cinder/volume/flows/manager/create_volume.py index 432a99310..dcc57195d 100644 --- a/cinder/volume/flows/manager/create_volume.py +++ b/cinder/volume/flows/manager/create_volume.py @@ -101,7 +101,7 @@ class OnFailureRescheduleTask(flow_utils.CinderTask): request_spec['volume_id'] = volume_id LOG.debug("Volume %(volume_id)s: re-scheduling %(method)s " - "attempt %(num)d due to %(reason)s" % + "attempt %(num)d due to %(reason)s", {'volume_id': volume_id, 'method': common.make_pretty_name(create_volume), 'num': num_attempts, @@ -136,7 +136,7 @@ class OnFailureRescheduleTask(flow_utils.CinderTask): 'status': 'creating', 'scheduled_at': timeutils.utcnow(), } - LOG.debug("Updating volume %(volume_id)s with %(update)s." % + LOG.debug("Updating volume %(volume_id)s with %(update)s.", {'update': update, 'volume_id': volume_id}) self.db.volume_update(context, volume_id, update) except exception.CinderException: @@ -318,9 +318,8 @@ class NotifyVolumeActionTask(flow_utils.CinderTask): # then we shouldn't error out the whole workflow since this is # not always information that must be sent for volumes to operate LOG.exception(_LE("Failed notifying about the volume" - " action %(event)s for volume %(volume_id)s") % - {'event': self.event_suffix, - 'volume_id': volume_id}) + " action %(event)s for volume %(volume_id)s"), + {'event': self.event_suffix, 'volume_id': volume_id}) class CreateVolumeFromSpecTask(flow_utils.CinderTask): @@ -358,18 +357,18 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): src_type = 'snapshot' src_id = kwargs['snapshot_id'] snapshot_id = src_id - LOG.debug(log_template % {'src_type': src_type, - 'src_id': src_id, - 'vol_id': volume_id}) + LOG.debug(log_template, {'src_type': src_type, + 'src_id': src_id, + 'vol_id': volume_id}) self.db.volume_glance_metadata_copy_to_volume( context, volume_id, snapshot_id) elif kwargs.get('source_volid'): src_type = 'source volume' src_id = kwargs['source_volid'] source_volid = src_id - LOG.debug(log_template % {'src_type': src_type, - 'src_id': src_id, - 'vol_id': volume_id}) + LOG.debug(log_template, {'src_type': src_type, + 'src_id': src_id, + 'vol_id': volume_id}) self.db.volume_glance_metadata_copy_from_volume_to_volume( context, source_volid, @@ -378,9 +377,9 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): src_type = 'source replica' src_id = kwargs['source_replicaid'] source_replicaid = src_id - LOG.debug(log_template % {'src_type': src_type, - 'src_id': src_id, - 'vol_id': volume_id}) + LOG.debug(log_template, {'src_type': src_type, + 'src_id': src_id, + 'vol_id': volume_id}) self.db.volume_glance_metadata_copy_from_volume_to_volume( context, source_replicaid, @@ -390,9 +389,9 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): src_id = kwargs['image_id'] image_id = src_id image_meta = kwargs.get('image_meta', {}) - LOG.debug(log_template % {'src_type': src_type, - 'src_id': src_id, - 'vol_id': volume_id}) + LOG.debug(log_template, {'src_type': src_type, + 'src_id': src_id, + 'vol_id': volume_id}) self._capture_volume_image_metadata(context, volume_id, image_id, image_meta) except exception.GlanceMetadataNotFound: @@ -401,9 +400,9 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): # volume glance metadata table pass except exception.CinderException as ex: - LOG.exception(exception_template % {'src_type': src_type, - 'src_id': src_id, - 'vol_id': volume_id}) + LOG.exception(exception_template, {'src_type': src_type, + 'src_id': src_id, + 'vol_id': volume_id}) raise exception.MetadataCopyFailure(reason=ex) def _create_from_snapshot(self, context, volume_ref, snapshot_id, @@ -424,7 +423,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): LOG.exception(_LE("Failed fetching snapshot %(snapshot_id)s " "bootable" " flag using the provided glance snapshot " - "%(snapshot_ref_id)s volume reference") % + "%(snapshot_ref_id)s volume reference"), {'snapshot_id': snapshot_id, 'snapshot_ref_id': snapshot.volume_id}) raise exception.MetadataUpdateFailure(reason=ex) @@ -439,7 +438,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): self.db.volume_update(context, volume_id, {'bootable': True}) except exception.CinderException as ex: LOG.exception(_LE("Failed updating volume %(volume_id)s bootable " - "flag to true") % {'volume_id': volume_id}) + "flag to true"), {'volume_id': volume_id}) raise exception.MetadataUpdateFailure(reason=ex) def _create_from_source_volume(self, context, volume_ref, @@ -487,34 +486,31 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): copy_image_to_volume = self.driver.copy_image_to_volume volume_id = volume_ref['id'] LOG.debug("Attempting download of %(image_id)s (%(image_location)s)" - " to volume %(volume_id)s." % + " to volume %(volume_id)s.", {'image_id': image_id, 'volume_id': volume_id, 'image_location': image_location}) try: copy_image_to_volume(context, volume_ref, image_service, image_id) except processutils.ProcessExecutionError as ex: - LOG.error(_LE("Failed to copy image %(image_id)s to volume: " - "%(volume_id)s, error: %(error)s") % - {'volume_id': volume_id, - 'error': ex.stderr, 'image_id': image_id}) + LOG.exception(_LE("Failed to copy image %(image_id)s to volume: " + "%(volume_id)s"), + {'volume_id': volume_id, 'image_id': image_id}) raise exception.ImageCopyFailure(reason=ex.stderr) except exception.ImageUnacceptable as ex: - LOG.error(_LE("Failed to copy image to volume: %(volume_id)s, " - "error: %(error)s") % - {'volume_id': volume_id, 'error': ex}) + LOG.exception(_LE("Failed to copy image to volume: %(volume_id)s"), + {'volume_id': volume_id}) raise exception.ImageUnacceptable(ex) except Exception as ex: - LOG.error(_LE("Failed to copy image %(image_id)s to " - "volume: %(volume_id)s, error: %(error)s") % - {'volume_id': volume_id, 'error': ex, - 'image_id': image_id}) + LOG.exception(_LE("Failed to copy image %(image_id)s to " + "volume: %(volume_id)s"), + {'volume_id': volume_id, 'image_id': image_id}) if not isinstance(ex, exception.ImageCopyFailure): raise exception.ImageCopyFailure(reason=ex) else: raise LOG.debug("Downloaded image %(image_id)s (%(image_location)s)" - " to volume %(volume_id)s successfully." % + " to volume %(volume_id)s successfully.", {'image_id': image_id, 'volume_id': volume_id, 'image_location': image_location}) @@ -551,7 +547,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): volume_metadata = dict(property_metadata) volume_metadata.update(base_metadata) LOG.debug("Creating volume glance metadata for volume %(volume_id)s" - " backed by image %(image_id)s with: %(vol_metadata)s." % + " backed by image %(image_id)s with: %(vol_metadata)s.", {'volume_id': volume_id, 'image_id': image_id, 'vol_metadata': volume_metadata}) for (key, value) in volume_metadata.items(): @@ -565,7 +561,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): image_location, image_id, image_meta, image_service, **kwargs): LOG.debug("Cloning %(volume_id)s from image %(image_id)s " - " at location %(image_location)s." % + " at location %(image_location)s.", {'volume_id': volume_ref['id'], 'image_location': image_location, 'image_id': image_id}) # Create the volume from an image. @@ -594,7 +590,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): volume_ref['id'], updates) except exception.CinderException: LOG.exception(_LE("Failed updating volume %(volume_id)s with " - "%(updates)s") % + "%(updates)s"), {'volume_id': volume_ref['id'], 'updates': updates}) self._copy_image_to_volume(context, volume_ref, @@ -617,8 +613,8 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): # we can't do anything if the driver didn't init if not self.driver.initialized: driver_name = self.driver.__class__.__name__ - LOG.error(_LE("Unable to create volume. " - "Volume driver %s not initialized") % driver_name) + LOG.exception(_LE("Unable to create volume. " + "Volume driver %s not initialized"), driver_name) # NOTE(flaper87): Set the error status before # raising any exception. self.db.volume_update(context, volume_id, dict(status='error')) @@ -626,7 +622,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): create_type = volume_spec.pop('type', None) LOG.info(_LI("Volume %(volume_id)s: being created as %(create_type)s " - "with specification: %(volume_spec)s") % + "with specification: %(volume_spec)s"), {'volume_spec': volume_spec, 'volume_id': volume_id, 'create_type': create_type}) if create_type == 'raw': @@ -660,7 +656,7 @@ class CreateVolumeFromSpecTask(flow_utils.CinderTask): # failure is logged (but not try rescheduling since the volume at # this point has been created). LOG.exception(_LE("Failed updating model of volume %(volume_id)s " - "with creation provided model %(model)s") % + "with creation provided model %(model)s"), {'volume_id': volume_id, 'model': model_update}) raise @@ -703,14 +699,13 @@ class CreateVolumeOnFinishTask(NotifyVolumeActionTask): super(CreateVolumeOnFinishTask, self).execute(context, volume_ref) except exception.CinderException: LOG.exception(_LE("Failed updating volume %(volume_id)s with " - "%(update)s") % {'volume_id': volume_id, - 'update': update}) + "%(update)s"), {'volume_id': volume_id, + 'update': update}) # Even if the update fails, the volume is ready. - msg = _("Volume %(volume_name)s (%(volume_id)s): created successfully") - LOG.info(msg % { - 'volume_name': volume_spec['volume_name'], - 'volume_id': volume_id, - }) + LOG.info(_LI("Volume %(volume_name)s (%(volume_id)s): " + "created successfully"), + {'volume_name': volume_spec['volume_name'], + 'volume_id': volume_id}) def get_flow(context, db, driver, scheduler_rpcapi, host, volume_id, -- 2.45.2