cinder-volume-usage-audit breaks when upgrading from Kilo to Liberty

[Tobias Urdin]

The cinder-volume-usage-audit utility breaks when upgrading from Kilo to Liberty.
I think it should be something that is changed in the database which causing this issue.

This is the output from our test environment having two volumes which as you can see it fails on the
iteration of both.

No handlers could be found for logger "oslo_config.cfg"
/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py:241: NotSupportedWarning: Configuration option(s) ['use_tpool'] not supported
  exception.NotSupportedWarning
2015-11-19 08:50:31.946 23397 ERROR cinder [req-cd131e13-3266-485e-8158-4adcb329a1a3 - - - - -] Exists volume notification failed: Parent instance <Volume at 0x7f48daac13d0> is not bound to a Session; lazy load operation of attribute 'volume_metadata' cannot proceed
2015-11-19 08:50:31.946 23397 ERROR cinder Traceback (most recent call last):
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/cmd/volume_usage_audit.py", line 120, in main
2015-11-19 08:50:31.946 23397 ERROR cinder 'exists', extra_usage_info=extra_info)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 125, in notify_about_volume_usage
2015-11-19 08:50:31.946 23397 ERROR cinder usage_info = _usage_from_volume(context, volume, **extra_usage_info)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 75, in _usage_from_volume
2015-11-19 08:50:31.946 23397 ERROR cinder metadata=volume_ref.get('volume_metadata'),)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/models.py", line 68, in get
2015-11-19 08:50:31.946 23397 ERROR cinder return getattr(self, key, default)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
2015-11-19 08:50:31.946 23397 ERROR cinder return self.impl.get(instance_state(instance), dict_)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 578, in get
2015-11-19 08:50:31.946 23397 ERROR cinder value = self.callable_(state, passive)
2015-11-19 08:50:31.946 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/strategies.py", line 502, in _load_for_state
2015-11-19 08:50:31.946 23397 ERROR cinder (orm_util.state_str(state), self.key)
2015-11-19 08:50:31.946 23397 ERROR cinder DetachedInstanceError: Parent instance <Volume at 0x7f48daac13d0> is not bound to a Session; lazy load operation of attribute 'volume_metadata' cannot proceed
2015-11-19 08:50:31.946 23397 ERROR cinder
2015-11-19 08:50:31.950 23397 ERROR cinder [req-cd131e13-3266-485e-8158-4adcb329a1a3 - - - - -] Exists volume notification failed: Parent instance <Volume at 0x7f48daac1450> is not bound to a Session; lazy load operation of attribute 'volume_metadata' cannot proceed
2015-11-19 08:50:31.950 23397 ERROR cinder Traceback (most recent call last):
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/cmd/volume_usage_audit.py", line 120, in main
2015-11-19 08:50:31.950 23397 ERROR cinder 'exists', extra_usage_info=extra_info)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 125, in notify_about_volume_usage
2015-11-19 08:50:31.950 23397 ERROR cinder usage_info = _usage_from_volume(context, volume, **extra_usage_info)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/cinder/volume/utils.py", line 75, in _usage_from_volume
2015-11-19 08:50:31.950 23397 ERROR cinder metadata=volume_ref.get('volume_metadata'),)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/models.py", line 68, in get
2015-11-19 08:50:31.950 23397 ERROR cinder return getattr(self, key, default)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
2015-11-19 08:50:31.950 23397 ERROR cinder return self.impl.get(instance_state(instance), dict_)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 578, in get
2015-11-19 08:50:31.950 23397 ERROR cinder value = self.callable_(state, passive)
2015-11-19 08:50:31.950 23397 ERROR cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/strategies.py", line 502, in _load_for_state
2015-11-19 08:50:31.950 23397 ERROR cinder (orm_util.state_str(state), self.key)
2015-11-19 08:50:31.950 23397 ERROR cinder DetachedInstanceError: Parent instance <Volume at 0x7f48daac1450> is not bound to a Session; lazy load operation of attribute 'volume_metadata' cannot proceed
2015-11-19 08:50:31.950 23397 ERROR cinder

[Tobias Urdin (tobias-urdin)]

Error is suppressed when commeting out the metadata line in the dict at /usr/lib/python2.7/dist-packages/cinder/volume/utils.py line 75.
So this should be an issue with the sqlalchemy query which is incorrect or some value checking is wrong since my volumes dont have any volume_metadata entries in the database.

I don't know what impact removing this line has.

[Tobias Urdin (tobias-urdin)]

I fail to see what purpose loading any metadata would be relevant for the cinder-volume-usage-audit auditing process.

[Tobias Urdin (tobias-urdin)]

I won't submit any change for this because I don't know what it affects but I will just include it here if anybody has the same error message and want to have is suppressed.

[Tobias Urdin (tobias-urdin)]

Here is a quick fix by Michal Dulko (dulek) after talking on IRC, he will work out a review fix for this when he has time I don't have the knowledge to dig deeper into this.

Ignore my ugly fix above and instead use this one if you are really in need of a quick fix.
Please note we cannot guarantee this causes any other issues since it hasn't been tested properly.

In /usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py add the change on line 10 in the following paste.
http://paste.openstack.org/show/479381/

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit 586727cef755abeb3360f176782c1b1dd680d318
Author: Michał Dulko <email address hidden>
Date: Fri Nov 20 12:36:22 2015 +0100

    Eager load columns in volume_get_active_by_window

    All other volume-related methods in db.sqlalchemy.api are eager loading
    volume_metadata, volume_admin_metadata (if admin), volume_type,
    volume_attachment and consistencygroup. volume_get_active_by_window
    wasn't, causing fails because of SQLAlchemy Session being closed when
    trying to lazy load volume_metadata. This commit adds missing
    options(joinedload()) to this query.

    Change-Id: I33ec89d7f1f43aae6010aaa6e12951b7c522b8f0
    Closes-Bug: 1517763
    Related-Bug: 1501838

[Thierry Carrez (ttx)]

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

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/304446

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/304446
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=7e970a1da65431655179b3bba084f4a63fdae959
Submitter: Jenkins
Branch: stable/liberty

commit 7e970a1da65431655179b3bba084f4a63fdae959
Author: Michał Dulko <email address hidden>
Date: Fri Nov 20 12:36:22 2015 +0100

    Eager load columns in volume_get_active_by_window

    All other volume-related methods in db.sqlalchemy.api are eager loading
    volume_metadata, volume_admin_metadata (if admin), volume_type,
    volume_attachment and consistencygroup. volume_get_active_by_window
    wasn't, causing fails because of SQLAlchemy Session being closed when
    trying to lazy load volume_metadata. This commit adds missing
    options(joinedload()) to this query.

    Change-Id: I33ec89d7f1f43aae6010aaa6e12951b7c522b8f0
    Closes-Bug: 1517763
    Related-Bug: 1501838
    (cherry picked from commit 586727cef755abeb3360f176782c1b1dd680d318)

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/cinder 7.0.2 release.

[Tobias Urdin (tobias-urdin)]

When can we expect a 7.0.2 release for stable liberty in Ubuntu cloud archieve? Added Ubuntu as distro

[Tobias Urdin (tobias-urdin)]

Bump

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "cinder-volume-usage-audit-error-fix.patch" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

[Tobias Urdin (tobias-urdin)]

Removed patch flag from attachment because it's not the resolution.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 7.0.2 release.

[Corey Bryant (corey.bryant)]

This looks to be valid for kilo and icehouse as well so triaging it accordingly for ubuntu.