diff -Nru cinder-9.1.0/debian/changelog cinder-9.1.0/debian/changelog --- cinder-9.1.0/debian/changelog 2016-11-29 14:56:17.000000000 -0300 +++ cinder-9.1.0/debian/changelog 2017-02-20 16:07:04.000000000 -0300 @@ -1,3 +1,10 @@ +cinder (2:9.1.0-0ubuntu2) yakkety; urgency=medium + + * d/p/log-message-cleanup-for-volume-usage-audit.patch: + Fixes LP: #1631561. + + -- Jorge Niedbalski Mon, 20 Feb 2017 16:06:39 -0300 + cinder (2:9.1.0-0ubuntu1) yakkety; urgency=medium * New upstream stable release for OpenStack Newton (LP: #1645772). diff -Nru cinder-9.1.0/debian/patches/0001-Log-message-cleanup-for-volume-usage-audit.newton.patch cinder-9.1.0/debian/patches/0001-Log-message-cleanup-for-volume-usage-audit.newton.patch --- cinder-9.1.0/debian/patches/0001-Log-message-cleanup-for-volume-usage-audit.newton.patch 1969-12-31 21:00:00.000000000 -0300 +++ cinder-9.1.0/debian/patches/0001-Log-message-cleanup-for-volume-usage-audit.newton.patch 2017-02-20 16:05:42.000000000 -0300 @@ -0,0 +1,306 @@ +From 82792be330e3b88aa1f625537ae1d2649e14ba4f 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 | 80 +++++++++++++++++----------------- + cinder/tests/unit/test_volume_utils.py | 46 +++++++++++++++++++ + cinder/volume/utils.py | 14 +++++- + 3 files changed, 99 insertions(+), 41 deletions(-) + +diff --git a/cinder/cmd/volume_usage_audit.py b/cinder/cmd/volume_usage_audit.py +index ba8d38f..678d4e0 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) +diff --git a/cinder/tests/unit/test_volume_utils.py b/cinder/tests/unit/test_volume_utils.py +index c49b113..bca8c71 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 0aec08a..c811e2d 100644 +--- a/cinder/volume/utils.py ++++ b/cinder/volume/utils.py +@@ -149,10 +149,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, +-- +2.7.4 + diff -Nru cinder-9.1.0/debian/patches/series cinder-9.1.0/debian/patches/series --- cinder-9.1.0/debian/patches/series 2016-11-29 14:56:17.000000000 -0300 +++ cinder-9.1.0/debian/patches/series 2017-02-20 16:05:42.000000000 -0300 @@ -1,2 +1,3 @@ google-back-requirements.patch fix-long-casting.patch +0001-Log-message-cleanup-for-volume-usage-audit.newton.patch