[SRU] volume usage audit print excessive debug log for deleted resources

Bug #1631561 reported by Huang Zhiteng on 2016-10-08
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Cinder
Low
Huang Zhiteng
Ubuntu Cloud Archive
Undecided
Unassigned
Mitaka
Undecided
Unassigned
Newton
Undecided
Unassigned
cinder (Ubuntu)
Medium
Unassigned
Xenial
Medium
Jorge Niedbalski
Yakkety
Medium
Jorge Niedbalski

Bug Description

[Impact]

* Current volume usage audit tool queries all volumes/snapshots/backups including those resources have been deleted, as a result, every single deleted resource would trigger a few debug/exception level messages, which is too much for a running production cluster at hour/day period.

* notify_snapshot_usage() doesn't handles the case when
 when the source volume for the snapshot has been deleted.

The following exception is raised:

2017-02-17 20:20:10.067 1921 ERROR cinder [req-7e273ce0-1ae8-410e-a814-0f444364c028 - - - - -] Exists snapshot notification failed: Volume 2c84e585-9947-4ad9-bd93-2fc3a5cf9a08 could not be found.
2017-02-17 20:20:10.067 1921 ERROR cinder Traceback (most recent call last):
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/cmd/volume_usage_audit.py", line 188, in main
2017-02-17 20:20:10.067 1921 ERROR cinder extra_info)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 174, in notify_about_snapshot_usage
2017-02-17 20:20:10.067 1921 ERROR cinder usage_info = _usage_from_snapshot(snapshot, **extra_usage_info)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 151, in _usage_from_snapshot
2017-02-17 20:20:10.067 1921 ERROR cinder 'availability_zone': snapshot.volume['availability_zone'],
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 67, in getter
2017-02-17 20:20:10.067 1921 ERROR cinder self.obj_load_attr(name)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/objects/snapshot.py", line 196, in obj_load_attr
2017-02-17 20:20:10.067 1921 ERROR cinder self.volume_id)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder result = fn(cls, context, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/objects/base.py", line 166, in get_by_id
2017-02-17 20:20:10.067 1921 ERROR cinder orm_obj = db.get_by_id(context, model, id, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/api.py", line 1127, in get_by_id
2017-02-17 20:20:10.067 1921 ERROR cinder return IMPL.get_by_id(context, model, id, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 193, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder return f(*args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 4451, in get_by_id
2017-02-17 20:20:10.067 1921 ERROR cinder return _GET_METHODS[model](context, id, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 193, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder return f(*args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 1480, in volume_get
2017-02-17 20:20:10.067 1921 ERROR cinder return _volume_get(context, volume_id)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 193, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder return f(*args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 1425, in _volume_get
2017-02-17 20:20:10.067 1921 ERROR cinder raise exception.VolumeNotFound(volume_id=volume_id)
2017-02-17 20:20:10.067 1921 ERROR cinder VolumeNotFound: Volume 2c84e585-9947-4ad9-bd93-2fc3a5cf9a08 could not be found.

[Test Case]

 *The steps to reproduce this bug:

1) Deploy Mitaka/Newton cloud
2) Set the volumes as deleted on the database

mysql> update volumes set deleted = 1;
Query OK, 2 rows affected (0.00 sec)
Rows matched: 2 Changed: 2 Warnings: 0

3) Run the cinder-volume-usage-audit command:

# /usr/bin/cinder-volume-usage-audit --start_time "2017-02-17 15:10:00" --end_time "2017-02-17 15:20:00" --debug

[Regression Potential]

 * None identified as the commit fixes a already existing misbehavior.

Related branches

~niedbalski/ubuntu/+source/cinder:stable/mitaka
Ubuntu Server Developers: Pending requested 2017-03-10
~niedbalski/ubuntu/+source/cinder:stable/newton
Ubuntu Server Developers: Pending requested 2017-03-10
Changed in cinder:
assignee: nobody → Huang Zhiteng (zhiteng-huang)
importance: Undecided → Low

Fix proposed to branch: master
Review: https://review.openstack.org/384124

Changed in cinder:
status: New → In Progress

Reviewed: https://review.openstack.org/384124
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=f4f42c966e378109f5ba9e4b800ae6e23dde1c75
Submitter: Jenkins
Branch: master

commit f4f42c966e378109f5ba9e4b800ae6e23dde1c75
Author: Zhiteng Huang <email address hidden>
Date: Sat Oct 8 13:03:37 2016 -0700

    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

Changed in cinder:
status: In Progress → Fix Released

This issue was fixed in the openstack/cinder 10.0.0.0b1 development milestone.

Changed in cinder (Ubuntu Xenial):
status: New → In Progress
Changed in cinder (Ubuntu):
status: New → Fix Released
Changed in cinder (Ubuntu Yakkety):
status: New → In Progress
Changed in cinder (Ubuntu):
importance: Undecided → Medium
Changed in cinder (Ubuntu Xenial):
importance: Undecided → Medium
Changed in cinder (Ubuntu Yakkety):
importance: Undecided → Medium
Changed in cinder (Ubuntu):
assignee: nobody → Jorge Niedbalski (niedbalski)
assignee: Jorge Niedbalski (niedbalski) → nobody
Changed in cinder (Ubuntu Xenial):
assignee: nobody → Jorge Niedbalski (niedbalski)
Changed in cinder (Ubuntu Yakkety):
assignee: nobody → Jorge Niedbalski (niedbalski)
Download full text (4.3 KiB)

Hello,

I am able to reproduce this bug on Xenial-Mitaka, Xenial-Newton by manually setting
the volume to deleted = 1 on the database.

We need to understand which condition causes to the volume to be flagged as deleted while the snapshots remain available, but that's a second investigation to be made.

The steps to reproduce this bug:

1) Deploy Mitaka/Newton cloud
2) Set the volumes as deleted on the database

mysql> update volumes set deleted = 1;
Query OK, 2 rows affected (0.00 sec)
Rows matched: 2 Changed: 2 Warnings: 0

3) Run the cinder-volume-usage-audit command:

root@juju-niedbalski-xenial-machine-5:/home/ubuntu# /usr/bin/cinder-volume-usage-audit --start_time "2017-02-17 15:10:00" --end_time "2017-02-17 15:20:00" --debug

Then the exception is raised:

2017-02-17 20:20:10.067 1921 ERROR cinder [req-7e273ce0-1ae8-410e-a814-0f444364c028 - - - - -] Exists snapshot notification failed: Volume 2c84e585-9947-4ad9-bd93-2fc3a5cf9a08 could not be found.
2017-02-17 20:20:10.067 1921 ERROR cinder Traceback (most recent call last):
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/cmd/volume_usage_audit.py", line 188, in main
2017-02-17 20:20:10.067 1921 ERROR cinder extra_info)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 174, in notify_about_snapshot_usage
2017-02-17 20:20:10.067 1921 ERROR cinder usage_info = _usage_from_snapshot(snapshot, **extra_usage_info)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 151, in _usage_from_snapshot
2017-02-17 20:20:10.067 1921 ERROR cinder 'availability_zone': snapshot.volume['availability_zone'],
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 67, in getter
2017-02-17 20:20:10.067 1921 ERROR cinder self.obj_load_attr(name)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/objects/snapshot.py", line 196, in obj_load_attr
2017-02-17 20:20:10.067 1921 ERROR cinder self.volume_id)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder result = fn(cls, context, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/objects/base.py", line 166, in get_by_id
2017-02-17 20:20:10.067 1921 ERROR cinder orm_obj = db.get_by_id(context, model, id, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/api.py", line 1127, in get_by_id
2017-02-17 20:20:10.067 1921 ERROR cinder return IMPL.get_by_id(context, model, id, *args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 193, in wrapper
2017-02-17 20:20:10.067 1921 ERROR cinder return f(*args, **kwargs)
2017-02-17 20:20:10.067 1921 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 4451, in get_by_id
2017-02-...

Read more...

summary: - volume usage audit print excessive debug log for deleted resources
+ [SRU] volume usage audit print excessive debug log for deleted resources
Jorge Niedbalski (niedbalski) wrote :
tags: added: sts
description: updated
Jorge Niedbalski (niedbalski) wrote :
Changed in cloud-archive:
status: New → Fix Released
Alvaro Uría (aluria) on 2017-03-02
tags: added: canonical-bootstack

Change abandoned by Sean McGinnis (<email address hidden>) on branch: stable/mitaka
Review: https://review.openstack.org/436130

Chuck Short (zulcss) wrote :

Can you rediff your patches so that they apply cleanly to whats in the packaging git tree. Thanks

Jorge Niedbalski (niedbalski) wrote :

@zulcss

Sure I can, Could you please point me to the source branches of cinder M/N to do a rebase the patch directly against them?

Many thanks.

Jorge Niedbalski (niedbalski) wrote :

@corey, @zul, attached both MPs against stable/newton and stable/mitaka.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers