From e9bc08f0ada2831dee4f3cd5a936cdc2f21fef6d Mon Sep 17 00:00:00 2001 From: John Griffith Date: Fri, 17 Apr 2015 20:51:06 +0000 Subject: [PATCH] Standardize logging in volume.api.py We now have resource tag support in oslo logging, and our logging is pretty inconsistent and down right ugly in places. Let's clean things up based on the standard logging guidelines and use the fancy new resource tag. This patch starts with the volume.api file as that's 'easy', so we can enforce things going forward and start working out other files in future patches. To use set the following in cinder.conf: logging_context_format_string = \ %(asctime)s.%(msecs)03d %(levelname)s %(name)s [%(request_id)s \ %(project_name)s] %(resource)s%(message)s Change-Id: I78708ba8bc372c2ca051aa7d84386dc7125a9b5e --- cinder/volume/api.py | 160 +++++++++++++++++++++++++++++++++---------- 1 file changed, 123 insertions(+), 37 deletions(-) diff --git a/cinder/volume/api.py b/cinder/volume/api.py index 8a2874e2b..86ad2e917 100644 --- a/cinder/volume/api.py +++ b/cinder/volume/api.py @@ -155,6 +155,7 @@ class API(base.Base): seconds=CONF.az_cache_duration)) else: azs = self.availability_zones + LOG.info(_LI("Availability Zones retrieved successfully.")) return tuple(azs) def create(self, context, size, name, description, snapshot=None, @@ -262,7 +263,9 @@ class API(base.Base): # cinders debugging (or error reporting) usage. with flow_utils.DynamicLogListener(flow_engine, logger=LOG): flow_engine.run() - return flow_engine.storage.fetch('volume') + vref = flow_engine.storage.fetch('volume') + LOG.info(_LI("Volume created successfully."), resource=vref) + return vref @wrap_check_policy def delete(self, context, volume, force=False, unmanage_only=False): @@ -296,6 +299,9 @@ class API(base.Base): volume_utils.notify_about_volume_usage(context, volume, "delete.end") + LOG.info(_LI("Delete volume request issued successfully."), + resource={'type': 'volume', + 'id': volume_id}) return if volume['attach_status'] == "attached": # Volume is still attached, need to detach first @@ -345,16 +351,19 @@ class API(base.Base): self.key_manager.delete_key(context, encryption_key_id) now = timeutils.utcnow() - self.db.volume_update(context, volume_id, {'status': 'deleting', - 'terminated_at': now}) + vref = self.db.volume_update(context, + volume_id, + {'status': 'deleting', + 'terminated_at': now}) self.volume_rpcapi.delete_volume(context, volume, unmanage_only) - LOG.info(_LI('Successfully issued request to ' - 'delete volume: %s.'), volume['id']) + LOG.info(_LI("Delete volume request issued successfully."), + resource=vref) @wrap_check_policy def update(self, context, volume, fields): - self.db.volume_update(context, volume['id'], fields) + vref = self.db.volume_update(context, volume['id'], fields) + LOG.info(_LI("Volume updated successfully."), resource=vref) def get(self, context, volume_id, viewable_admin_meta=False): if viewable_admin_meta: @@ -369,6 +378,7 @@ class API(base.Base): # raise VolumeNotFound instead to make sure Cinder behaves # as it used to raise exception.VolumeNotFound(volume_id=volume_id) + LOG.info(_LI("Volume info retrieved successfully."), resource=rv) return volume def _get_all_tenants_value(self, filters): @@ -437,15 +447,24 @@ class API(base.Base): sort_dirs=sort_dirs, filters=filters) + LOG.info(_LI("Get all volumes completed successfully.")) return volumes def get_snapshot(self, context, snapshot_id): - return objects.Snapshot.get_by_id(context, snapshot_id) + snapshot = objects.Snapshot.get_by_id(context, snapshot_id) + + # FIXME(jdg): The objects don't have the db name entries + # so build the resource tag manually for now. + LOG.info(_LI("Snapshot retrieved successfully."), + resource={'type': 'snapshot', + 'id': snapshot['id']}) + return snapshot def get_volume(self, context, volume_id): check_policy(context, 'get_volume') - rv = self.db.volume_get(context, volume_id) - return dict(rv.iteritems()) + vref = self.db.volume_get(context, volume_id) + LOG.info(_LI("Volume retrieved successfully."), resource=vref) + return dict(vref.iteritems()) def get_all_snapshots(self, context, search_opts=None): check_policy(context, 'get_all_snapshots') @@ -472,6 +491,7 @@ class API(base.Base): else: results.append(snapshot) snapshots = results + LOG.info(_LI("Get all snaphsots completed successfully.")) return snapshots @wrap_check_policy @@ -492,6 +512,8 @@ class API(base.Base): msg = _("Volume status must be available to reserve.") LOG.error(msg) raise exception.InvalidVolume(reason=msg) + LOG.info(_LI("Reserve volume completed successfully."), + resource=volume) @wrap_check_policy def unreserve_volume(self, context, volume): @@ -503,6 +525,8 @@ class API(base.Base): self.update(context, volume, {"status": "in-use"}) else: self.update(context, volume, {"status": "available"}) + LOG.info(_LI("Unreserve volume completed successfully."), + resource=volume) @wrap_check_policy def begin_detaching(self, context, volume): @@ -523,11 +547,15 @@ class API(base.Base): LOG.error(msg) raise exception.InvalidVolume(reason=msg) self.update(context, volume, {"status": "detaching"}) + LOG.info(_LI("Begin detaching volume completed successfully."), + resource=volume) @wrap_check_policy def roll_detaching(self, context, volume): if volume['status'] == "detaching": self.update(context, volume, {"status": "in-use"}) + LOG.info(_LI("Roll detaching of volume completed successfully."), + resource=volume) @wrap_check_policy def attach(self, context, volume, instance_uuid, host_name, @@ -544,41 +572,53 @@ class API(base.Base): raise exception.InvalidVolumeAttachMode(mode=mode, volume_id=volume['id']) - return self.volume_rpcapi.attach_volume(context, - volume, - instance_uuid, - host_name, - mountpoint, - mode) + attach_results = self.volume_rpcapi.attach_volume(context, + volume, + instance_uuid, + host_name, + mountpoint, + mode) + LOG.info(_LI("Attach volume completed successfully."), + resource=volume) + return attach_results @wrap_check_policy def detach(self, context, volume, attachment_id): - return self.volume_rpcapi.detach_volume(context, volume, - attachment_id) + detach_results = self.volume_rpcapi.detach_volume(context, volume, + attachment_id) + LOG.info(_LI("Detach volume completed successfully."), + resource=volume) + return detach_results @wrap_check_policy def initialize_connection(self, context, volume, connector): - LOG.debug('initialize connection for volume-id: %(volid)s, and ' - 'connector: %(connector)s.', {'volid': volume['id'], - 'connector': connector}) - return self.volume_rpcapi.initialize_connection(context, - volume, - connector) + init_results = self.volume_rpcapi.initialize_connection(context, + volume, + connector) + LOG.info(_LI("Initialize volume connection completed successfully."), + resource=volume) + return init_results @wrap_check_policy def terminate_connection(self, context, volume, connector, force=False): self.unreserve_volume(context, volume) - return self.volume_rpcapi.terminate_connection(context, - volume, - connector, - force) + results = self.volume_rpcapi.terminate_connection(context, + volume, + connector, + force) + LOG.info(_LI("Terminate volume connection completed successfully."), + resource=volume) + return results @wrap_check_policy def accept_transfer(self, context, volume, new_user, new_project): - return self.volume_rpcapi.accept_transfer(context, - volume, - new_user, - new_project) + results = self.volume_rpcapi.accept_transfer(context, + volume, + new_user, + new_project) + LOG.info(_LI("Transfer volume completed successfully."), + resource=volume) + return results def _create_snapshot(self, context, volume, name, description, @@ -809,14 +849,20 @@ class API(base.Base): def create_snapshot(self, context, volume, name, description, metadata=None, cgsnapshot_id=None): - return self._create_snapshot(context, volume, name, description, - False, metadata, cgsnapshot_id) + result = self._create_snapshot(context, volume, name, description, + False, metadata, cgsnapshot_id) + LOG.info(_LI("Snapshot create request issued successfully."), + resource=result) + return result def create_snapshot_force(self, context, volume, name, description, metadata=None): - return self._create_snapshot(context, volume, name, description, - True, metadata) + result = self._create_snapshot(context, volume, name, description, + True, metadata) + LOG.info(_LI("Snapshot force create request issued successfully."), + resource=result) + return result @wrap_check_policy def delete_snapshot(self, context, snapshot, force=False): @@ -843,8 +889,8 @@ class API(base.Base): volume = self.db.volume_get(context, snapshot_obj.volume_id) self.volume_rpcapi.delete_snapshot(context, snapshot_obj, volume['host']) - LOG.info(_LI('Successfully issued request to ' - 'delete snapshot: %s'), snapshot_obj.id) + LOG.info(_LI("Snapshot delete request issued successfully."), + resource=snapshot) @wrap_check_policy def update_snapshot(self, context, snapshot, fields): @@ -855,12 +901,16 @@ class API(base.Base): def get_volume_metadata(self, context, volume): """Get all metadata associated with a volume.""" rv = self.db.volume_metadata_get(context, volume['id']) + LOG.info(_LI("Get volume metadata completed successfully."), + resource=volume) return dict(rv.iteritems()) @wrap_check_policy def delete_volume_metadata(self, context, volume, key): """Delete the given metadata item from a volume.""" self.db.volume_metadata_delete(context, volume['id'], key) + LOG.info(_LI("Delete volume metadata completed successfully."), + resource=volume) def _check_metadata_properties(self, metadata=None): if not metadata: @@ -902,6 +952,8 @@ class API(base.Base): # TODO(jdg): Implement an RPC call for drivers that may use this info + LOG.info(_LI("Update volume metadata completed successfully."), + resource=volume) return db_meta def get_volume_metadata_value(self, volume, key): @@ -911,18 +963,24 @@ class API(base.Base): for i in volume['volume_metadata']: if i['key'] == key: return i['value'] + LOG.info(_LI("Get volume metadata key completed successfully."), + resource=volume) return None @wrap_check_policy def get_volume_admin_metadata(self, context, volume): """Get all administration metadata associated with a volume.""" rv = self.db.volume_admin_metadata_get(context, volume['id']) + LOG.info(_LI("Get volume admin metadata completed successfully."), + resource=volume) return dict(rv.iteritems()) @wrap_check_policy def delete_volume_admin_metadata(self, context, volume, key): """Delete the given administration metadata item from a volume.""" self.db.volume_admin_metadata_delete(context, volume['id'], key) + LOG.info(_LI("Delete volume admin metadata completed successfully."), + resource=volume) @wrap_check_policy def update_volume_admin_metadata(self, context, volume, metadata, @@ -947,17 +1005,23 @@ class API(base.Base): # TODO(jdg): Implement an RPC call for drivers that may use this info + LOG.info(_LI("Update volume admin metadata completed successfully."), + resource=volume) return _metadata def get_snapshot_metadata(self, context, snapshot): """Get all metadata associated with a snapshot.""" snapshot_obj = self.get_snapshot(context, snapshot['id']) + LOG.info(_LI("Get snapshot metadata completed successfully."), + resource=snapshot) return snapshot_obj.metadata def delete_snapshot_metadata(self, context, snapshot, key): """Delete the given metadata item from a snapshot.""" snapshot_obj = self.get_snapshot(context, snapshot['id']) snapshot_obj.delete_metadata_key(context, key) + LOG.info(_LI("Delete snapshot metadata completed successfully."), + resource=snapshot) def update_snapshot_metadata(self, context, snapshot, metadata, @@ -982,9 +1046,14 @@ class API(base.Base): # TODO(jdg): Implement an RPC call for drivers that may use this info + LOG.info(_LI("Update snapshot metadata completed successfully."), + resource=snapshot) return snapshot.metadata def get_snapshot_metadata_value(self, snapshot, key): + LOG.info(_LI("Get snapshot metadata value not implemented."), + resource=snapshot) + # FIXME(jdg): Huh? Pass? pass def get_volumes_image_metadata(self, context): @@ -999,6 +1068,8 @@ class API(base.Base): @wrap_check_policy def get_volume_image_metadata(self, context, volume): db_data = self.db.volume_glance_metadata_get(context, volume['id']) + LOG.info(_LI("Get volume image-metadata completed successfully."), + resource=volume) return dict( (meta_entry.key, meta_entry.value) for meta_entry in db_data ) @@ -1055,6 +1126,8 @@ class API(base.Base): "container_format": recv_metadata['container_format'], "disk_format": recv_metadata['disk_format'], "image_name": recv_metadata.get('name', None)} + LOG.info(_LI("Copy image to volume completed successfully."), + resource=volume) return response @wrap_check_policy @@ -1101,6 +1174,8 @@ class API(base.Base): self.update(context, volume, {'status': 'extending'}) self.volume_rpcapi.extend_volume(context, volume, new_size, reservations) + LOG.info(_LI("Extend volume request issued successfully."), + resource=volume) @wrap_check_policy def migrate_volume(self, context, volume, host, force_host_copy): @@ -1183,6 +1258,8 @@ class API(base.Base): host, force_host_copy, request_spec) + LOG.info(_LI("Migrate volume request issued successfully."), + resource=volume) @wrap_check_policy def migrate_volume_completion(self, context, volume, new_volume, error): @@ -1206,6 +1283,8 @@ class API(base.Base): 'exp': expected_status}) raise exception.InvalidVolume(reason=msg) + LOG.info(_LI("Migrate volume completion issued successfully."), + resource=volume) return self.volume_rpcapi.migrate_volume_completion(context, volume, new_volume, error) @@ -1219,6 +1298,9 @@ class API(base.Base): raise exception.InvalidVolume(reason=msg) self.update_volume_admin_metadata(context.elevated(), volume, {'readonly': six.text_type(flag)}) + LOG.info(_LI("Update readonly setting on volume " + "completed successfully."), + resource=volume) @wrap_check_policy def retype(self, context, volume, new_type, migration_policy=None): @@ -1319,6 +1401,8 @@ class API(base.Base): self.scheduler_rpcapi.retype(context, CONF.volume_topic, volume['id'], request_spec=request_spec, filter_properties={}) + LOG.info(_LI("Retype volume request issued successfully."), + resource=volume) def manage_existing(self, context, host, ref, name=None, description=None, volume_type=None, metadata=None, @@ -1361,6 +1445,8 @@ class API(base.Base): self.scheduler_rpcapi.manage_existing(context, CONF.volume_topic, volume['id'], request_spec=request_spec) + LOG.info(_LI("Manage volume request issued successfully."), + resource=volume) return volume -- 2.45.2