Mirantis OpenStack

Invalid volume while boot_server_from_volume_and_delete Nova test case

Bug #1602682 reported by Pavel on 2016-07-13

This bug report is a duplicate of: Bug #1550192: When deleting a lot of volumes at once, some of the volumes stay in status “Deleting”. Edit Remove

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Mirantis OpenStack	Confirmed	Medium	MOS Cinder	Mirantis OpenStack 9.1

Bug Description

Detailed bug description:
Problem discovered on MOS 9.0 ISO #495 RC2

Problem was discovered during execution of NovaServers.boot_server_from_volume_and_delete.

Rally Traceback:
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/runner.py", line 64, in _run_scenario_once
    getattr(scenario_inst, method_name)(**kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/nova/servers.py", line 159, in boot_server_from_volume_and_delete
    **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/atomic.py", line 84, in func_atomic_actions
    f = func(self, *args, **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/plugins/openstack/scenarios/nova/utils.py", line 147, in _boot_server
    check_interval=CONF.benchmark.nova_server_boot_poll_interval
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/common/logging.py", line 236, in wrapper
    return f(*args, **kwargs)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/utils.py", line 147, in wait_for
    check_interval=check_interval)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/utils.py", line 211, in wait_for_status
    resource = update_resource(resource)
  File "/opt/stack/.venv/lib/python2.7/site-packages/rally/task/utils.py", line 90, in _get_from_manager
    fault=getattr(res, "fault", "n/a"))
GetResourceErrorStatus: Resource <Server: s_rally_701e4e8c_Nj9btEed> has ERROR status.
Fault: {u'message': u'Build of instance 9d4316e1-6390-4ace-90ab-95e1ac946577 aborted: Block Device Mapping is Invalid.', u'code': 500, u'created': u'2016-07-05T11:10:58Z'}

Nova compute log:

2016-07-05T11:10:52.155041+00:00 debug: 2016-07-05 11:10:52.143 30599 DEBUG keystoneauth.session [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] RESP: [504] Connection: close Content-Type: text/html Cache-Control: no-cache
RESP BODY: <html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

_http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:277
2016-07-05T11:10:52.155674+00:00 warning: 2016-07-05 11:10:52.144 30599 WARNING nova.compute.manager [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] [instance: 9f765e12-a8d7-46e4-89cb-d44130010ce0] Ignoring unknown cinder exception for volume 76ff90c2-3c9d-4b2b-b07f-0cabf6dca702: Gateway Time-out (HTTP 504)
2016-07-05T11:10:52.156071+00:00 info: 2016-07-05 11:10:52.145 30599 INFO nova.compute.manager [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] [instance: 9f765e12-a8d7-46e4-89cb-d44130010ce0] Took 60.97 seconds to detach 1 volumes for instance.
2016-07-05T11:10:52.157869+00:00 debug: 2016-07-05 11:10:52.146 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: 72df2446f5a54e0784c6e9d8434b300c size: 3522 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.177549+00:00 debug: 2016-07-05 11:10:52.166 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 72df2446f5a54e0784c6e9d8434b300c size: 174 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.179684+00:00 debug: 2016-07-05 11:10:52.167 30599 DEBUG nova.compute.manager [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] [instance: 9f765e12-a8d7-46e4-89cb-d44130010ce0] terminating bdm BlockDeviceMapping(boot_index=0,connection_info='{"driver_volume_type": "rbd", "connector": {"initiator": "iqn.1993-08.org.debian:01:3ce3668e45c2", "ip": "192.168.0.11", "platform": "x86_64", "host": "node-20.domain.tld", "os_type": "linux2", "multipath": false}, "serial": "76ff90c2-3c9d-4b2b-b07f-0cabf6dca702", "data": {"secret_type": "ceph", "name": "volumes/volume-76ff90c2-3c9d-4b2b-b07f-0cabf6dca702", "encrypted": false, "secret_uuid": "***", "qos_specs": null, "hosts": ["192.168.1.5", "192.168.1.6", "192.168.1.8"], "volume_id": "76ff90c2-3c9d-4b2b-b07f-0cabf6dca702", "auth_enabled": true, "access_mode": "rw", "auth_username": "volumes", "ports": ["6789", "6789", "6789"]}}',created_at=2016-07-05T11:09:25Z,delete_on_termination=True,deleted=False,deleted_at=None,destination_type='volume',device_name='/dev/vda',device_type='disk',disk_bus='virtio',guest_format=None,id=28909,image_id=None,instance=<?>,instance_uuid=9f765e12-a8d7-46e4-89cb-d44130010ce0,no_device=False,snapshot_id=None,source_type='volume',updated_at=2016-07-05T11:09:32Z,volume_id='76ff90c2-3c9d-4b2b-b07f-0cabf6dca702',volume_size=10) _cleanup_volumes /usr/lib/python2.7/dist-packages/nova/compute/manager.py:2398
2016-07-05T11:10:52.180585+00:00 debug: 2016-07-05 11:10:52.169 30599 DEBUG keystoneauth.session [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] REQ: curl -g -i -X DELETE http://192.168.0.2:8776/v2/5bf9c324988b4e54957d4e4f7992c7ac/volumes/76ff90c2-3c9d-4b2b-b07f-0cabf6dca702 -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}20690315b252a660793d818d07e670b5ab84e30f" _http_log_request /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:248
2016-07-05T11:10:52.235577+00:00 debug: 2016-07-05 11:10:52.224 30599 DEBUG keystoneauth.session [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] RESP: [400] Content-Length: 224 X-Compute-Request-Id: req-7401f38f-75ad-4e76-84ec-d4dafa950d8b Vary: OpenStack-API-Version Openstack-Api-Version: 2.0 Connection: close Date: Tue, 05 Jul 2016 11:10:52 GMT Content-Type: application/json; charset=UTF-8 X-Openstack-Request-Id: req-7401f38f-75ad-4e76-84ec-d4dafa950d8b
RESP BODY: {"badRequest": {"message": "Invalid volume: Volume status must be available or error or error_restoring or error_extending and must not be migrating, attached, belong to a consistency group or have snapshots.", "code": 400}}
_http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:277
2016-07-05T11:10:52.236022+00:00 warning: 2016-07-05 11:10:52.224 30599 WARNING nova.compute.manager [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] Failed to delete volume: 76ff90c2-3c9d-4b2b-b07f-0cabf6dca702 due to Invalid input received: Invalid volume: Volume status must be available or error or error_restoring or error_extending and must not be migrating, attached, belong to a consistency group or have snapshots. (HTTP 400) (Request-ID: req-7401f38f-75ad-4e76-84ec-d4dafa950d8b)
2016-07-05T11:10:52.238791+00:00 debug: 2016-07-05 11:10:52.227 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: 2244980bf1844c1b9a2bedd737bd7878 size: 6160 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.331051+00:00 debug: 2016-07-05 11:10:52.320 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 2244980bf1844c1b9a2bedd737bd7878 size: 1318 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.334246+00:00 debug: 2016-07-05 11:10:52.323 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: e7a3b2d250a8418b99911985acb762e9 size: 4958 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.415188+00:00 debug: 2016-07-05 11:10:52.404 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: e7a3b2d250a8418b99911985acb762e9 size: 1373 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.417489+00:00 debug: 2016-07-05 11:10:52.406 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: 4824e25b03d2435a90ee76218e354424 size: 2414 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.442937+00:00 debug: 2016-07-05 11:10:52.431 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 4824e25b03d2435a90ee76218e354424 size: 196 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.444221+00:00 debug: 2016-07-05 11:10:52.433 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: d26553f9919a40f084098d3e1348ffc7 size: 3477 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.456588+00:00 debug: 2016-07-05 11:10:52.445 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: d26553f9919a40f084098d3e1348ffc7 size: 174 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.458354+00:00 debug: 2016-07-05 11:10:52.447 30599 DEBUG oslo_concurrency.lockutils [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-07-05T11:10:52.464599+00:00 debug: 2016-07-05 11:10:52.453 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: 6fed442647804b04988f874c4bfb079c size: 5456 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.490899+00:00 debug: 2016-07-05 11:10:52.479 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 6fed442647804b04988f874c4bfb079c size: 1355 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:52.492221+00:00 debug: 2016-07-05 11:10:52.481 30599 DEBUG oslo_concurrency.lockutils [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.034s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-07-05T11:10:52.493271+00:00 debug: 2016-07-05 11:10:52.482 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CAST unique_id: 5a7fe6edc5994a59bfc93cd378264df0 size: 1971 exchange: nova topic: consoleauth _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.497021+00:00 debug: 2016-07-05 11:10:52.485 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CAST unique_id: 36f212e4168c4abcb6a6407375a7bf3a size: 2008 FANOUT topic: scheduler _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:485
2016-07-05T11:10:52.499329+00:00 debug: 2016-07-05 11:10:52.488 30599 DEBUG oslo_concurrency.lockutils [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] Lock "9f765e12-a8d7-46e4-89cb-d44130010ce0" released by "nova.compute.manager.do_terminate_instance" :: held 63.991s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-07-05T11:10:52.500045+00:00 debug: 2016-07-05 11:10:52.489 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-3d3975f8-77a6-4e5b-83b3-bf8300bed827 16f695d87a64403981fc15977022a9c7 5bf9c324988b4e54957d4e4f7992c7ac - - -] CALL msg_id: 9e7d9789d48848ba95d91e8a286ec3b4 size: 2291 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:52.515068+00:00 debug: 2016-07-05 11:10:52.504 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 9e7d9789d48848ba95d91e8a286ec3b4 size: 146 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:55.755930+00:00 debug: 2016-07-05 11:10:55.744 30599 DEBUG keystoneauth.session [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] RESP: [504] Connection: close Content-Type: text/html Cache-Control: no-cache
RESP BODY: <html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

_http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:277
2016-07-05T11:10:55.756406+00:00 err: 2016-07-05 11:10:55.745 30599 ERROR nova.volume.cinder [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] Initialize connection failed for volume d8101d37-673a-4e23-b352-7c178dacf26b on host node-20.domain.tld. Error: Gateway Time-out (HTTP 504) Code: 504. Attempting to terminate connection.
2016-07-05T11:10:55.757190+00:00 debug: 2016-07-05 11:10:55.746 30599 DEBUG keystoneauth.session [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] REQ: curl -g -i -X POST http://192.168.0.2:8776/v2/25399a780f43413d9e124f55521f127d/volumes/d8101d37-673a-4e23-b352-7c178dacf26b/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}b44db00b1017646fd832f0d45f5df18d0b5fe921" -d '{"os-terminate_connection": {"connector": {"initiator": "iqn.1993-08.org.debian:01:3ce3668e45c2", "ip": "192.168.0.11", "platform": "x86_64", "host": "node-20.domain.tld", "os_type": "linux2", "multipath": false}}}' _http_log_request /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:248
2016-07-05T11:10:56.001715+00:00 debug: 2016-07-05 11:10:55.990 30599 DEBUG keystoneauth.session [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] RESP: [202] Date: Tue, 05 Jul 2016 11:10:55 GMT Connection: close Content-Type: text/html; charset=UTF-8 Content-Length: 0 X-Openstack-Request-Id: req-63c1b280-dece-4bce-8acd-ea68596313aa _http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:277
2016-07-05T11:10:56.003020+00:00 debug: 2016-07-05 11:10:55.991 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] CALL msg_id: 4c4a1cf1ae4d4b1a8a12d19135ba34a3 size: 2726 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:56.023573+00:00 debug: 2016-07-05 11:10:56.012 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 4c4a1cf1ae4d4b1a8a12d19135ba34a3 size: 212 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:56.026122+00:00 err: 2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Instance failed block device setup
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Traceback (most recent call last):
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1754, in _prep_block_device
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] wait_func=self._await_block_device_map_created)
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 518, in attach_block_devices
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] map(_log_and_attach, block_device_mapping)
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 516, in _log_and_attach
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] bdm.attach(*attach_args, **attach_kwargs)
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 54, in wrapped
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] ret_val = method(obj, context, *args, **kwargs)
2016-07-05 11:10:56.013 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py"
2016-07-05T11:10:56.026792+00:00 debug: 2016-07-05 11:10:56.015 30599 DEBUG nova.compute.claims [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Aborting claim: [Claim: 64 MB memory, 0 GB disk] abort /usr/lib/python2.7/dist-packages/nova/compute/claims.py:121
2016-07-05T11:10:56.027036+00:00 debug: 2016-07-05 11:10:56.016 30599 DEBUG oslo_concurrency.lockutils [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.abort_instance_claim" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-07-05T11:10:56.030867+00:00 debug: 2016-07-05 11:10:56.019 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] CALL msg_id: bd250c91664a4636b1af94205b1ad93d size: 5239 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:56.088873+00:00 debug: 2016-07-05 11:10:56.077 30599 DEBUG oslo_service.periodic_task [req-c79f3fe0-380f-4134-af8b-80aeecd3b934 - - - - -] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/dist-packages/oslo_service/periodic_task.py:215
2016-07-05T11:10:56.089729+00:00 debug: 2016-07-05 11:10:56.078 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-c79f3fe0-380f-4134-af8b-80aeecd3b934 - - - - -] CALL msg_id: 8d753c9305d34299af53990457482f0b size: 1178 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:56.108386+00:00 debug: 2016-07-05 11:10:56.097 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 8d753c9305d34299af53990457482f0b size: 691 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:56.158546+00:00 debug: 2016-07-05 11:10:56.147 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: bd250c91664a4636b1af94205b1ad93d size: 2920 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:56.164865+00:00 debug: 2016-07-05 11:10:56.153 30599 DEBUG oslo_messaging._drivers.amqpdriver [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] CALL msg_id: b181a1bcbc8c447eabd39ed37619a97d size: 5456 exchange: nova topic: conductor _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:496
2016-07-05T11:10:56.208605+00:00 debug: 2016-07-05 11:10:56.197 30599 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: b181a1bcbc8c447eabd39ed37619a97d size: 1355 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:339
2016-07-05T11:10:56.209995+00:00 debug: 2016-07-05 11:10:56.198 30599 DEBUG oslo_concurrency.lockutils [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.abort_instance_claim" :: held 0.183s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-07-05T11:10:56.210262+00:00 debug: 2016-07-05 11:10:56.199 30599 DEBUG nova.compute.manager [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Build of instance 9d4316e1-6390-4ace-90ab-95e1ac946577 aborted: Block Device Mapping is Invalid. _build_and_run_instance /usr/lib/python2.7/dist-packages/nova/compute/manager.py:2081
2016-07-05T11:10:56.211011+00:00 debug: 2016-07-05 11:10:56.199 30599 DEBUG nova.compute.utils [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Build of instance 9d4316e1-6390-4ace-90ab-95e1ac946577 aborted: Block Device Mapping is Invalid. notify_about_instance_usage /usr/lib/python2.7/dist-packages/nova/compute/utils.py:284
2016-07-05T11:10:56.212616+00:00 err: 2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Build of instance 9d4316e1-6390-4ace-90ab-95e1ac946577 aborted: Block Device Mapping is Invalid.
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Traceback (most recent call last):
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1926, in _do_build_and_run_instance
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] filter_properties)
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 2083, in _build_and_run_instance
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] 'create.error', fault=e)
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] self.force_reraise()
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] six.reraise(self.type_, self.value, self.tb)
2016-07-05 11:10:56.200 30599 ERROR nova.compute.manager [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line
2016-07-05T11:10:56.213057+00:00 debug: 2016-07-05 11:10:56.202 30599 DEBUG nova.compute.manager [req-abf1d7f1-2ae3-473f-bdb8-b812d36f41c8 22b291892e6646cabff0dd7a45ddcc8a 25399a780f43413d9e124f55521f127d - - -] [instance: 9d4316e1-6390-4ace-90ab-95e1ac946577] Deallocating network for instance _deallocate_network /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1824

Steps to reproduce:
Start rally test NovaServers.boot_server_from_volume_and_delete.
Expected results:
Test passed.
Actual result:
Test failed.
Reproducibility:
Iterations: 41, Failures: 2
Workaround:
n/a
Impact:
unknown
Description of the environment:
* 10 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)
   - 7 computes
* Details:
   - OS on controllers: Mitaka on Ubuntu 14.04
   - OS on computes: RHEL
   - Compute: KVM
   - Neutron with VLAN segmentation

Additional information:
Diagnostic snapshot download link: http://mos-scale-share.mirantis.com/fuel-snapshot-2016-07-11_08-57-28.tar.gz

Tags:

Revision history for this message

Pavel (pshvetsov) wrote on 2016-07-13:

nova-compute.log.6.gz Edit (6.4 MiB, application/octet-stream)

Sergey Kolekonov (skolekonov) on 2016-07-15

Changed in mos:
milestone:	9.0 → 9.1
assignee:	nobody → MOS Nova (mos-nova)
importance:	Undecided → Medium
status:	New → Confirmed
tags:	added: area-nova