Merge ~niedbalski/ubuntu/+source/cinder:stable/newton into ~ubuntu-server-dev/ubuntu/+source/cinder:stable/newton

[Jorge Niedbalski]

* d/p/log-message-cleanup-for-volume-usage-audit.patch:
    Fixes LP: #1631561.

diff --git a/debian/changelog b/debian/changelog
index 570a073..cdcd84a 100644
--- a/debian/changelog
+++ b/debian/changelog
@@ -1,3 +1,10 @@
+cinder (2:9.1.2-0ubuntu2) yakkety; urgency=medium
+
+  * d/p/log-message-cleanup-for-volume-usage-audit.patch:
+    Fixes LP: #1631561.
+
+ -- Jorge Niedbalski <[e-mail]>  Fri, 10 Mar 2017 18:20:41 -0300
+
 cinder (2:9.1.2-0ubuntu1) yakkety; urgency=medium
 
   [ Corey Bryant ]
diff --git a/debian/patches/log-message-cleanup-for-volume-usage-audit.patch b/debian/patches/log-message-cleanup-for-volume-usage-audit.patch
new file mode 100644
index 0000000..9421d04
--- /dev/null
+++ b/debian/patches/log-message-cleanup-for-volume-usage-audit.patch
@@ -0,0 +1,306 @@
+From 82792be330e3b88aa1f625537ae1d2649e14ba4f Mon Sep 17 00:00:00 2001
+From: Zhiteng Huang <[e-mail]>
+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 <volume_id: "
++            cinder.volume.utils.notify_about_volume_usage(
++                admin_context,
++                volume_ref,
++                'exists', extra_usage_info=extra_info)
++            LOG.debug("Sent exists notification for <volume_id: "
+                       "%(volume_id)s> <project_id %(project_id)s> "
+                       "<%(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 "
+-                          "<volume_id: %(volume_id)s> "
+-                          "<project_id %(project_id)s> <%(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 "
++                          "<volume_id: %(volume_id)s> "
++                          "<project_id %(project_id)s> <%(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 "
+-                          "<volume_id: %(volume_id)s> "
+-                          "<project_id %(project_id)s> <%(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 "
++                          "<volume_id: %(volume_id)s> "
++                          "<project_id %(project_id)s> <%(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 <snapshot_id: %(snapshot_id)s> "
+-                      "<project_id %(project_id)s> <%(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 <snapshot_id: %(snapshot_id)s> "
++                      "<project_id %(project_id)s> <%(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 "
+-                          "<snapshot_id: %(snapshot_id)s> "
+-                          "<project_id %(project_id)s> <%(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 "
++                          "<snapshot_id: %(snapshot_id)s> "
++                          "<project_id %(project_id)s> <%(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 "
+-                          "<snapshot_id: %(snapshot_id)s> "
+-                          "<project_id %(project_id)s> <%(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 "
++                          "<snapshot_id: %(snapshot_id)s> "
++                          "<project_id %(project_id)s> <%(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 --git a/debian/patches/series b/debian/patches/series
index 7abc008..238c9c6 100644
--- a/debian/patches/series
+++ b/debian/patches/series
@@ -1,2 +1,3 @@
 google-back-requirements.patch
 fix-long-casting.patch
+log-message-cleanup-for-volume-usage-audit.patch