overcloud create failing; "Command output matched '(CREATE|UPDATE)_FAILED'"

[Christopher Grandinetti]

When running devtest it's consistently failing with the following:

10:55:55 + echo 'Waiting for the overcloud stack to be ready'
10:55:55 Waiting for the overcloud stack to be ready
10:55:55 + wait_for_stack_ready 360 10 overcloud
10:55:56 Command output matched '(CREATE|UPDATE)_FAILED'. Exiting...
10:55:56 Build step 'Execute shell' marked build as failure

Logging into the undercloud as heat-admin and running the following heat commands, yields:

root@undercloud-undercloud-oueregn6xs6s:~# !2
heat stack-show overcloud
+----------------------+----------------------------------------------------------------------------------------------------------------------------------+
| Property | Value |
+----------------------+----------------------------------------------------------------------------------------------------------------------------------+
| capabilities | [] |
| creation_time | 2014-05-12T10:51:54Z |
| description | Nova API,Keystone,Heat Engine and |
| | API,Glance,Neutron,Dedicated MySQL server,Dedicated |
| | RabbitMQ Server,Group of Nova Computes,Common Block |
| | Storage Configuration,swift-source.yaml,Common Swift |
| | Storage Configuration,ssl-source: SSL endpoint metadata |
| | for openstack,Swift-proxy: OpenStack object storage |
| | proxy,nova-compute-config.yaml |
| disable_rollback | True |
| id | 3c22375b-3b09-4e1f-8c24-0513d5a1f3c1 |
| links | http://192.0.2.3:8004/v1/d00e17d13acd4e26a485392ccdc8efe6/stacks/overcloud/3c22375b-3b09-4e1f-8c24-0513d5a1f3c1 |
| notification_topics | [] |
| parameters | { |
|
.
.
..
                                                                                  |
| stack_name | overcloud |
| stack_status | CREATE_FAILED |
| stack_status_reason | Resource CREATE failed: Error: Creation of server |
| | overcloud-NovaCompute1-wlpjv2iqayyn failed. |
| template_description | Nova API,Keystone,Heat Engine and |
| | API,Glance,Neutron,Dedicated MySQL server,Dedicated |
| | RabbitMQ Server,Group of Nova Computes,Common Block |
| | Storage Configuration,swift-source.yaml,Common Swift |
| | Storage Configuration,ssl-source: SSL endpoint metadata |
| | for openstack,Swift-proxy: OpenStack object storage |
| | proxy,nova-compute-config.yaml |
| timeout_mins | None |
| updated_time | None |
+----------------------+----------------------------------------------------------------------------------------------------------------------------------+

root@undercloud-undercloud-oueregn6xs6s:~# !4
heat resource-list overcloud
+--------------------------+--------------------------------+-----------------+----------------------+
| resource_name | resource_type | resource_status | updated_time |
+--------------------------+--------------------------------+-----------------+----------------------+
| NovaCompute1 | OS::Nova::Server | CREATE_FAILED | 2014-05-12T10:51:54Z |
| SwiftConfig | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:51:54Z |
| BlockStorageConfig | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:51:56Z |
| NovaCompute0 | OS::Nova::Server | CREATE_FAILED | 2014-05-12T10:51:56Z |
| NovaComputePassthrough | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:51:57Z |
| controller0 | OS::Nova::Server | CREATE_FAILED | 2014-05-12T10:51:57Z |
| controllerPassthrough | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:51:58Z |
| ControlVirtualIP | OS::Neutron::Port | CREATE_COMPLETE | 2014-05-12T10:52:01Z |
| RabbitCookie | OS::Heat::RandomString | CREATE_COMPLETE | 2014-05-12T10:52:01Z |
| SSLConfig | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:52:02Z |
| NovaComputeConfig | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:52:03Z |
| controllerConfig | OS::Heat::StructuredConfig | CREATE_COMPLETE | 2014-05-12T10:52:04Z |
| NovaCompute0Config | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| NovaCompute0Passthrough | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| NovaCompute1Config | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| NovaCompute1Passthrough | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| controller0Deployment | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| controller0Passthrough | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| controller0SSLDeployment | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
| controller0Swift | OS::Heat::StructuredDeployment | INIT_COMPLETE | 2014-05-12T16:51:23Z |
+--------------------------+--------------------------------+-----------------+----------------------+

The tail end of /var/log/upstart/heat-engine.log shows:
2014-05-12 10:53:03.717 5390 ERROR heat.engine.resource [-] CREATE : Server "NovaCompute1" [641d143f-1533-4747-95ec-68fb9601fa56] Stack "overcloud" [3c22375b-3b09-4e1f-8c24-0513d5a1f3c1]
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource Traceback (most recent call last):
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/resource.py", line 397, in _do_action
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource while not check(handle_data):
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource File "/opt/stack/venvs/heat/lib/python2.7/site-packages/heat/engine/resources/server.py", line 533, in check_create_complete
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource return self._check_active(server)
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource File "/opt/stack/venvs/heat/lib/python2.7/site-packages/heat/engine/resources/server.py", line 549, in _check_active
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource raise exc
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource Error: Creation of server overcloud-NovaCompute1-wlpjv2iqayyn failed.
2014-05-12 10:53:03.717 5390 TRACE heat.engine.resource
2014-05-12 10:53:03.795 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.092 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.355 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.451 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.571 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.691 5390 WARNING heat.common.keystoneclient [-] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 10:53:04.842 5390 WARNING heat.engine.service [-] Stack create failed, status FAILED
2014-05-12 16:23:07.209 5390 WARNING heat.common.keystoneclient [req-b6d4f586-04a2-439a-9841-17a44224dad7 None] stack_user_domain ID not set in heat.conf falling back to using default
2014-05-12 16:51:23.319 5390 WARNING heat.common.keystoneclient [req-e6e03ca0-d1dd-40ca-a8c5-ae6db30a4d89 None] stack_user_domain ID not set in heat.conf falling back to using default

The tail end of the /var/log/upstart/nova-compute.log:
2014-05-12 16:54:00.185 5951 TRACE nova.compute.manager [instance: 6618bc9b-195f-4f62-a6a2-778c1f1a1835] raise ConnectionFailed()
2014-05-12 16:54:00.185 5951 TRACE nova.compute.manager [instance: 6618bc9b-195f-4f62-a6a2-778c1f1a1835] ConnectionFailed: Connection failed
2014-05-12 16:54:00.185 5951 TRACE nova.compute.manager [instance: 6618bc9b-195f-4f62-a6a2-778c1f1a1835]
2014-05-12 16:54:00.330 5951 ERROR nova.virt.baremetal.common [-] Connection error
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common Traceback (most recent call last):
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/common.py", line 55, in ssh_connect
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common timeout=CONNECTION_TIMEOUT)
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/paramiko/client.py", line 273, in connect
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common self._auth(username, password, pkey, key_filenames, allow_agent, look_for_keys)
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/paramiko/client.py", line 456, in _auth
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common raise saved_exception
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common AuthenticationException: Authentication failed.
2014-05-12 16:54:00.330 5951 TRACE nova.virt.baremetal.common
2014-05-12 16:54:00.394 5951 ERROR nova.compute.manager [-] [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] Periodic sync_power_state task had an error while processing an instance.
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] Traceback (most recent call last):
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/compute/manager.py", line 5282, in _sync_power_states
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] vm_instance = self.driver.get_info(db_instance)
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/driver.py", line 445, in get_info
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] ps = pm.is_power_on()
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/virtual_power_driver.py", line 195, in is_power_on
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] if not self._check_for_node():
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/virtual_power_driver.py", line 144, in _check_for_node
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] full_node_list = self._get_full_node_list()
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/virtual_power_driver.py", line 137, in _get_full_node_list
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] full_list = self._run_command(cmd)
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/virtual_power_driver.py", line 220, in _run_command
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] self._set_connection()
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/virtual_power_driver.py", line 132, in _set_connection
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] self._connection = connection.ssh_connect(self.connection_data)
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] File "/opt/stack/venvs/nova/local/lib/python2.7/site-packages/nova/virt/baremetal/common.py", line 66, in ssh_connect
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] raise ConnectionFailed()
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139] ConnectionFailed: Connection failed
2014-05-12 16:54:00.394 5951 TRACE nova.compute.manager [instance: b3ee5b60-64ad-4753-8c1a-7b218a7d8139]

[Clint Byrum (clint-fewbar)]

This is a TripleO bug, not Heat. We need to investigate more.