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
This commit is contained in:
Zhiteng Huang 2016-10-08 13:03:37 -07:00
parent 674a6b0a7c
commit f4f42c966e
3 changed files with 118 additions and 60 deletions

View File

@ -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)
@ -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 <backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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 <backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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 "
"<backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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 "
"<backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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 "
"<backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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 "
"<backup_id: %(backup_id)s> "
"<project_id %(project_id)s> <%(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"))

View File

@ -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):

View File

@ -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,