e.g. http://logs.openstack.org/43/84043/2/check-tripleo/check-tripleo-ironic-undercloud-precise/a956ec9/
2014-04-01 02:55:51.973 | + echo 'Waiting for the undercloud stack to be ready'
2014-04-01 02:55:51.973 | Waiting for the undercloud stack to be ready
2014-04-01 02:55:51.974 | + wait_for_stack_ready 220 10 undercloud
2014-04-01 03:31:51.728 | Command output matched 'CREATE_FAILED'. Exiting...
Looking at nova-compute log:
2014-04-01 03:31:21.939 4490 ERROR nova.compute.manager [req-860b9cc8-d71a-4804-9384-7e8cb2c59057 771f2c6bbf2045a893d039346c8ab5c8 9eb55fac42dc4fcc928f7b18aa1a5d36] [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] Instance failed to spawn
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] Traceback (most recent call last):
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1718, in _spawn
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] block_device_info)
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 472, in spawn
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] timer.start(interval=10).wait()
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] return hubs.get_hub().switch()
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] return self.greenlet.switch()
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 78, in _inner
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] self.f(*self.args, **self.kw)
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 468, in _wait_for_active
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] raise exception.InstanceDeployFailure(msg)
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] InstanceDeployFailure: Failed to provision instance 05e3af7a-383a-4697-9cc9-bd7c572600f0: Deploy timed out, but an unhandled exception was encountered while aborting. More info may be found in the log file.
2014-04-01 03:31:21.939 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0]
2014-04-01 03:31:35.365 4490 ERROR nova.compute.manager [req-860b9cc8-d71a-4804-9384-7e8cb2c59057 771f2c6bbf2045a893d039346c8ab5c8 9eb55fac42dc4fcc928f7b18aa1a5d36] [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] Error: Failed to provision instance 05e3af7a-383a-4697-9cc9-bd7c572600f0: Deploy timed out, but an unhandled exception was encountered while aborting. More info may be found in the log file.
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] Traceback (most recent call last):
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1309, in _build_instance
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] set_access_ip=set_access_ip)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 399, in decorated_function
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] return function(self, context, *args, **kwargs)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1721, in _spawn
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] LOG.exception(_('Instance failed to spawn'), instance=instance)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] six.reraise(self.type_, self.value, self.tb)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 1718, in _spawn
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] block_device_info)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 472, in spawn
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] timer.start(interval=10).wait()
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] return hubs.get_hub().switch()
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] return self.greenlet.switch()
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py", line 78, in _inner
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] self.f(*self.args, **self.kw)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/ironic/nova/virt/ironic/driver.py", line 468, in _wait_for_active
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] raise exception.InstanceDeployFailure(msg)
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0] InstanceDeployFailure: Failed to provision instance 05e3af7a-383a-4697-9cc9-bd7c572600f0: Deploy timed out, but an unhandled exception was encountered while aborting. More info may be found in the log file.
2014-04-01 03:31:35.365 4490 TRACE nova.compute.manager [instance: 05e3af7a-383a-4697-9cc9-bd7c572600f0]
And Ironic-conductor log:
(stevedore.extension): 2014-04-01 02:40:13,499 ERROR Could not load 'pxe_seamicro': PXEAndSeaMicroDriver
(stevedore.extension): 2014-04-01 02:40:13,500 ERROR PXEAndSeaMicroDriver
Traceback (most recent call last):
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/extension.py", line 162, in _load_plugins
verify_requirements,
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/enabled.py", line 66, in _load_one_plugin
verify_requirements,
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/extension.py", line 180, in _load_one_plugin
obj = plugin(*invoke_args, **invoke_kwds)
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/ironic/drivers/pxe.py", line 102, in __init__
raise exception.DriverNotFound('PXEAndSeaMicroDriver')
DriverNotFound: PXEAndSeaMicroDriver
(stevedore.extension): 2014-04-01 02:40:13,501 ERROR Could not load 'fake_seamicro': FakeSeaMicroDriver
(stevedore.extension): 2014-04-01 02:40:13,502 ERROR FakeSeaMicroDriver
Traceback (most recent call last):
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/extension.py", line 162, in _load_plugins
verify_requirements,
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/enabled.py", line 66, in _load_one_plugin
verify_requirements,
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/stevedore/extension.py", line 180, in _load_one_plugin
obj = plugin(*invoke_args, **invoke_kwds)
File "/opt/stack/venvs/ironic/local/lib/python2.7/site-packages/ironic/drivers/fake.py", line 87, in __init__
raise exception.DriverNotFound('FakeSeaMicroDriver')
DriverNotFound: FakeSeaMicroDriver
(ironic.conductor.manager): 2014-04-01 03:31:17,856 ERROR Timeout reached when waiting callback for node f36bc755-df36-40fc-8d57-9504e194eadd
(glanceclient.common.http): 2014-04-01 03:31:17,879 ERROR Request returned failure status.
(ironic.conductor.utils): 2014-04-01 03:31:17,879 ERROR Cleanup failed for node f36bc755-df36-40fc-8d57-9504e194eadd after deploy timeout: HTTPUnauthorized (HTTP 401)
This is the problem:
_create_ token_file( task, node)
_update_ neutron( task, node)
manager_ utils.node_ set_boot_ device( task, node, 'pxe', persistent=True)
manager_ utils.node_ power_action( task, node, states.REBOOT)
There's no synchronisation with neutron (neither poll nor call-back) to know that (all) the dnsmasq processes serving that port have been updated - and a VM that boots quickly may DHCP before the dnsmasq is hupped.