Debug info so far: ironic node-list | grep 0c282e24-1a4a-4c29-8a91-db5d05fd2063 | b3396d19-2cad-4250-bede-67f478d54926 | 0c282e24-1a4a-4c29-8a91-db5d05fd2063 | power on | wait call-back | False | | cc695acc-5674-44b6-b141-dc41de9b8778 | 0c282e24-1a4a-4c29-8a91-db5d05fd2063 | power off | deploy failed | False | Nova-compute.log snip-its: 2014-06-04 23:07:32.712 6862 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 9.205668 sec 2014-06-04 23:07:32.934 6862 ERROR nova.openstack.common.loopingcall [-] in fixed duration looping call 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall Traceback (most recent call last): 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall self.f(*self.args, **self.kw) 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 289, in _wait_for_active 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall raise exception.InstanceDeployFailure(msg) 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall InstanceDeployFailure: Failed to provision instance 0c282e24-1a4a-4c29-8a91-db5d05fd2063: None 2014-06-04 23:07:32.934 6862 TRACE nova.openstack.common.loopingcall 2014-06-04 23:07:33.159 6862 ERROR nova.compute.manager [req-331412f4-88b4-4ce5-a988-faf489f8c023 None] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Instance failed to spawn 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Traceback (most recent call last): 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 2059, in _build_resources 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] yield resources 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1962, in _build_and_run_instance 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] block_device_info=block_device_info) 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 455, in spawn 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] timer.start(interval=CONF.ironic.api_retry_interval).wait() 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return hubs.get_hub().switch() 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self.greenlet.switch() 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] self.f(*self.args, **self.kw) 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 289, in _wait_for_active 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] raise exception.InstanceDeployFailure(msg) 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] InstanceDeployFailure: Failed to provision instance 0c282e24-1a4a-4c29-8a91-db5d05fd2063: None 2014-06-04 23:07:33.159 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] 2014-06-04 23:07:33.289 6862 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 0.93191 sec .... .... .... 2014-06-04 23:08:28.094 6862 WARNING nova.compute.resource_tracker [req-331412f4-88b4-4ce5-a988-faf489f8c023 None] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Host field should not be set on the instance until resources have been claimed. 2014-06-04 23:08:28.095 6862 WARNING nova.compute.resource_tracker [req-331412f4-88b4-4ce5-a988-faf489f8c023 None] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Node field should not be set on the instance until resources have been claimed. ... ... ...2014-06-04 23:09:23.741 6862 WARNING ironicclient.common.http [-] Request returned failure status. 2014-06-04 23:09:23.741 6862 ERROR nova.openstack.common.loopingcall [-] in fixed duration looping call 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall Traceback (most recent call last): 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall self.f(*self.args, **self.kw) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 269, in _wait_for_active 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall node = icli.call("node.get_by_instance_uuid", instance['uuid']) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/client_wrapper.py", line 89, in call 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall return self._multi_getattr(client, method)(*args, **kwargs) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/v1/node.py", line 61, in get_by_instance_uuid 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall nodes = self._list(self._path(path), 'nodes') 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/base.py", line 50, in _list 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall resp, body = self.api.json_request('GET', url) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 186, in json_request 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall resp, body_iter = self._http_request(url, method, **kwargs) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 169, in _http_request 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall error_json.get('debuginfo'), method, url) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall InternalServerError: Multiple rows were found for one() (HTTP 500) 2014-06-04 23:09:23.741 6862 TRACE nova.openstack.common.loopingcall 2014-06-04 23:09:23.833 6862 ERROR nova.compute.manager [req-331412f4-88b4-4ce5-a988-faf489f8c023 None] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Instance failed to spawn 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Traceback (most recent call last): 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 2059, in _build_resources 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] yield resources 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1962, in _build_and_run_instance 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] block_device_info=block_device_info) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 455, in spawn 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] timer.start(interval=CONF.ironic.api_retry_interval).wait() 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return hubs.get_hub().switch() 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self.greenlet.switch() 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] self.f(*self.args, **self.kw) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 269, in _wait_for_active 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] node = icli.call("node.get_by_instance_uuid", instance['uuid']) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/client_wrapper.py", line 89, in call 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self._multi_getattr(client, method)(*args, **kwargs) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/v1/node.py", line 61, in get_by_instance_uuid 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] nodes = self._list(self._path(path), 'nodes') 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/base.py", line 50, in _list 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body = self.api.json_request('GET', url) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 186, in json_request 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body_iter = self._http_request(url, method, **kwargs) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 169, in _http_request 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] error_json.get('debuginfo'), method, url) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] InternalServerError: Multiple rows were found for one() (HTTP 500) 2014-06-04 23:09:23.833 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] .... .... .... 2014-06-04 23:18:30.066 6862 WARNING ironicclient.common.http [-] Request returned failure status. 2014-06-04 23:18:30.067 6862 ERROR nova.compute.manager [-] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Periodic sync_power_state task had an error while processing an instance. 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Traceback (most recent call last): 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5278, in _sync_power_states 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] vm_instance = self.driver.get_info(db_instance) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 368, in get_info 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] node = icli.call("node.get_by_instance_uuid", instance['uuid']) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/client_wrapper.py", line 89, in call 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self._multi_getattr(client, method)(*args, **kwargs) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/v1/node.py", line 61, in get_by_instance_uuid 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] nodes = self._list(self._path(path), 'nodes') 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/base.py", line 50, in _list 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body = self.api.json_request('GET', url) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 186, in json_request 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body_iter = self._http_request(url, method, **kwargs) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 169, in _http_request 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] error_json.get('debuginfo'), method, url) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] InternalServerError: Multiple rows were found for one() (HTTP 500) 2014-06-04 23:18:30.067 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] 2014-06-04 23:25:42.407 6862 ERROR nova.openstack.common.periodic_task [-] Error during ClusteredComputeManager._cleanup_running_deleted_instances: 'str' object has no attribute 'instance_uuid' 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task Traceback (most recent call last): 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py", line 175, in run_periodic_tasks 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task task(self, context) 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5532, in _cleanup_running_deleted_instances 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task for instance in self._running_deleted_instances(context): 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5588, in _running_deleted_instances 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task instances = self._get_instances_on_driver(context, filters) 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 652, in _get_instances_on_driver 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task driver_uuids = self.driver.list_instance_uuids() 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 333, in list_instance_uuids 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task return [i.instance_uuid for i in self.list_instances()] 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task AttributeError: 'str' object has no attribute 'instance_uuid' 2014-06-04 23:25:42.407 6862 TRACE nova.openstack.common.periodic_task 2014-06-04 23:28:29.159 6862 WARNING nova.compute.manager [-] Found 30 in the database and 31 on the hypervisor. 2014-06-04 23:28:29.414 6862 WARNING ironicclient.common.http [-] Request returned failure status. 2014-06-04 23:28:29.415 6862 ERROR nova.compute.manager [-] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Periodic sync_power_state task had an error while processing an instance. 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Traceback (most recent call last): 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5278, in _sync_power_states 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] vm_instance = self.driver.get_info(db_instance) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 368, in get_info 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] node = icli.call("node.get_by_instance_uuid", instance['uuid']) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/client_wrapper.py", line 89, in call 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self._multi_getattr(client, method)(*args, **kwargs) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/v1/node.py", line 61, in get_by_instance_uuid 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] nodes = self._list(self._path(path), 'nodes') 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/base.py", line 50, in _list 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body = self.api.json_request('GET', url) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 186, in json_request 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body_iter = self._http_request(url, method, **kwargs) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 169, in _http_request 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] error_json.get('debuginfo'), method, url) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] InternalServerError: Multiple rows were found for one() (HTTP 500) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] 2014-06-04 23:28:29.159 6862 WARNING nova.compute.manager [-] Found 30 in the database and 31 on the hypervisor. 2014-06-04 23:28:29.414 6862 WARNING ironicclient.common.http [-] Request returned failure status. 2014-06-04 23:28:29.415 6862 ERROR nova.compute.manager [-] [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Periodic sync_power_state task had an error while processing an instance. 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] Traceback (most recent call last): 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5278, in _sync_power_states 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] vm_instance = self.driver.get_info(db_instance) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 368, in get_info 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] node = icli.call("node.get_by_instance_uuid", instance['uuid']) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/client_wrapper.py", line 89, in call 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] return self._multi_getattr(client, method)(*args, **kwargs) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/v1/node.py", line 61, in get_by_instance_uuid 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] nodes = self._list(self._path(path), 'nodes') 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/base.py", line 50, in _list 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body = self.api.json_request('GET', url) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 186, in json_request 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] resp, body_iter = self._http_request(url, method, **kwargs) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironicclient/common/http.py", line 169, in _http_request 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] error_json.get('debuginfo'), method, url) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] InternalServerError: Multiple rows were found for one() (HTTP 500) 2014-06-04 23:28:29.415 6862 TRACE nova.compute.manager [instance: 0c282e24-1a4a-4c29-8a91-db5d05fd2063] 2014-06-04 23:30:57.497 6862 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 0.011055 sec 2014-06-04 23:33:21.855 6862 ERROR nova.openstack.common.loopingcall [-] in fixed duration looping call 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall Traceback (most recent call last): 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall self.f(*self.args, **self.kw) 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 289, in _wait_for_active 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall raise exception.InstanceDeployFailure(msg) 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall InstanceDeployFailure: Failed to provision instance 44a6883c-6cce-4f8c-a7ee-1782a6b98149: Timeout reached while waiting for callback for node 951f30c4-1b63-43e2-b3ce-4ca69b3013ee 2014-06-04 23:33:21.855 6862 TRACE nova.openstack.common.loopingcall 2014-06-04 23:33:21.856 6862 ERROR nova.compute.manager [req-44a4433c-e2b5-47fc-8608-ed1d3108e0f9 None] [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] Instance failed to spawn 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] Traceback (most recent call last): 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 2059, in _build_resources 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] yield resources 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1962, in _build_and_run_instance 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] block_device_info=block_device_info) 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 455, in spawn 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] timer.start(interval=CONF.ironic.api_retry_interval).wait() 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] return hubs.get_hub().switch() 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] return self.greenlet.switch() 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 76, in _inner 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] self.f(*self.args, **self.kw) 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 289, in _wait_for_active 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] raise exception.InstanceDeployFailure(msg) 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] InstanceDeployFailure: Failed to provision instance 44a6883c-6cce-4f8c-a7ee-1782a6b98149: Timeout reached while waiting for callback for node 951f30c4-1b63-43e2-b3ce-4ca69b3013ee 2014-06-04 23:33:21.856 6862 TRACE nova.compute.manager [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] 2014-06-04 23:33:22.174 6862 WARNING nova.compute.resource_tracker [req-44a4433c-e2b5-47fc-8608-ed1d3108e0f9 None] [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] Host field should not be set on the instance until resources have been claimed. 2014-06-04 23:33:22.174 6862 WARNING nova.compute.resource_tracker [req-44a4433c-e2b5-47fc-8608-ed1d3108e0f9 None] [instance: 44a6883c-6cce-4f8c-a7ee-1782a6b98149] Node field should not be set on the instance until resources have been claimed.