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

Bug #1631561 reported by Huang Zhiteng on 2016-10-08
16
This bug affects 2 people
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

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
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.

Hello Huang, or anyone else affected,

Accepted cinder into yakkety-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cinder/2:9.1.2-0ubuntu2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in cinder (Ubuntu Yakkety):
status: In Progress → Fix Committed
tags: added: verification-needed
Changed in cinder (Ubuntu Xenial):
status: In Progress → Fix Committed
Brian Murray (brian-murray) wrote :

Hello Huang, or anyone else affected,

Accepted cinder into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cinder/2:8.1.1-0ubuntu2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Jorge Niedbalski (niedbalski) wrote :

The build is failing on Xenial due to a broken test. I will mark the verification-xenial-failed and attach a new patch to be sponsored.

tags: added: verification-failed-xenial
Jorge Niedbalski (niedbalski) wrote :

Also appended the merge proposal for stable/mitaka.

Changed in cinder (Ubuntu Xenial):
status: Fix Committed → In Progress
Jorge Niedbalski (niedbalski) wrote :
tags: added: sts-sponsor
tags: added: sts-sru-needed
removed: sts-sponsor
Łukasz Zemczak (sil2100) wrote :

Hello Huang, or anyone else affected,

Accepted cinder into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cinder/2:8.1.1-0ubuntu3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in cinder (Ubuntu Xenial):
status: In Progress → Fix Committed

Change abandoned by Jorge Niedbalski R. (<email address hidden>) on branch: stable/newton
Review: https://review.openstack.org/436125

Jorge Niedbalski (niedbalski) wrote :

Hello Lukasz,

I can confirm that the current -proposed version fixes the issue on Yakkety and Xenial series.

Without the patch, I can reproduce the issue as can be seen here: http://pastebin.ubuntu.com/24375830/

After enabling proposed on Xenial and Yakkety, and running through the steps to reproduce,
the exception is not being triggered, as can be seen here: http://pastebin.ubuntu.com/24375842/

Many thanks for the sponsorship!

tags: added: verification-done verification-done-xenial verification-done-yakkety
removed: verification-failed-xenial verification-needed

The verification of the Stable Release Update for cinder has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cinder - 2:9.1.2-0ubuntu2

---------------
cinder (2:9.1.2-0ubuntu2) yakkety; urgency=medium

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

 -- Jorge Niedbalski <email address hidden> Fri, 10 Mar 2017 18:20:41 -0300

Changed in cinder (Ubuntu Yakkety):
status: Fix Committed → Fix Released
Robie Basak (racb) wrote :

@Jorge,

Please can you confirm the package versions that you tested?

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cinder - 2:8.1.1-0ubuntu3

---------------
cinder (2:8.1.1-0ubuntu3) xenial; urgency=medium

  * d/p/log-message-cleanup-for-volume-usage-audit.patch:
     Fixes broken tests introduced by 8.1.1-0ubuntu2 (LP: #1631561).

 -- Jorge Niedbalski <email address hidden> Thu, 06 Apr 2017 12:56:37 -0300

Changed in cinder (Ubuntu Xenial):
status: Fix Committed → Fix Released

Hello Huang, or anyone else affected,

Accepted cinder into mitaka-proposed. The package will build now and be available in the Ubuntu Cloud Archive in a few hours, and then in the -proposed repository.

Please help us by testing this new package. To enable the -proposed repository:

  sudo add-apt-repository cloud-archive:mitaka-proposed
  sudo apt-get update

Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-mitaka-needed to verification-mitaka-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-mitaka-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

tags: added: verification-mitaka-needed
James Page (james-page) wrote :

Hello Huang, or anyone else affected,

Accepted cinder into newton-proposed. The package will build now and be available in the Ubuntu Cloud Archive in a few hours, and then in the -proposed repository.

Please help us by testing this new package. To enable the -proposed repository:

  sudo add-apt-repository cloud-archive:newton-proposed
  sudo apt-get update

Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-newton-needed to verification-newton-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-newton-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

tags: added: verification-newton-needed
Jorge Niedbalski (niedbalski) wrote :

Hello James,

The patch fixes the issue for cloud-archive:mitaka, after applying the latest
update from mitaka-proposed, the exception is not longer raised, and the program
continues its execution correctly.

Reference:

http://paste.ubuntu.com/24449943/

I will mark the verification-mitaka-done.

tags: added: verification-mitaka-done
removed: verification-mitaka-needed
Jorge Niedbalski (niedbalski) wrote :

Hello James,

I just completed the verification for newton, before applying the current newton-proposed patch, the following exception was raised: http://paste.ubuntu.com/24450265/, after applying the latest update from newton-proposed, the exception is not longer raised and the program continues its execution correctly.

Reference:

http://paste.ubuntu.com/24450277/

Marking verification-newton-done

tags: added: verification-newton-done
removed: verification-newton-needed

The verification of the Stable Release Update for cinder has completed successfully and the package has now been released to -updates. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

James Page (james-page) wrote :

This bug was fixed in the package cinder - 2:8.1.1-0ubuntu3~cloud0
---------------

 cinder (2:8.1.1-0ubuntu3~cloud0) trusty-mitaka; urgency=medium
 .
   * New update for the Ubuntu Cloud Archive.
 .
 cinder (2:8.1.1-0ubuntu3) xenial; urgency=medium
 .
   * d/p/log-message-cleanup-for-volume-usage-audit.patch:
      Fixes broken tests introduced by 8.1.1-0ubuntu2 (LP: #1631561).
 .
 cinder (2:8.1.1-0ubuntu2) xenial; urgency=medium
 .
   * d/p/log-message-cleanup-for-volume-usage-audit.patch:
     Fixes LP: #1631561.

James Page (james-page) wrote :

Re-validated with yakkety-proposed regression tests:

======
Totals
======
Ran: 103 tests in 1004.6364 sec.
 - Passed: 97
 - Skipped: 6
 - Expected Fail: 0
 - Unexpected Success: 0
 - Failed: 0
Sum of execute time for each test: 553.9073 sec.

==============
Worker Balance
==============
 - Worker 0 (103 tests) => 0:16:29.464425

James Page (james-page) wrote :

Re-validated xenial-newton-proposed regression tests:

======
Totals
======
Ran: 103 tests in 1048.1681 sec.
 - Passed: 97
 - Skipped: 6
 - Expected Fail: 0
 - Unexpected Success: 0
 - Failed: 0
Sum of execute time for each test: 596.4067 sec.

tags: added: sts-sru-done
removed: sts-sru-needed
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers