[Bug 1631561] Re: volume usage audit print excessive debug log for deleted resources

[Jorge Niedbalski]

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

After applying the proposed patch the exception is logged but the program continues
without issues.

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to cinder in Ubuntu.
https://bugs.launchpad.net/bugs/1631561

Title:
  volume usage audit print excessive debug log for deleted resources

Status in Cinder:
  Fix Released
Status in Ubuntu Cloud Archive:
  New
Status in cinder package in Ubuntu:
  Fix Released
Status in cinder source package in Xenial:
  In Progress
Status in cinder source package in Yakkety:
  In Progress

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/cinder/+bug/1631561/+subscriptions