Huawei OceanStor 5800 V3: 'volume_admin_metadata' lazy load error

[Oleksandr Liemieshko]

Looks like Huawei driver tries to access admin_metadata but context is not admin so it fails if session is busy or expired because this has not been pre-loaded by Cinder.

2016-09-07 14:18:59.668 22218 ERROR cinder.volume.manager [req-14d00815-2c96-48a9-a119-d5e2da8646b2 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec10> is not bound to a Session; lazy load operation of attribute 'volume_admin_metadata' cannot proceed
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher [req-14d00815-2c96-48a9-a119-d5e2da8646b2 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Exception during message handling: Bad or unexpected response from the storage volume backend API: Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec10> is not bound to a Session; lazy load operation of attribute 'volume_admin_metadata' cannot proceed

[Vitaly Sedelnik (vsedelnik)]

Incomplete - please provide MOS version and steps to reproduce

[Ivan Kolodyazhny (e0ne)]

Alexander, please add full traceback and steps to reproduce. It don't have an env but I could try to verify this bug with upstream fixes

[Oleksandr Liemieshko (oliemieshko)]

Unfortunately we couldn't reproduce the issue in our lab. We saw this on customer's env (Fuel 9.0).

Happens randomly when the array is handling multiple requests to create and attach volumes at the same time.

2016-09-07 14:18:59.661 22217 INFO cinder.volume.manager [req-5016e25a-4c33-4670-8844-65fc1a6f19dc 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Terminate volume connection completed successfully.
2016-09-07 14:18:59.668 22218 ERROR cinder.volume.manager [req-14d00815-2c96-48a9-a119-d5e2da8646b2 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec10> is not bound to a Session; lazy load operation of attribute 'volume_admin_metadata' cannot proceed
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher [req-14d00815-2c96-48a9-a119-d5e2da8646b2 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Exception during message handling: Bad or unexpected response from the storage volume backend API: Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec10> is not bound to a Session; lazy load operation of attribute 'volume_admin_metadata' cannot proceed
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher incoming.message))
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 1541, in terminate_connection
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher raise exception.VolumeBackendAPIException(data=err_msg)
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher VolumeBackendAPIException: Bad or unexpected response from the storage volume backend API: Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec10> is not bound to a Session; lazy load operation of attribute 'volume_admin_metadata' cannot proceed
2016-09-07 14:18:59.669 22218 ERROR oslo_messaging.rpc.dispatcher
2016-09-07 14:18:59.673 22218 ERROR oslo_messaging._drivers.common [req-14d00815-2c96-48a9-a119-d5e2da8646b2 1f0a08659d2a4ce1a3523c2637f572be 3b93a86a24e84cd4afae7d336d42fc31 - - -] Returning exception Bad or unexpected response from the storage volume backend API: Terminate volume connection failed: Parent instance <Volume at 0x7fad3b59ec1...

[Justinas Balciunas (justinas-balciunas)]

I would add that this issue is probably specific to Huawei Cinder driver, namely with the way the drive interacts with SQLAlchemy.

The Huawei driver uses the _volume_get_query method in cinder/db/sqlalchemy/api.py.

As the most use cases are for the non-admin users, hence the problem appears immediately. It would not, however, if only the admin user managed (create/attach/detach/delete) the volumes. Also, concurrency is key to the issue. If the operations are atomic - no issues typically happen but with concurrency - always. This type of workload can be simulated with Rally.

[Ivan Kolodyazhny (e0ne)]

Mark as confirmed. It't faced by customer

[Ivan Kolodyazhny (e0ne)]

Alexander, is this issue still valid? If yes, please, provide an env for troubleshooting.

[Oleksandr Liemieshko (oliemieshko)]

Yes, it's still valid. But unfortunately we don't have lab for troubleshooting the issue. I asked to customer about a WebEx session to perform live issue analysis

[Sam Stoelinga (sammiestoel)]

I am decreasing importance to Medium as this is only applicable to customers with Huawei Cinder driver.

[Ivan Kolodyazhny (e0ne)]

Alexander, will we have webex session? We can't resolve an issue without it

[Oleksandr Liemieshko (oliemieshko)]

Ticket was closed by customer, so we won't be able create Webex session for this particular issue. I think we can close the bug

[Oleksandr Liemieshko (oliemieshko)]

We have another ticket from customer related to the issue. We need to fix it

[Ivan Kolodyazhny (e0ne)]

Alexander, please schedule a webex with customer

[Ivan Kolodyazhny (e0ne)]

Short update after the webex:
- issue is reproduced sometimes using Rally
- we don't have steps to reproduce it manually to debug it
- I'll provide a patch to customer with detailed logging
- customer will apply a patch and give us logs after the failure to investigate the issue

[Ivan Kolodyazhny (e0ne)]

- the same issue initialize_connection calls too

[Ivan Kolodyazhny (e0ne)]

Alexander, please, ask customer to apply attached patches, re-run rally until issue will be reproduced and send us logs.

Patches should be applied to all cinder-volume nodes and cinder-volume services should be restarted

[Ivan Kolodyazhny (e0ne)]

Upstream bug filed: https://bugs.launchpad.net/cinder/+bug/1650594