Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Heat: Deletion of volume attachments fail during stack-delete

Running Icehouse 2014.1.2 along with the version of Heat included with this release. Control nodes are running Oracle Enterprise Linux 6.5.
Compute nodes are running Oracle Virtual Server 3.3.2 (Xen-based kernel)

I have a stack which does the following:

  1. Creates volume
  2. Creates server
  3. Attaches the volume as a secondary device
  4. Associates floating IP

This all works fine. The problem occures when deleting the stack. The request consistently hangs on the deletion of the storage attachment and floating IP address.

The floating IP address is actually dissassociated and removed, but heat resource-list continues to reflect a status of "DELETE_IN_PROGRESS" for the floating IP resource.

The storage attachment continues to exist and the volume status shows that it's in-use and associated to the instance. Heat resource-list continues to reflect a status of DELETE_IN_PROGRESS for the attachment and floating IP resource indefinitely (as in days if I let it).

The only way I can get rid of the stack is by deleting the instance, which forces the stack's delete request to fail. I then submit another stack-delete request which finally deletes the stack.

We have no issues with instances' volume attachments when deleted outside the context of heat stacks via nova volume-detach.

Heat-engine log repeats the following entries over and over...

2014-12-18 11:39:50.221 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:50.222 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130
2014-12-18 11:39:51.223 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) running step /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:186
2014-12-18 11:39:51.419 33908 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130

Nova API logs show no errors regarding the attachment, but you do see request to delete:

2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Matched GET /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Match dict: {'action': u'show', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.680 1037 INFO nova.osapi_compute.wsgi.server [req-5830b253-196a-402e-b2fe-4ea7f2ec9903 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "GET /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 200 len: 368 time: 0.1860700
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Matched DELETE /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Match dict: {'action': u'delete', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.993 1023 AUDIT nova.api.openstack.compute.contrib.volumes [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] Detach volume d6911785-00b3-4145-86df-2bd48c301cde
2014-12-18 11:34:54.180 1023 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.264 1023 DEBUG urllib3.connectionpool [-] "POST /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.313 1023 INFO nova.osapi_compute.wsgi.server [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "DELETE /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 202 len: 185 time: 0.4159088

Compute logs from the node hosting the instance have the following errors:

2014-12-18 11:36:34.667 9752 ERROR nova.compute.manager [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Failed to detach volume d6911785-00b3-4145-86df-2bd48c301cde from /dev/xvdb
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Traceback (most recent call last):
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     encryption=encryption)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = meth(*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] 
2014-12-18 11:36:35.217 9752 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     pass
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = meth(*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher 
2014-12-18 11:36:35.218 9752 ERROR oslo.messaging._drivers.common [-] Returning exception POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ') to caller
2014-12-18 11:36:35.219 9752 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume\n    virt_dom.detachDeviceFlags(xml, flags)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit\n    result = proxy_call(self._autowrap, f, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call\n    rv = execute(f,*args,**kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker\n    rv = meth(*args,**kwargs)\n', '  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags\n    if ret == -1: raise libvirtError (\'virDomainDetachDeviceFlags() failed\', dom=self)\n', "libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')\n"]

Heat: Deletion Detachment of volume attachments secondary volumes fail during stack-deletedue to device in use

Running Icehouse 2014.1.2 along with the version of Heat included with this release. Control nodes are running Oracle Enterprise Linux 6.5.
Compute nodes are running Oracle Virtual Server 3.3.2 (Xen-based kernel)

I have a stack which does the following:

  1. Creates volume
  2. Creates server
  3. Attaches the volume as a secondary device
  4. Associates floating IP

This all works fine. The problem occures when deleting the stack. The request consistently hangs on the deletion of the storage attachment and floating IP address.

The floating IP address is actually dissassociated and removed, but heat resource-list continues to reflect a status of "DELETE_IN_PROGRESS" for the floating IP resource.

The storage attachment continues to exist and the volume status shows that it's in-use and associated to the instance. Heat resource-list continues to reflect a status of DELETE_IN_PROGRESS for the attachment and floating IP resource indefinitely (as in days if I let it).

The only way I can get rid of the stack is by deleting the instance, which forces the stack's delete request to fail. I then submit another stack-delete request which finally deletes the stack.

We have no issues with instances' volume attachments when deleted outside the context of heat stacks via nova volume-detach.

Heat-engine log repeats the following entries over and over...

2014-12-18 11:39:50.221 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:50.222 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130
2014-12-18 11:39:51.223 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) running step /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:186
2014-12-18 11:39:51.419 33908 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130

Nova API logs show no errors regarding the attachment, but you do see request to delete:

2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Matched GET /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Match dict: {'action': u'show', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.680 1037 INFO nova.osapi_compute.wsgi.server [req-5830b253-196a-402e-b2fe-4ea7f2ec9903 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "GET /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 200 len: 368 time: 0.1860700
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Matched DELETE /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Match dict: {'action': u'delete', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.993 1023 AUDIT nova.api.openstack.compute.contrib.volumes [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] Detach volume d6911785-00b3-4145-86df-2bd48c301cde
2014-12-18 11:34:54.180 1023 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.264 1023 DEBUG urllib3.connectionpool [-] "POST /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.313 1023 INFO nova.osapi_compute.wsgi.server [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "DELETE /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 202 len: 185 time: 0.4159088

Compute logs from the node hosting the instance have the following errors:

2014-12-18 11:36:34.667 9752 ERROR nova.compute.manager [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Failed to detach volume d6911785-00b3-4145-86df-2bd48c301cde from /dev/xvdb
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Traceback (most recent call last):
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     encryption=encryption)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = meth(*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] 
2014-12-18 11:36:35.217 9752 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     pass
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = meth(*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher 
2014-12-18 11:36:35.218 9752 ERROR oslo.messaging._drivers.common [-] Returning exception POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ') to caller
2014-12-18 11:36:35.219 9752 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume\n    virt_dom.detachDeviceFlags(xml, flags)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit\n    result = proxy_call(self._autowrap, f, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call\n    rv = execute(f,*args,**kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker\n    rv = meth(*args,**kwargs)\n', '  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags\n    if ret == -1: raise libvirtError (\'virDomainDetachDeviceFlags() failed\', dom=self)\n', "libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')\n"]

Update. Changing title of question as this apparently is not a Heat related issue. I've determined that I cannot detach secondary volumes from instances launched outside of Heat. The messages log on the compute node shows the following:

Error: Device 51744 (tap) disconnect failed - Device in use; refusing to close.

The instance console shows a similar message. This is an idle instance that I've spun up specifically for this test. I can spin up additional instances and see the same behavior.

If I delete the instance, the volume is detached and becomes available. This only occurs if I'm trying to detach a secondary volume while keeping the instance alive.

Detachment of secondary volumes fail due to device in use

Running Icehouse 2014.1.2 along with the version of Heat included with this release. Control nodes are running Oracle Enterprise Linux 6.5.
Compute nodes are running Oracle Virtual Server 3.3.2 (Xen-based kernel)

I have a stack which does the following:

  1. Creates volume
  2. Creates server
  3. Attaches the volume as a secondary device
  4. Associates floating IP

This all works fine. The problem occures when deleting the stack. The request consistently hangs on the deletion of the storage attachment and floating IP address.

The floating IP address is actually dissassociated and removed, but heat resource-list continues to reflect a status of "DELETE_IN_PROGRESS" for the floating IP resource.

The storage attachment continues to exist and the volume status shows that it's in-use and associated to the instance. Heat resource-list continues to reflect a status of DELETE_IN_PROGRESS for the attachment and floating IP resource indefinitely (as in days if I let it).

The only way I can get rid of the stack is by deleting the instance, which forces the stack's delete request to fail. I then submit another stack-delete request which finally deletes the stack.

We have no issues with instances' volume attachments when deleted outside the context of heat stacks via nova volume-detach.

Heat-engine log repeats the following entries over and over...

2014-12-18 11:39:50.221 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:50.222 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130
2014-12-18 11:39:51.223 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) running step /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:186
2014-12-18 11:39:51.419 33908 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130

Nova API logs show no errors regarding the attachment, but you do see request to delete:

2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Matched GET /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Match dict: {'action': u'show', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.680 1037 INFO nova.osapi_compute.wsgi.server [req-5830b253-196a-402e-b2fe-4ea7f2ec9903 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "GET /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 200 len: 368 time: 0.1860700
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Matched DELETE /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Match dict: {'action': u'delete', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.993 1023 AUDIT nova.api.openstack.compute.contrib.volumes [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] Detach volume d6911785-00b3-4145-86df-2bd48c301cde
2014-12-18 11:34:54.180 1023 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.264 1023 DEBUG urllib3.connectionpool [-] "POST /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.313 1023 INFO nova.osapi_compute.wsgi.server [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "DELETE /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 202 len: 185 time: 0.4159088

Compute logs from the node hosting the instance have the following errors:

2014-12-18 11:36:34.667 9752 ERROR nova.compute.manager [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Failed to detach volume d6911785-00b3-4145-86df-2bd48c301cde from /dev/xvdb
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Traceback (most recent call last):
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     encryption=encryption)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = meth(*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] 
2014-12-18 11:36:35.217 9752 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     pass
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = meth(*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher 
2014-12-18 11:36:35.218 9752 ERROR oslo.messaging._drivers.common [-] Returning exception POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ') to caller
2014-12-18 11:36:35.219 9752 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume\n    virt_dom.detachDeviceFlags(xml, flags)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit\n    result = proxy_call(self._autowrap, f, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call\n    rv = execute(f,*args,**kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker\n    rv = meth(*args,**kwargs)\n', '  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags\n    if ret == -1: raise libvirtError (\'virDomainDetachDeviceFlags() failed\', dom=self)\n', "libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')\n"]

Update. Changing title of question as this apparently is not a Heat related issue. I've determined that I cannot detach secondary volumes from instances launched outside of Heat. The messages log on the compute node shows the following:

Error: Device 51744 (tap) disconnect failed - Device in use; refusing to close.

The instance console shows a similar message. This is an idle instance that I've spun up specifically for this test. I can spin up additional instances and see the same behavior.

If I delete the instance, the volume is detached and becomes available. This only occurs if I'm trying to detach a secondary volume while keeping the instance alive.

Detachment of secondary volumes fail due to device in useHow do I detach a volume from a running instance

  • Running Icehouse 2014.1.2 along with the version of Heat included with this release. 2014.1.2

  • Control nodes are running Oracle Enterprise Linux 6.5.
    6.5

  • Compute nodes are running Oracle Virtual Server 3.3.2 (Xen-based kernel)

I'm trying to detach secondary volumes from instances that need to remain up. When I have attempt this using nova volume-detach, I receive errors on the compute node reporting that the device is in use and cannot be disconnected.

Message in /var/log/messages on compute node:

Error: Device 51744 (tap) disconnect failed - Device in use; refusing to close.

The instance console shows a stack which does similar message. This is an idle instance that I've spun up specifically for this test. I can spin up additional instances and see the following:same behavior.

  1. Creates volume
  2. Creates server
  3. Attaches

    If I delete the instance, the volume as is detached and becomes available. This only occurs if I'm trying to detach a secondary device

  4. Associates floating IP
volume while keeping the instance alive.

This all works fine. The problem occures when deleting the stack. The request consistently hangs I've seen similar issues reported for EBS on the deletion of the storage attachment and floating IP address.

The floating IP address is actually dissassociated and removed, but heat resource-list continues to reflect a status of "DELETE_IN_PROGRESS" for the floating IP resource.

The storage attachment continues to exist and AWS as well as RackSpace. They recommend unmounting the volume status shows that it's in-use and associated to the instance. Heat resource-list continues to reflect a status of DELETE_IN_PROGRESS for the attachment and floating IP resource indefinitely (as in days if I let it).

The only way I can get rid of the stack is by deleting from within the instance, which forces then attempt a volume detach. Makes sense, however when I try this Nova now complains that the stack's delete request device is missing. So, I ask... If you want to fail. I then submit another stack-delete request which finally deletes the stack.detach a volume from an instance that needs to remain running, how are you supposed to go about this?

Heat-engine log repeats the following entries over and over...

2014-12-18 11:39:50.221 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:50.222 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130
2014-12-18 11:39:51.223 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) running step /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:186
2014-12-18 11:39:51.419 33908 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.resources.volume [-] Removing attachment d6911785-00b3-4145-86df-2bd48c301cde from Instance cbefdb38-3022-41ce-a7ef-3aae4a5784ae - volume still in use __call__ /usr/lib/python2.6/site-packages/heat/engine/resources/volume.py:284
2014-12-18 11:39:51.422 33908 DEBUG heat.engine.scheduler [-] Task VolumeDetachTask(d6911785-00b3-4145-86df-2bd48c301cde -/> cbefdb38-3022-41ce-a7ef-3aae4a5784ae) sleeping _sleep /usr/lib/python2.6/site-packages/heat/engine/scheduler.py:130

Nova API logs show no errors regarding the attachment, but you do see request to delete:

2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Matched GET /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.602 1037 DEBUG routes.middleware [-] Match dict: {'action': u'show', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.680 1037 INFO nova.osapi_compute.wsgi.server [req-5830b253-196a-402e-b2fe-4ea7f2ec9903 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "GET /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 200 len: 368 time: 0.1860700
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Matched DELETE /eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100
2014-12-18 11:34:53.992 1023 DEBUG routes.middleware [-] Match dict: {'action': u'delete', 'server_id': u'cbefdb38-3022-41ce-a7ef-3aae4a5784ae', 'project_id': u'eafc492e2912424faa4a1903977c2b92', 'controller': <nova.api.openstack.wsgi.Resource object at 0x4531d90>, 'id': u'd6911785-00b3-4145-86df-2bd48c301cde'} __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:103
2014-12-18 11:34:53.993 1023 AUDIT nova.api.openstack.compute.contrib.volumes [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] Detach volume d6911785-00b3-4145-86df-2bd48c301cde
2014-12-18 11:34:54.180 1023 DEBUG urllib3.connectionpool [-] "GET /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" 200 823 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.264 1023 DEBUG urllib3.connectionpool [-] "POST /v1/eafc492e2912424faa4a1903977c2b92/volumes/d6911785-00b3-4145-86df-2bd48c301cde/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
2014-12-18 11:34:54.313 1023 INFO nova.osapi_compute.wsgi.server [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] 10.241.70.70 "DELETE /v2/eafc492e2912424faa4a1903977c2b92/servers/cbefdb38-3022-41ce-a7ef-3aae4a5784ae/os-volume_attachments/d6911785-00b3-4145-86df-2bd48c301cde HTTP/1.1" status: 202 len: 185 time: 0.4159088

Compute logs from the node hosting the instance have the following errors:

2014-12-18 11:36:34.667 9752 ERROR nova.compute.manager [req-98525048-1df6-4a22-9ebb-a54130f96761 f778784adfc2458faa17e77b6cf0617c eafc492e2912424faa4a1903977c2b92] [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Failed to detach volume d6911785-00b3-4145-86df-2bd48c301cde from /dev/xvdb
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] Traceback (most recent call last):
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     encryption=encryption)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     rv = meth(*args,**kwargs)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae]     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:34.667 9752 TRACE nova.compute.manager [instance: cbefdb38-3022-41ce-a7ef-3aae4a5784ae] 
2014-12-18 11:36:35.217 9752 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     pass
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     virt_dom.detachDeviceFlags(xml, flags)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     result = proxy_call(self._autowrap, f, *args, **kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = execute(f,*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     rv = meth(*args,**kwargs)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher     if ret == -1: raise libvirtError ('virDomainDetachDeviceFlags() failed', dom=self)
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')
2014-12-18 11:36:35.217 9752 TRACE oslo.messaging.rpc.dispatcher 
2014-12-18 11:36:35.218 9752 ERROR oslo.messaging._drivers.common [-] Returning exception POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ') to caller
2014-12-18 11:36:35.219 9752 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1418, in detach_volume\n    virt_dom.detachDeviceFlags(xml, flags)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 179, in doit\n    result = proxy_call(self._autowrap, f, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 139, in proxy_call\n    rv = execute(f,*args,**kwargs)\n', '  File "/usr/lib/python2.6/site-packages/eventlet/tpool.py", line 77, in tworker\n    rv = meth(*args,**kwargs)\n', '  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 823, in detachDeviceFlags\n    if ret == -1: raise libvirtError (\'virDomainDetachDeviceFlags() failed\', dom=self)\n', "libvirtError: POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 51728 (vbd) could not be disconnected. ')\n"]

Update. Changing title of question as this apparently is not a Heat related issue. I've determined that I cannot detach secondary volumes from instances launched outside of Heat. The messages log on the compute node shows the following:

Error: Device 51744 (tap) disconnect failed - Device in use; refusing to close.

The instance console shows a similar message. This is an idle instance that I've spun up specifically for this test. I can spin up additional instances and see the same behavior.

If I delete the instance, the volume is detached and becomes available. This only occurs if I'm trying to detach a secondary volume while keeping the instance alive.