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

diff --git a/cinder/volume/api.py b/cinder/volume/api.py
index 8a2874e2bb5dc9911170c0ccbfe26a07d46cb4cb..86ad2e917b6523c898b5f4207e9b9f77f0cfafef 100644 (file)
--- 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