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

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

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

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

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

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/436125

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/436130

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

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

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

Hey Jorge, they're all here: https://code.launchpad.net/~ubuntu-server-dev/+git

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

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!

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.

Also appended the merge proposal for stable/mitaka.

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!

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

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!

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.

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

@Jorge,

Please can you confirm the package versions that you tested?

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

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!

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!

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.

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

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.

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.

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

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.