From f4f42c966e378109f5ba9e4b800ae6e23dde1c75 Mon Sep 17 00:00:00 2001 From: Zhiteng Huang Date: Sat, 8 Oct 2016 13:03:37 -0700 Subject: [PATCH] Log message cleanup for volume-usage-audit volume-usage-audit utlis logs unecessary message at for deleted volumes or exception: try: LOG.debug('Send notification for vol X') _notify_func except Exception: LOG.exception(...) In the case when _notify_func raises exception, it logs 'Send notification' and the exception. This change reduce logs by only logging 'Sent notification' when there is no exception by: try: _notify_func LOG.debug('Sent notification for vol X') except Exception: LOG.exception(...) Also, this change fixes notify_snapshot_usage() for not handling the case when source volume for the snapshot is deleted. Closes-bug: #1631561 Change-Id: Iff5448e888ee39bce1ff99c7bf48581d655fb687 --- cinder/cmd/volume_usage_audit.py | 118 ++++++++++++------------- cinder/tests/unit/test_volume_utils.py | 46 ++++++++++ cinder/volume/utils.py | 14 ++- 3 files changed, 118 insertions(+), 60 deletions(-) diff --git a/cinder/cmd/volume_usage_audit.py b/cinder/cmd/volume_usage_audit.py index 20da655cf41..86e4d542ea5 100644 --- a/cinder/cmd/volume_usage_audit.py +++ b/cinder/cmd/volume_usage_audit.py @@ -48,7 +48,7 @@ from cinder import i18n i18n.enable_lazy() from cinder import context from cinder import db -from cinder.i18n import _, _LE +from cinder.i18n import _, _LE, _LI from cinder import objects from cinder import rpc from cinder import utils @@ -95,9 +95,9 @@ def main(): 'end': end} LOG.error(msg) sys.exit(-1) - LOG.debug("Starting volume usage audit") - msg = _("Creating usages for %(begin_period)s until %(end_period)s") - LOG.debug(msg, {"begin_period": str(begin), "end_period": str(end)}) + LOG.info(_LI("Starting volume usage audit")) + msg = _LI("Creating usages for %(begin_period)s until %(end_period)s") + LOG.info(msg, {"begin_period": str(begin), "end_period": str(end)}) extra_info = { 'audit_period_beginning': str(begin), @@ -107,19 +107,19 @@ def main(): volumes = db.volume_get_active_by_window(admin_context, begin, end) - LOG.debug("Found %d volumes", len(volumes)) + LOG.info(_LI("Found %d volumes"), len(volumes)) for volume_ref in volumes: try: - LOG.debug("Send exists notification for " "<%(extra_info)s>", {'volume_id': volume_ref.id, 'project_id': volume_ref.project_id, 'extra_info': extra_info}) - cinder.volume.utils.notify_about_volume_usage( - admin_context, - volume_ref, - 'exists', extra_usage_info=extra_info) except Exception as exc_msg: LOG.exception(_LE("Exists volume notification failed: %s"), exc_msg, resource=volume_ref) @@ -132,12 +132,6 @@ def main(): 'audit_period_beginning': str(volume_ref.created_at), 'audit_period_ending': str(volume_ref.created_at), } - LOG.debug("Send create notification for " - " " - " <%(extra_info)s>", - {'volume_id': volume_ref.id, - 'project_id': volume_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_volume_usage( admin_context, volume_ref, @@ -146,6 +140,12 @@ def main(): admin_context, volume_ref, 'create.end', extra_usage_info=local_extra_info) + LOG.debug("Sent create notification for " + " " + " <%(extra_info)s>", + {'volume_id': volume_ref.id, + 'project_id': volume_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.exception(_LE("Create volume notification failed: %s"), exc_msg, resource=volume_ref) @@ -158,12 +158,6 @@ def main(): 'audit_period_beginning': str(volume_ref.deleted_at), 'audit_period_ending': str(volume_ref.deleted_at), } - LOG.debug("Send delete notification for " - " " - " <%(extra_info)s>", - {'volume_id': volume_ref.id, - 'project_id': volume_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_volume_usage( admin_context, volume_ref, @@ -172,24 +166,30 @@ def main(): admin_context, volume_ref, 'delete.end', extra_usage_info=local_extra_info) + LOG.debug("Sent delete notification for " + " " + " <%(extra_info)s>", + {'volume_id': volume_ref.id, + 'project_id': volume_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.exception(_LE("Delete volume notification failed: %s"), exc_msg, resource=volume_ref) snapshots = objects.SnapshotList.get_active_by_window(admin_context, begin, end) - LOG.debug("Found %d snapshots", len(snapshots)) + LOG.info(_LI("Found %d snapshots"), len(snapshots)) for snapshot_ref in snapshots: try: - LOG.debug("Send notification for " - " <%(extra_info)s>", - {'snapshot_id': snapshot_ref.id, - 'project_id': snapshot_ref.project_id, - 'extra_info': extra_info}) cinder.volume.utils.notify_about_snapshot_usage(admin_context, snapshot_ref, 'exists', extra_info) + LOG.debug("Sent notification for " + " <%(extra_info)s>", + {'snapshot_id': snapshot_ref.id, + 'project_id': snapshot_ref.project_id, + 'extra_info': extra_info}) except Exception as exc_msg: LOG.exception(_LE("Exists snapshot notification failed: %s"), exc_msg, resource=snapshot_ref) @@ -202,12 +202,6 @@ def main(): 'audit_period_beginning': str(snapshot_ref.created_at), 'audit_period_ending': str(snapshot_ref.created_at), } - LOG.debug("Send create notification for " - " " - " <%(extra_info)s>", - {'snapshot_id': snapshot_ref.id, - 'project_id': snapshot_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_snapshot_usage( admin_context, snapshot_ref, @@ -216,6 +210,12 @@ def main(): admin_context, snapshot_ref, 'create.end', extra_usage_info=local_extra_info) + LOG.debug("Sent create notification for " + " " + " <%(extra_info)s>", + {'snapshot_id': snapshot_ref.id, + 'project_id': snapshot_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.exception(_LE("Create snapshot notification failed: %s"), exc_msg, resource=snapshot_ref) @@ -228,12 +228,6 @@ def main(): 'audit_period_beginning': str(snapshot_ref.deleted_at), 'audit_period_ending': str(snapshot_ref.deleted_at), } - LOG.debug("Send delete notification for " - " " - " <%(extra_info)s>", - {'snapshot_id': snapshot_ref.id, - 'project_id': snapshot_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_snapshot_usage( admin_context, snapshot_ref, @@ -242,6 +236,12 @@ def main(): admin_context, snapshot_ref, 'delete.end', extra_usage_info=local_extra_info) + LOG.debug("Sent delete notification for " + " " + " <%(extra_info)s>", + {'snapshot_id': snapshot_ref.id, + 'project_id': snapshot_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.exception(_LE("Delete snapshot notification failed: %s"), exc_msg, resource=snapshot_ref) @@ -249,18 +249,18 @@ def main(): backups = db.backup_get_active_by_window(admin_context, begin, end) - LOG.debug("Found %d backups", len(backups)) + LOG.info(_LI("Found %d backups"), len(backups)) for backup_ref in backups: try: - LOG.debug("Send notification for " - " <%(extra_info)s>", - {'backup_id': backup_ref.id, - 'project_id': backup_ref.project_id, - 'extra_info': extra_info}) cinder.volume.utils.notify_about_backup_usage(admin_context, backup_ref, 'exists', extra_info) + LOG.debug("Sent notification for " + " <%(extra_info)s>", + {'backup_id': backup_ref.id, + 'project_id': backup_ref.project_id, + 'extra_info': extra_info}) except Exception as exc_msg: LOG.error(_LE("Exists backups notification failed: %s"), exc_msg) @@ -273,12 +273,6 @@ def main(): 'audit_period_beginning': str(backup_ref.created_at), 'audit_period_ending': str(backup_ref.created_at), } - LOG.debug("Send create notification for " - " " - " <%(extra_info)s>", - {'backup_id': backup_ref.id, - 'project_id': backup_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_backup_usage( admin_context, backup_ref, @@ -287,6 +281,12 @@ def main(): admin_context, backup_ref, 'create.end', extra_usage_info=local_extra_info) + LOG.debug("Sent create notification for " + " " + " <%(extra_info)s>", + {'backup_id': backup_ref.id, + 'project_id': backup_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.error(_LE("Create backup notification failed: %s"), exc_msg) @@ -299,12 +299,6 @@ def main(): 'audit_period_beginning': str(backup_ref.deleted_at), 'audit_period_ending': str(backup_ref.deleted_at), } - LOG.debug("Send delete notification for " - " " - " <%(extra_info)s>", - {'backup_id': backup_ref.id, - 'project_id': backup_ref.project_id, - 'extra_info': local_extra_info}) cinder.volume.utils.notify_about_backup_usage( admin_context, backup_ref, @@ -313,8 +307,14 @@ def main(): admin_context, backup_ref, 'delete.end', extra_usage_info=local_extra_info) + LOG.debug("Sent delete notification for " + " " + " <%(extra_info)s>", + {'backup_id': backup_ref.id, + 'project_id': backup_ref.project_id, + 'extra_info': local_extra_info}) except Exception as exc_msg: LOG.error(_LE("Delete backup notification failed: %s"), exc_msg) - LOG.debug("Volume usage audit completed") + LOG.info(_LI("Volume usage audit completed")) diff --git a/cinder/tests/unit/test_volume_utils.py b/cinder/tests/unit/test_volume_utils.py index c49b113a76a..bca8c71648a 100644 --- a/cinder/tests/unit/test_volume_utils.py +++ b/cinder/tests/unit/test_volume_utils.py @@ -166,6 +166,52 @@ class NotifyUsageTestCase(test.TestCase): } self.assertDictMatch(expected_snapshot, usage_info) + @mock.patch('cinder.objects.Volume.get_by_id') + def test_usage_from_deleted_snapshot(self, volume_get_by_id): + raw_volume = { + 'id': fake.VOLUME_ID, + 'availability_zone': 'nova', + 'deleted': 1 + } + ctxt = context.get_admin_context() + volume_obj = fake_volume.fake_volume_obj(ctxt, **raw_volume) + volume_get_by_id.side_effect = exception.VolumeNotFound( + volume_id=fake.VOLUME_ID) + + raw_snapshot = { + 'project_id': fake.PROJECT_ID, + 'user_id': fake.USER_ID, + 'volume': volume_obj, + 'volume_id': fake.VOLUME_ID, + 'volume_size': 1, + 'id': fake.SNAPSHOT_ID, + 'display_name': '11', + 'created_at': '2014-12-11T10:10:00', + 'status': fields.SnapshotStatus.ERROR, + 'deleted': '', + 'snapshot_metadata': [{'key': 'fake_snap_meta_key', + 'value': 'fake_snap_meta_value'}], + 'expected_attrs': ['metadata'], + } + + snapshot_obj = fake_snapshot.fake_snapshot_obj(ctxt, **raw_snapshot) + usage_info = volume_utils._usage_from_snapshot(snapshot_obj) + expected_snapshot = { + 'tenant_id': fake.PROJECT_ID, + 'user_id': fake.USER_ID, + 'availability_zone': '', + 'volume_id': fake.VOLUME_ID, + 'volume_size': 1, + 'snapshot_id': fake.SNAPSHOT_ID, + 'display_name': '11', + 'created_at': 'DONTCARE', + 'status': fields.SnapshotStatus.ERROR, + 'deleted': '', + 'metadata': six.text_type({'fake_snap_meta_key': + u'fake_snap_meta_value'}), + } + self.assertDictMatch(expected_snapshot, usage_info) + @mock.patch('cinder.db.volume_glance_metadata_get') @mock.patch('cinder.db.volume_attachment_get_all_by_volume_id') def test_usage_from_volume(self, mock_attachment, mock_image_metadata): diff --git a/cinder/volume/utils.py b/cinder/volume/utils.py index 352cf5c1c92..fd4f78183ef 100644 --- a/cinder/volume/utils.py +++ b/cinder/volume/utils.py @@ -152,10 +152,22 @@ def notify_about_backup_usage(context, backup, event_suffix, def _usage_from_snapshot(snapshot, **extra_usage_info): + try: + az = snapshot.volume['availability_zone'] + except exception.VolumeNotFound: + # (zhiteng) Snapshot's source volume could have been deleted + # (which means snapshot has been deleted as well), + # lazy-loading volume would raise VolumeNotFound exception. + # In that case, not going any further by abusing low level + # DB API to fetch deleted volume but simply return empty + # string for snapshot's AZ info. + az = '' + LOG.debug("Source volume %s deleted", snapshot.volume_id) + usage_info = { 'tenant_id': snapshot.project_id, 'user_id': snapshot.user_id, - 'availability_zone': snapshot.volume['availability_zone'], + 'availability_zone': az, 'volume_id': snapshot.volume_id, 'volume_size': snapshot.volume_size, 'snapshot_id': snapshot.id,