CleanableInUse error in a deployment with just one cinder-volume

[Alfredo Moralejo]

While running tempest tests in a deployment using current packages versions in master (ocata), we've found a test failing claiming it can't delete a volume:

11:05:50 Captured traceback:
11:05:50 ~~~~~~~~~~~~~~~~~~~
11:05:50 Traceback (most recent call last):
11:05:50 File "/tmp/openstack/tempest/tempest/api/volume/base.py", line 149, in delete_volume
11:05:50 client.wait_for_resource_deletion(volume_id)
11:05:50 File "/tmp/openstack/tempest/tempest/lib/common/rest_client.py", line 862, in wait_for_resource_deletion
11:05:50 raise exceptions.TimeoutException(message)
11:05:50 tempest.lib.exceptions.TimeoutException: Request timed out
11:05:50 Details: (VolumesV2GetTest:_run_cleanups) Failed to delete volume 52fa32f4-a259-4101-b391-b97a7760242f within the required time (300 s).

When investigating the logs i see the DELETE call in api logs:

2016-11-12 10:52:46.449 15068 INFO cinder.api.openstack.wsgi [req-23ae17e6-02d4-438d-bc9e-3fcb28583dad cbaccdf81ac84196a784e459ff98ca4c 2d346a39e22549d3bba0345cbec63a39 - default default] DELETE https://[::1]:8776/v2/2d346a39e22549d3bba0345cbec63a39/volumes/52fa32f4-a259-4101-b391-b97a7760242f

And this error in cinder-volume log:

2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server [req-23ae17e6-02d4-438d-bc9e-3fcb28583dad cbaccdf81ac84196a784e459ff98ca4c 2d346a39e22549d3bba0345cbec63a39 - default default] Exception during message handling
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 225, in dispatch
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 195, in _do_dispatch
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "<string>", line 2, in delete_volume
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinder/coordination.py", line 286, in _synchronized
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server return f(*a, **k)
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "<string>", line 2, in delete_volume
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinder/objects/cleanable.py", line 188, in wrapper
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server cleanable.set_worker()
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinder/objects/cleanable.py", line 152, in set_worker
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server id=self.id)
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server CleanableInUse: Volume with id 52fa32f4-a259-4101-b391-b97a7760242f is already being cleaned up or another host has taken over it.
2016-11-12 10:52:46.526 12386 ERROR oslo_messaging.rpc.server

Note this is a single node installation with a single cinder-volume instance and coordination is using backend_url = file:///var/lib/cinder

Cinder version openstack-cinder-9.0.0-0.20161111234718.353216c.el7.centos.noarch

Logs, configuration files and additional information can be found in:

https://ci.centos.org/artifacts/rdo/weirdo-master-promote-puppet-openstack-scenario001/665/weirdo-project/logs/

Note that some other DELETE operations succeeded so this seems to happen intermittently.

[Alfredo Moralejo (amoralej)]

Other example: http://logs.openstack.org/88/397088/1/check/gate-puppet-openstack-integration-4-scenario002-tempest-centos-7/e34f572/logs/cinder/volume.txt.gz

[Alex Schultz (alex-schultz)]

After further review, it's probably a failure related to https://review.openstack.org/#/c/303021/

[Gorka Eguileor (gorka)]

This is caused by a bug in PyMySQL in rounding the microseconds: https://github.com/PyMySQL/PyMySQL/pull/487

Due to this bug a DATETIME in the DB like this "2016-11-15 11:44:16.516917" would be read in Cinder as "2016-11-15 11:44:16.516916", which makes the whole conditional update impossible since the datetime is different.

This is fixed in PyMySQL version 0.7.6, so we need to bump the minimum version.

[Gorka Eguileor (gorka)]

Fix bumping PyMySQL version has been merged: https://review.openstack.org/#/c/397830/

[Sean McGinnis (sean-mcginnis)]

Addressed in Cinder with patch https://review.openstack.org/484213

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/requirements 1.1.0 release.

[Sean McGinnis (sean-mcginnis)]

Cinder patch abandoned, this is not a Cinder specific requirement and should get the right version if following the OpenStack minimum requirements and using constraints.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/requirements ocata-eol release.