list manageable snapshots fails with lazy load error on snapshot model attr

[Patrick East]

Traceback (most recent call last):
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
    res = self.dispatcher.dispatch(message)
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 225, in dispatch
    return self._do_dispatch(endpoint, method, ctxt, args)
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 195, in _do_dispatch
    result = func(ctxt, **new_args)
', u' File "/opt/stack/new/cinder/cinder/volume/manager.py", line 4183, in get_manageable_snapshots
    LOG.exception(_LE("Listing manageable snapshots failed, due "
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
', u' File "/opt/stack/new/cinder/cinder/volume/manager.py", line 4180, in get_manageable_snapshots
    cinder_snapshots, marker, limit, offset, sort_keys, sort_dirs)
', u' File "/opt/stack/new/cinder/cinder/volume/drivers/pure.py", line 1029, in get_manageable_snapshots
    name = self._get_snap_name(cinder_snap)
', u' File "/opt/stack/new/cinder/cinder/volume/drivers/pure.py", line 1093, in _get_snap_name
    return "%s-cinder.%s" % (snapshot["volume_name"], snapshot["name"])
', u' File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/models.py", line 54, in __getitem__
    return getattr(self, key)
', u' File "/opt/stack/new/cinder/cinder/db/sqlalchemy/models.py", line 659, in volume_name
    return self.volume.name # pylint: disable=E1101
', u' File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
    return self.impl.get(instance_state(instance), dict_)
', u' File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 583, in get
    value = self.callable_(state, passive)
', u' File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/strategies.py", line 517, in _load_for_state
    (orm_util.state_str(state), self.key)
', u"DetachedInstanceError: Parent instance <Snapshot at 0x7f0db58d9ad0> is not bound to a Session; lazy load operation of attribute 'volume' cannot proceed

Full logs http://52.8.17.232/PureISCSIDriver-tempest-dsvm-trusty-aio-multipath-obj-scale/26/logs/screen-c-api.txt.gz?level=ERROR#_2016-11-10_04_08_40_638

Looks like there is something wrong with the way we are getting the snapshot objects from the query in volume/manager.py, in the driver it is just trying to look at snapshot['volume-name'] and breaking as it tries to lazy load the volume attribute.

[Matt Riedemann (mriedem)]

Seeing a similar failure here in a CI job run during what appears to be teardown of the test so likely the lazy load failure is due to a deleted resource:

http://logs.openstack.org/06/641806/12/check/nova-next/c7f23f4/logs/screen-c-api.txt.gz?level=TRACE#_Apr_20_23_19_28_844945

Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault [None req-eed65cf5-f6db-4782-b63f-a7191697eb5e tempest-TestEncryptedCinderVolumes-2130063619 tempest-TestEncryptedCinderVolumes-2130063619] Caught error: <class 'sqlalchemy.orm.exc.DetachedInstanceError'> Parent instance <VolumeAttachment at 0x7f570edb7320> is not bound to a Session; lazy load operation of attribute 'volume' cannot proceed (Background on this error at: http://sqlalche.me/e/bhk3): sqlalchemy.orm.exc.DetachedInstanceError: Parent instance <VolumeAttachment at 0x7f570edb7320> is not bound to a Session; lazy load operation of attribute 'volume' cannot proceed (Background on this error at: http://sqlalche.me/e/bhk3)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault Traceback (most recent call last):
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/opt/stack/new/cinder/cinder/api/middleware/fault.py", line 85, in __call__
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault return req.get_response(self.application)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/usr/local/lib/python3.6/dist-packages/webob/request.py", line 1314, in send
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault application, catch_exc_info=False)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/usr/local/lib/python3.6/dist-packages/webob/request.py", line 1278, in call_application
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault app_iter = application(self.environ, start_response)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/usr/local/lib/python3.6/dist-packages/webob/dec.py", line 143, in __call__
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault return resp(environ, start_response)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/usr/local/lib/python3.6/dist-packages/webob/dec.py", line 129, in __call__
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault resp = self.call_func(req, *args, **kw)
Apr 20 23:19:28.844945 ubuntu-bionic-rax-dfw-0005375337 <email address hidden>[398]: ERROR cinder.api.middleware.fault File "/usr/local/lib/python3.6/dist-pa...

[Matt Riedemann (mriedem)]

For the issue in comment 1 it could be a race in how TestEncryptedCinderVolumes:_run_cleanups runs (maybe something is out of order?).

[Matt Riedemann (mriedem)]

Bug 1626499 could be related to the issue in comment 1 or a duplicate.

[Matt Riedemann (mriedem)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Parent%20instance%20%3CVolumeAttachment%5C%22%20AND%20message%3A%5C%22is%20not%20bound%20to%20a%20Session%3B%20lazy%20load%20operation%20of%20attribute%20'volume'%20cannot%20proceed%5C%22%20AND%20tags%3A%5C%22screen-c-api.txt%5C%22&from=7d

[Matt Riedemann (mriedem)]

This is the request that fails:

2019-04-20 23:19:28,850 7870 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 20 Apr 2019 23:19:28 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version', 'content-length': '128', 'content-type': 'application/json', 'x-compute-request-id': 'req-eed65cf5-f6db-4782-b63f-a7191697eb5e', 'x-openstack-request-id': 'req-eed65cf5-f6db-4782-b63f-a7191697eb5e', 'connection': 'close', 'status': '500', 'content-location': 'https://104.130.127.82/volume/v3/15cab1f3b3ea4491a5f62d49368897dd/volumes/detail?all_tenants=1'}
        Body: b'{"computeFault": {"code": 500, "message": "The server has either erred or is incapable of performing the requested operation."}}'

And right before it:

2019-04-20 23:19:28,670 7870 INFO [tempest.lib.common.rest_client] Request (TestEncryptedCinderVolumes:_run_cleanups): 404 GET https://104.130.127.82/volume/v3/4615ed1db47a4db48e5b4ed79460d6ec/volumes/2ba8052d-8fd0-4b42-8ca7-7313e215cbc5 0.066s
2019-04-20 23:19:28,671 7870 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 20 Apr 2019 23:19:28 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version', 'content-length': '109', 'content-type': 'application/json', 'x-compute-request-id': 'req-d030a6e9-4907-4915-af42-ae5a7dbe0cf3', 'x-openstack-request-id': 'req-d030a6e9-4907-4915-af42-ae5a7dbe0cf3', 'connection': 'close', 'status': '404', 'content-location': 'https://104.130.127.82/volume/v3/4615ed1db47a4db48e5b4ed79460d6ec/volumes/2ba8052d-8fd0-4b42-8ca7-7313e215cbc5'}
        Body: b'{"itemNotFound": {"code": 404, "message": "Volume 2ba8052d-8fd0-4b42-8ca7-7313e215cbc5 could not be found."}}'

So the volume is gone, and then we're listing volumes with details (attachments) across all_tenants and the all_tenants=1 might be loading up deleted fields? So my guess would be the view builder is trying to load attachments which are trying to load a deleted volume and that blows up.

[Sean McGinnis (sean-mcginnis)]

Temporarily assigning to Gorka since he has fixed a few others like this. Feel free to unassign yourself, but wanted to get your input on this.

[melanie witt (melwitt)]

Just had a gate failure on a patch of mine, hitting this same issue:

http://logs.openstack.org/74/659374/4/gate/nova-next/299de4d/logs/screen-c-api.txt.gz?level=TRACE#_May_16_17_33_05_329064