Issue

• Cinder snapshots fail to delete and end up in error_deleting state.
• Resetting the state and attempting to delete does not help

[root@controller ~(keystone_qa)]# cinder snapshot-list
+--------------------------------------+--------------------------------------+----------------+--------------+------+
|                  ID                  |              Volume ID               |     Status     | Display Name | Size |
+--------------------------------------+--------------------------------------+----------------+--------------+------+
| 8a0ef494-4e84-4b1b-8be6-e5d7780ca37f | b4a0a013-6c7f-42b7-9606-c36b820ad27d |   available    |   majmnt1    |  1   |
| fb163dda-6929-44a7-b244-5be35bff4ee3 | c5743a9f-d9c3-420c-bcb9-4585ba205f25 | error_deleting |   majmnt1    |  1   |
+--------------------------------------+--------------------------------------+----------------+--------------+------+

• From /var/log/cinder/api.log

2016-01-06 11:15:08.654 22071 DEBUG oslo_messaging._drivers.amqp [-] unpacked context: {u'read_only': False, u'domain': None, u'project_name': u'qa', u'user_id': u'4e6b04842ec6442fb729d59fa970ff6a', u'show_deleted': False, u'roles': [u'admin'], u'user_identity': u'4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -', u'project_domain': None, u'timestamp': u'2016-01-06T16:15:08.374266', u'auth_token': u'***', u'remote_address': u'172.21.2.101', u'quota_class': None, u'resource_uuid': None, u'project_id': u'1b6e3a699d3e4fc1a5bec8546c320327', u'is_admin': True, u'user': u'4e6b04842ec6442fb729d59fa970ff6a', u'service_catalog': [{u'endpoints': [{u'adminURL': u'http://172.21.2.101:35357/v2.0', u'region': u'RegionOne', u'internalURL': u'http://172.21.2.101:5000/v2.0', u'publicURL': u'http://172.21.2.101:5000/v2.0'}], u'type': u'identity', u'name': u'keystone'}, {u'endpoints': [{u'adminURL': u'http://172.21.2.101:8774/v2/1b6e3a699d3e4fc1a5bec8546c320327', u'region': u'RegionOne', u'internalURL': u'http://172.21.2.101:8774/v2/1b6e3a699d3e4fc1a5bec8546c320327', u'publicURL': u'http://172.21.2.101:8774/v2/1b6e3a699d3e4fc1a5bec8546c320327'}], u'type': u'compute', u'name': u'nova'}, {u'endpoints': [{u'adminURL': u'http://172.21.2.101:8080/', u'region': u'RegionOne', u'internalURL': u'http://172.21.2.101:8080/v1/AUTH_1b6e3a699d3e4fc1a5bec8546c320327', u'publicURL': u'http://172.21.2.101:8080/v1/AUTH_1b6e3a699d3e4fc1a5bec8546c320327'}], u'type': u'object-store', u'name': u'swift'}], u'request_id': u'req-e8d23209-00b8-4d6a-b066-7e260eabb288', u'user_domain': None, u'read_deleted': u'no', u'tenant': u'1b6e3a699d3e4fc1a5bec8546c320327'} unpack_context /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqp.py:203
2016-01-06 11:15:08.658 22071 DEBUG oslo_concurrency.lockutils [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Acquired file lock "/var/lib/cinder/tmp/cinder-fb163dda-6929-44a7-b244-5be35bff4ee3-delete_snapshot" after waiting 0.000s acquire /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212
2016-01-06 11:15:08.659 22071 DEBUG oslo_concurrency.lockutils [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Lock "fb163dda-6929-44a7-b244-5be35bff4ee3-delete_snapshot" acquired by "lso_inner2" :: waited 0.001s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:444
2016-01-06 11:15:08.659 22071 INFO cinder.volume.manager [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] snapshot fb163dda-6929-44a7-b244-5be35bff4ee3: deleting
2016-01-06 11:15:08.696 22071 DEBUG cinder.volume.manager [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] snapshot fb163dda-6929-44a7-b244-5be35bff4ee3: deleting delete_snapshot /usr/lib/python2.7/site-packages/cinder/volume/manager.py:709
2016-01-06 11:15:08.698 22071 INFO cinder.volume.drivers.nimble [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Setting snapshot snapshot-fb163dda-6929-44a7-b244-5be35bff4ee3 to online_flag False
2016-01-06 11:15:08.711 22071 INFO cinder.volume.drivers.nimble [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Deleting snapshot snapshot-fb163dda-6929-44a7-b244-5be35bff4ee3 
2016-01-06 11:15:08.723 22071 ERROR cinder.volume.drivers.nimble [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] API delete_snap failed with error string SM-ebusy
2016-01-06 11:15:08.746 22071 DEBUG oslo_concurrency.lockutils [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Releasing file lock "/var/lib/cinder/tmp/cinder-fb163dda-6929-44a7-b244-5be35bff4ee3-delete_snapshot" after holding it for 0.088s release /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:227
2016-01-06 11:15:08.747 22071 DEBUG oslo_concurrency.lockutils [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Lock "fb163dda-6929-44a7-b244-5be35bff4ee3-delete_snapshot" released by "lso_inner2" :: held 0.088s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:456
2016-01-06 11:15:08.747 22071 ERROR oslo_messaging.rpc.dispatcher [req-e8d23209-00b8-4d6a-b066-7e260eabb288 4e6b04842ec6442fb729d59fa970ff6a 1b6e3a699d3e4fc1a5bec8546c320327 - - -] Exception during message handling: Message objects do not support str() because they may contain non-ascii characters. Please use unicode() or translate() instead.
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     executor_callback))
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     executor_callback)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     result = func(ctxt, **new_args)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     return f(*args, **kwargs)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 179, in lso_inner1
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     return lso_inner2(inst, context, snapshot, **kwargs)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 445, in inner
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     return f(*args, **kwargs)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 178, in lso_inner2
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     return f(*_args, **_kwargs)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 726, in delete_snapshot
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     snapshot.save()
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in __exit__
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 716, in delete_snapshot
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     self.driver.delete_snapshot(snapshot)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     return f(*args, **kwargs)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/nimble.py", line 284, in delete_snapshot
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     ignore_list=['SM-enoent'])
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/nimble.py", line 524, in inner_connection_checker
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     if attempts < 1 and (re.search('SM-eaccess', str(e))):
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_i18n/_message.py", line 167, in __str__
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher     raise UnicodeError(msg)
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher UnicodeError: Message objects do not support str() because they may contain non-ascii characters. Please use unicode() or translate() instead.
2016-01-06 11:15:08.747 22071 TRACE oslo_messaging.rpc.dispatcher