Volume remains in "detaching" status when user call detach request immediately after attach request

Bug #1430553 reported by Tushar Patil
20
This bug affects 4 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
In Progress
Low
Abhijeet Malawade

Bug Description

Steps to reproduce:
a) Attach a volume to an instance.
b) Wait for volume status to be "in-use".
c) Detach the volume immediately.
d) Wait for volume status to be "available", but it remains in "detaching" status.

How it happens
1) Nova requests cinder to make the volume "attaching".
2) Nova actually attaches the volume to the instance.
3) Nova requests cinder to make the volume "in-use".
4) After the volume becomes "in-use", nova stores connection_info JSON into block_device_mapping table.

If user request detach volume between 3 and 4 above, the volume becomes "detaching" and actual detach procedure fails since there is no connection_info in block_device_mapping.

LOGS
================================================================================================================
### Attaching, request to make the volume "in-use"

2015-02-28 01:09:17,000.747 7026 DEBUG nova.volume.cinder [req-f5978fea-cfa7-4bef-af37-d32d816fe78c None] Cinderclient connection created using URL: http://ct-int-vip:30776/v2/75fdf0098b71463eb87820ef47d93d68 get_cinder_client_version /usr/lib/python2.7/dist-packages/nova/volume/cinder.py:255
2015-02-28 01:09:18,000.561 7026 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._sync_power_states run_periodic_tasks /usr/lib/python2.7/dist-packages/nova/openstack/common/periodic_task.py:193
2015-02-28 01:09:18,000.606 7026 DEBUG nova.compute.manager [-] Triggering sync for uuid 7695a528-c73b-4b44-b4de-2c26974ac471 _sync_manager /usr/lib/python2.7/dist-packages/nova/compute/manager.py:5749
2015-02-28 01:09:18,000.607 7026 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7fd33349e090>> sleeping for 4.49 seconds _inner /usr/lib/python2.7/dist-packages/nova/openstack/common/loopingcall.py:132
2015-02-28 01:09:18,000.607 7026 DEBUG nova.openstack.common.lockutils [-] Using existing semaphore "7695a528-c73b-4b44-b4de-2c26974ac471" internal_lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:202

### Detaching

2015-02-28 01:09:19,000.915 7026 AUDIT nova.compute.manager [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a None] [instance: 7695a528-c73b-4b44-b4de-2c26974ac471] Detach volume 2c923e19-cccf-43ce-8c3f-2e1efda813ed from mountpoint /dev/vdz
2015-02-28 01:09:20,000.132 7026 DEBUG nova.openstack.common.lockutils [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Created new semaphore "compute_resources" internal_lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:206
2015-02-28 01:09:20,000.132 7026 DEBUG nova.openstack.common.lockutils [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Acquired semaphore "compute_resources" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:229
2015-02-28 01:09:20,000.133 7026 DEBUG nova.openstack.common.lockutils [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:271
2015-02-28 01:09:20,000.247 7026 INFO nova.scheduler.client.report [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a None] Compute_service record updated for ('b1cp104', 'b1cp104')
2015-02-28 01:09:20,000.248 7026 DEBUG nova.openstack.common.lockutils [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Releasing semaphore "compute_resources" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:238
2015-02-28 01:09:20,000.248 7026 DEBUG nova.openstack.common.lockutils [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:275

### Detach fails since there is no connection_info, volume remains "detaching"

2015-02-28 01:09:20,000.256 7026 ERROR oslo.messaging.rpc.dispatcher [req-02e1e7ca-1dbf-4f50-b374-236f5ec3700a ] Exception during message handling: <type 'NoneType'> can't be decoded
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 419, in decorated_function
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 88, in wrapped
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher payload)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 71, in wrapped
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return f(self, context, *args, **kw)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 303, in decorated_function
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher pass
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 289, in decorated_function
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 331, in decorated_function
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher kwargs['instance'], e, sys.exc_info())
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 319, in decorated_function
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 4642, in detach_volume
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher self._detach_volume(context, instance, bdm)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 4588, in _detach_volume
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher connection_info = jsonutils.loads(bdm.connection_info)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/openstack/common/jsonutils.py", line 188, in loads
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher return json.loads(strutils.safe_decode(s, encoding), **kwargs)
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/dist-packages/nova/openstack/common/strutils.py", line 145, in safe_decode
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher raise TypeError("%s can't be decoded" % type(text))
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher TypeError: <type 'NoneType'> can't be decoded
2015-02-28 01:09:20,000.256 7026 TRACE oslo.messaging.rpc.dispatcher

### Attach completed

2015-02-28 01:09:20,000.980 7026 DEBUG nova.openstack.common.lockutils [req-f5978fea-cfa7-4bef-af37-d32d816fe78c ] Releasing semaphore "7695a528-c73b-4b44-b4de-2c26974ac471" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:238
2015-02-28 01:09:20,000.980 7026 DEBUG nova.openstack.common.lockutils [req-f5978fea-cfa7-4bef-af37-d32d816fe78c ] Semaphore / lock released "do_attach_volume" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:275
2015-02-28 01:09:20,000.981 7026 DEBUG nova.openstack.common.lockutils [-] Acquired semaphore "7695a528-c73b-4b44-b4de-2c26974ac471" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:229

Tushar Patil (tpatil)
Changed in nova:
assignee: nobody → Tushar Patil (tpatil)
Changed in nova:
status: New → Confirmed
importance: Undecided → Low
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
status: Confirmed → In Progress
Revision history for this message
Matt Riedemann (mriedem) wrote :

This is essentially a duplicate of an old gate bug 1327218.

Changed in nova:
assignee: Tushar Patil (tpatil) → Abhijeet Malawade (abhijeet-malawade)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on nova (master)

Change abandoned by Joe Gordon (<email address hidden>) on branch: master
Review: https://review.openstack.org/163937
Reason: This review is > 4 weeks without comment, and failed Jenkins the last time it was checked. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.