Detailed bug description:
Problem discovered on MOS 9.0 ISO #310
Problem was discovered during execution of CinderVolumes.create_and_attach_volume: one volume hangs in IN-USE state on detaching from VM.
Here are parts from nova-compute-log and rally below. It shows us how volume is raising an error during detaching.
Attempting claim:
2016-05-20 13:33:36.083 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Attempting claim: memory 64 MB, disk 0 GB, vcpus 1 CPU
2016-05-20 13:33:36.084 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Total memory: 31979 MB, used: 6656.00 MB
2016-05-20 13:33:36.085 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] memory limit: 31979.00 MB, free: 25323.00 MB
2016-05-20 13:33:36.085 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Total disk: 2791 GB, used: 60.00 GB
2016-05-20 13:33:36.086 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] disk limit: 2791.00 GB, free: 2731.00 GB
2016-05-20 13:33:36.086 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Total vcpu: 12 VCPU, used: 3.00 VCPU
2016-05-20 13:33:36.086 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] vcpu limit: 96.00 VCPU, free: 93.00 VCPU
2016-05-20 13:33:36.102 28838 INFO nova.compute.claims [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Claim successful
Creating image, spawned successfully:
2016-05-20 13:33:39.103 28838 INFO nova.virt.libvirt.driver [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Creating image
2016-05-20 13:34:15.033 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Auditing locally available compute resources for node node-29.domain.tld
2016-05-20 13:34:16.953 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Total usable vcpus: 12, total allocated vcpus: 4
2016-05-20 13:34:16.954 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Final resource view: name=node-29.domain.tld phys_ram=31979MB used_ram=6720MB phys_disk=2791GB used_disk=60GB total_vcpus=12 used_vcpus=4 pci_stats=[]
2016-05-20 13:34:18.547 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Compute_service record updated for node-29.domain.tld:node-29.domain.tld
2016-05-20 13:35:04.322 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Auditing locally available compute resources for node node-29.domain.tld
2016-05-20 13:35:04.683 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Total usable vcpus: 12, total allocated vcpus: 4
2016-05-20 13:35:04.684 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Final resource view: name=node-29.domain.tld phys_ram=31979MB used_ram=6720MB phys_disk=2791GB used_disk=60GB total_vcpus=12 used_vcpus=4 pci_stats=[]
2016-05-20 13:35:04.728 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Compute_service record updated for node-29.domain.tld:node-29.domain.tld
2016-05-20 13:35:33.562 28838 INFO nova.compute.manager [req-b571b420-6dc3-4aa8-9de0-5533e04b7451 - - - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] VM Resumed (Lifecycle Event)
2016-05-20 13:35:33.569 28838 INFO nova.virt.libvirt.driver [-] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Instance spawned successfully.
Еime spent on a building:
2016-05-20 13:35:33.570 28838 INFO nova.compute.manager [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Took 114.47 seconds to spawn the instance on the hypervisor.
2016-05-20 13:35:33.681 28838 INFO nova.compute.manager [req-8d3945e5-f004-4670-a4be-50538f67a934 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Took 117.60 seconds to build instance.
Starting VM:
2016-05-20 13:35:33.763 28838 INFO nova.compute.manager [req-b571b420-6dc3-4aa8-9de0-5533e04b7451 - - - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] VM Started (Lifecycle Event)
Attaching volume:
2016-05-20 13:36:04.229 28838 INFO nova.compute.manager [req-340255d5-1d83-4ebb-acdc-d09718be32db 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Attaching volume 85c29a5c-a719-43d1-9a62-57fa5037bb01 to /dev/vdb
2016-05-20 13:36:06.317 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Auditing locally available compute resources for node node-29.domain.tld
2016-05-20 13:36:06.715 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Total usable vcpus: 12, total allocated vcpus: 4
2016-05-20 13:36:06.716 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Final resource view: name=node-29.domain.tld phys_ram=31979MB used_ram=6720MB phys_disk=2791GB used_disk=60GB total_vcpus=12 used_vcpus=4 pci_stats=[]
2016-05-20 13:36:06.749 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Compute_service record updated for node-29.domain.tld:node-29.domain.tld
Trying to detach volume:
2016-05-20 13:36:26.174 28838 INFO nova.compute.manager [req-8010f3b6-0072-4cdb-a198-7c95f1044681 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Detach volume 85c29a5c-a719-43d1-9a62-57fa5037bb01 from mountpoint /dev/vdb
2016-05-20 13:37:06.319 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Auditing locally available compute resources for node node-29.domain.tld
2016-05-20 13:37:06.669 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Total usable vcpus: 12, total allocated vcpus: 4
2016-05-20 13:37:06.670 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Final resource view: name=node-29.domain.tld phys_ram=31979MB used_ram=6720MB phys_disk=2791GB used_disk=60GB total_vcpus=12 used_vcpus=4 pci_stats=[]
2016-05-20 13:37:06.705 28838 INFO nova.compute.resource_tracker [req-f6c6a127-b56f-49ad-ad42-136c1298639f - - - - -] Compute_service record updated for node-29.domain.tld:node-29.domain.tld
And catching the error:
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall [-] Dynamic interval looping call 'oslo_service.loopingcall._func' failed
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall Traceback (most recent call last):
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall result = func(*self.args, **self.kw)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 377, in _func
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall return self._sleep_time
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall self.force_reraise()
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall six.reraise(self.type_, self.value, self.tb)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 356, in _func
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall result = f(*args, **kwargs)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/guest.py", line 342, in _do_wait_and_retry_detach
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall reason=reason)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall DeviceDetachFailed: Device detach failed for vdb: Unable to detach from guest transient domain.)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.loopingcall
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [req-8010f3b6-0072-4cdb-a198-7c95f1044681 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Failed to detach volume 85c29a5c-a719-43d1-9a62-57fa5037bb01 from /dev/vdb
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Traceback (most recent call last):
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 4775, in _driver_detach_volume
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] encryption=encryption)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1469, in detach_volume
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] wait_for_detach()
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 385, in func
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] return evt.wait()
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] return hubs.get_hub().switch()
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] return self.greenlet.switch()
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] result = func(*self.args, **self.kw)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 377, in _func
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] return self._sleep_time
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] self.force_reraise()
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] six.reraise(self.type_, self.value, self.tb)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 356, in _func
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] result = f(*args, **kwargs)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/guest.py", line 342, in _do_wait_and_retry_detach
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] reason=reason)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] DeviceDetachFailed: Device detach failed for vdb: Unable to detach from guest transient domain.)
2016-05-20 13:38:07.215 28838 ERROR nova.compute.manager [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327]
Rally test results of this part of work.
The penult answer:
RESP BODY: {"volume": {"status": "in-use", "user_id": "51adf8b5919b437c87c375f25c6b31f8", "attachments": [{"server_id": "92e8cec9-8e8f-4089-ac44-5b661c3fc327", "attachment_id": "498a41b6-0b8d-466d-bead-35a67391501c", "attached_at": "2016-05-20T11:36:25.000000", "host_name": null, "volume_id": "85c29a5c-a719-43d1-9a62-57fa5037bb01", "device": "/dev/vdb", "id": "85c29a5c-a719-43d1-9a62-57fa5037bb01"}], "links": [{"href": "http://172.16.45.102:8776/v2/03b73860b54545eaa01b6c9af607597f/volumes/85c29a5c-a719-43d1-9a62-57fa5037bb01", "rel": "self"}, {"href": "http://172.16.45.102:8776/03b73860b54545eaa01b6c9af607597f/volumes/85c29a5c-a719-43d1-9a62-57fa5037bb01", "rel": "bookmark"}], "availability_zone": "nova", "bootable": "false", "encrypted": false, "created_at": "2016-05-20T11:35:35.000000", "description": null, "os-vol-tenant-attr:tenant_id": "03b73860b54545eaa01b6c9af607597f", "updated_at": "2016-05-20T11:38:07.000000", "volume_type": null, "name": "s_rally_d404c8e8_SJMMPWIQ", "replication_status": "disabled", "consistencygroup_id": null, "source_volid": null, "snapshot_id": null, "multiattach": false, "metadata": {"readonly": "False", "attached_mode": "rw"}, "id": "85c29a5c-a719-43d1-9a62-57fa5037bb01", "size": 10}}
And next answer:
REQ: curl -i http://172.16.45.102:8776/v2/93a273ff545c455db6dacb03b13ec042/volumes/d03c6503-2b12-4228-b24d-1e3eb3bf0bb2 -X GET-H 'X-Auth-Project-Id: c_rally_d404c8e8_0DRk15vc'-H 'User-Agent: python-cinderclient'-H 'Accept: application/json'-H 'X-Auth-Token: {SHA1}130f54b6d2f3ad96a145e5756ed7ed75e8081e17'
http_log_req /opt/stack/.venv/lib/python2.7/site-packages/cinderclient/client.py:236
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner [-] Rally tired waiting for Volume s_rally_d404c8e8_SJMMPWIQ:85c29a5c-a719-43d1-9a62-57fa5037bb01 to become ('AVAILABLE') current status IN-USE
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner Traceback (most recent call last):
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/runner.py", line 66, in _run_scenario_once
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner deprecated_output = getattr(scenario_inst, method_name)(**kwargs)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/common/logging.py", line 266, in wrapper
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner result = f(*args, **kwargs)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/cinder/volumes.py", line 316, in create_and_attach_volume
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner self._detach_volume(server, volume)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/atomic.py", line 84, in func_atomic_actions
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner f = func(self, *args, **kwargs)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/nova/utils.py", line 699, in _detach_volume
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner check_interval=CONF.benchmark.nova_detach_volume_poll_interval
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/common/logging.py", line 236, in wrapper
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner return f(*args, **kwargs)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/utils.py", line 147, in wait_for
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner check_interval=check_interval)
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/utils.py", line 246, in wait_for_status
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner resource_status=get_status(resource))
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner TimeoutException: Rally tired waiting for Volume s_rally_d404c8e8_SJMMPWIQ:85c29a5c-a719-43d1-9a62-57fa5037bb01 to become ('AVAILABLE') current status IN-USE
2016-05-20 11:39:46.433 21370 ERROR rally.task.runner
2016-05-20 11:39:46.438 21370 INFO rally.task.runner [-] Task d404c8e8-bd17-45de-9997-f0255c5a70c5 | ITER: 1 END: Error TimeoutException: Rally tired waiting for Volume s_rally_d404c8e8_SJMMPWIQ:85c29a5c-a719-43d1-9a62-57fa5037bb01 to become ('AVAILABLE') current status IN-USE
Back to nova-compute log.
Terminating instance
2016-05-20 13:52:57.383 28838 INFO nova.compute.manager [req-ecc75281-c974-4c8c-a4ca-d9a3a4f56936 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Terminating instance
2016-05-20 13:53:07.598 28838 INFO nova.virt.libvirt.driver [-] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Instance destroyed successfully.
2016-05-20 13:53:07.598 28838 INFO nova.virt.libvirt.driver [-] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Instance destroyed successfully.
2016-05-20 13:53:27.259 28838 INFO nova.compute.manager [-] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] VM Stopped (Lifecycle Event)
Deleting instance:
2016-05-20 13:54:21.226 28838 INFO nova.virt.libvirt.driver [req-ecc75281-c974-4c8c-a4ca-d9a3a4f56936 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Deleting instance files /var/lib/nova/instances/92e8cec9-8e8f-4089-ac44-5b661c3fc327_del
2016-05-20 13:54:21.228 28838 INFO nova.virt.libvirt.driver [req-ecc75281-c974-4c8c-a4ca-d9a3a4f56936 51adf8b5919b437c87c375f25c6b31f8 03b73860b54545eaa01b6c9af607597f - - -] [instance: 92e8cec9-8e8f-4089-ac44-5b661c3fc327] Deletion of /var/lib/nova/instances/92e8cec9-8e8f-4089-ac44-5b661c3fc327_del complete
Steps to reproduce:
Start rally test CinderVolumes.create_and_attach_volume during the load.
Expected results:
Test passed. The was volume atteched and detached successfully.
Actual result:
Test failed. The volume was attached and wasnt detached.
Reproducibility:
Iterations: 6, Failures: 6
Workaround:
n/a
Impact:
unknown
Description of the environment:
* 50 baremetal nodes:
- CPU: 12 x 2.10 GHz
- Disks: 2 drives (SSD - 80 GB, HDD - 931.5 GB), 1006.0 GB total
- Memory: 2 x 16.0 GB, 32.0 GB total
- NUMA topology: 1 NUMA node
* Node roles:
- 3 controllers (1 was is offline because of disk problems)
- 44 computes
- 3 Ceph OSD
* Details:
- OS on controllers: Mitaka on Ubuntu 14.04
- OS on computes: RHEL
- Compute: KVM
- Neutron with VLAN segmentation
- Ceph RBD for volumes (Cinder)
- Ceph RadosGW for objects (Swift API)
- Ceph RBD for ephemeral volumes (Nova)
- Ceph RBD for images (Glance)
Additional information:
Nova compute logs download link: http://mos-scale-share.mirantis.com/pshvetsov/nova-compute.log-20160521
Rally logs download link: http://mos-scale-share.mirantis.com/pshvetsov/cinder_create-and-attach-volume-rally-stdout.log
All computes logs download link: http://mos-scale-share.mirantis.com/small_logs.tar.bz2
Diagnostic snapshot (controllers + Ceph only) download link: http://mos-scale-share.mirantis.com/fuel-snapshot-2016-05-25_12-15-36.tar.xz
According to nova-compute logs: loopingcall Traceback (most recent call last): loopingcall File "/usr/lib/ python2. 7/site- packages/ oslo_service/ loopingcall. py", line 136, in _run_loop loopingcall result = func(*self.args, **self.kw) loopingcall File "/usr/lib/ python2. 7/site- packages/ oslo_service/ loopingcall. py", line 377, in _func loopingcall return self._sleep_time loopingcall File "/usr/lib/ python2. 7/site- packages/ oslo_utils/ excutils. py", line 220, in __exit__ loopingcall self.force_ reraise( ) loopingcall File "/usr/lib/ python2. 7/site- packages/ oslo_utils/ excutils. py", line 196, in force_reraise loopingcall six.reraise( self.type_ , self.value, self.tb) loopingcall File "/usr/lib/ python2. 7/site- packages/ oslo_service/ loopingcall. py", line 356, in _func loopingcall result = f(*args, **kwargs) loopingcall File "/usr/lib/ python2. 7/site- packages/ nova/virt/ libvirt/ guest.py" , line 342, in _do_wait_ and_retry_ detach loopingcall reason=reason) loopingcall DeviceDetachFailed: Device detach failed for vdb: Unable to detach from guest transient domain.)
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
2016-05-20 13:38:07.213 28838 ERROR oslo.service.
It looks like a nova issue