Instance Creation fails because of Timeout and Duplicate Hostname for Bindings on NSX Edge (DHCP)

[Daniel Weber]

Using Openstack Liberty with VMware Driver / NSX Integration.

When deploying a Template with Heat (3 Instances, with 3 Security Groups, own Network)
The creation failes with an Error: no Hosts available.

But the main reason is a Timeout that occures between nova and neutron.
See the logs below.

For me it seems that Nova creates with Neutron a new Port in NSX (Create DHCP reservation) , this times out, but the port gets created.

2016-05-05 15:53:33.165 8705 ERROR nova.compute.manager [instance: 6129429c-803b-47bb-a5cd-afb0419e2a12] RequestTimeout: Request to http://172.17.99.211:9696/v2.0/ports/4832456a-c007-4c06-bcbe-718cf9346a93.json timed out (HTTP 408)
29c-803b-47bb-a5cd-afb0419e2a12] Error from last host: vcenter-MirantisLiberty (node domain-c197.11160f6a-be80-4025-a0be-b915de612a16): [u'Traceback (most recent call last):\n', u' File "/usr/lib/python2.7/dist-packages/nova/compu
te/manager.py", line 1907, in _do_build_and_run_instance\n filter_properties)\n', u' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 2059, in _build_and_run_instance\n instance_uuid=instance.uuid, reaso
n=six.text_type(e))\n', u'RescheduledException: Build of instance 6129429c-803b-47bb-a5cd-afb0419e2a12 was re-scheduled: Request to http://172.17.99.211:9696/v2.0/ports/4832456a-c007-4c06-bcbe-718cf9346a93.json timed out (HTTP 408)
\n']

I can see, that the Edge DHCP, that has been created with HEAT, has also created a reservation for this machine.

Then, as the instance creation is rescheduled, it tries again to create that port but fails, as the port is alredy configured on the Edge:

2016-05-05 15:54:51.191 8705 ERROR nova.compute.manager [instance: 18c9db8e-1a89-4ac6-a432-3ca75e92dbf2] InternalServerError: Request https://172.17.99.8/api/4.0/edges/edge-115/dhcp/config/bindings is Bad, response {"details":"[Dhcp] Duplicate hostname for binding 4832456a-c007-4c06-bcbe-718cf9346a93 : VmId null and VnicId null.","errorCode":12504,"moduleName":"vShield Edge"}

The environment consists of following:

Vsphere Version: 6.0.2
Openstack Liberty (Deployed from Mirantis)
There is only one Controller which includes all the Parts of Openstack (Nova, Neutron, Cinder, Glance, Horizon)

Thanks for any help to solve the Problem.

Here are Logs in Detail:

83a2-445a-b43a-4a0b59b8e3f5] Claim successful
<179>May 5 15:53:44 node-3 nova-compute: 2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager [-] Instance failed network setup after 1 attempt(s)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager Traceback (most recent call last):
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1566, in _allocate_network_async
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager bind_host_id=bind_host_id)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py", line 727, in allocate_for_instance
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager self._delete_ports(neutron, instance, created_port_ids)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager six.reraise(self.type_, self.value, self.tb)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py", line 712, in allocate_for_instance
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager port_client.update_port(port['id'], port_req_body)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 102, in with_params
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager ret = self.function(instance, *args, **kwargs)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 562, in update_port
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager return self.put(self.port_path % (port), body=body)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 302, in put
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager headers=headers, params=params)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 270, in retry_request
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager headers=headers, params=params)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 211, in do_request
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager self._handle_fault_response(status_code, replybody)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 185, in _handle_fault_response
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager exception_handler_v20(status_code, des_error_body)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 70, in exception_handler_v20
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager status_code=status_code)
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager InternalServerError: Request https://172.17.99.8/api/4.0/edges/edge-115/dhcp/config/bindings is Bad, response {"details":"[Dhcp] Duplicate hostname for binding 4832456a-c007-4c06-bcbe-718cf9346a93 : VmId null and VnicId null.","errorCode":12504,"moduleName":"vShield Edge"}
2016-05-05 15:53:44.592 8705 ERROR nova.compute.manager
<182>May 5 15:53:44 node-3 nova-api: 2016-05-05 15:53:44.708 6386 INFO nova.osapi_compute.wsgi.server [req-7de220d2-3ddb-429a-8429-1c5e2eb7516b 02d474c44fb44732a2fa1032e2634e9b aac24994050a4252b3d7a2450b8ca6cf - - -] 172.17.99.211 "GET /v2/aac24994050a4252b3d7a2450b8ca6cf/servers/52366566-19ca-455a-91e0-563781ade687 HTTP/1.1" status: 200 len: 2051 time: 0.1466730
<179>May 5 15:53:44 node-3 nova-compute: 2016-05-05 15:53:44.731 8705 ERROR nova.compute.manager [req-e3108c74-9e5d-4a26-9383-54f3e4bc8b2c 02d474c44fb44732a2fa1032e2634e9b aac24994050a4252b3d7a2450b8ca6cf - - -] [instance: cde38026-83a2-445a-b43a-4a0b59b8e3f5] Instance failed to spawn

<182>May 5 15:53:32 node-3 nova-compute: 2016-05-05 15:53:32.482 8705 INFO nova.compute.resource_tracker [req-c3485140-d059-4a25-a466-1a2fd7d4af14 - - - - -] Compute_service record updated for vcenter-MirantisLiberty:domain-c197.1
1160f6a-be80-4025-a0be-b915de612a16
<179>May 5 15:53:33 node-3 nova-compute: 2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager [-] Instance failed network setup after 1 attempt(s)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager Traceback (most recent call last):
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1566, in _allocate_network_async
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager bind_host_id=bind_host_id)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py", line 727, in allocate_for_instance
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager self._delete_ports(neutron, instance, created_port_ids)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 195, in __exit__
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager six.reraise(self.type_, self.value, self.tb)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py", line 712, in allocate_for_instance
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager port_client.update_port(port['id'], port_req_body)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 102, in with_params
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager ret = self.function(instance, *args, **kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 562, in update_port
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager return self.put(self.port_path % (port), body=body)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 302, in put
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager headers=headers, params=params)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 270, in retry_request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager headers=headers, params=params)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 200, in do_request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager content_type=self.content_type())
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 306, in do_request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager return self.request(url, method, **kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 294, in request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager resp = super(SessionClient, self).request(*args, **kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 95, in request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager return self.session.request(url, method, **kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/keystoneclient/utils.py", line 337, in inner
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager return func(*args, **kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 386, in request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager resp = send(**kwargs)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 427, in _send_request
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager raise exceptions.RequestTimeout(msg)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager RequestTimeout: Request to http://172.17.99.211:9696/v2.0/ports/4832456a-c007-4c06-bcbe-718cf9346a93.json timed out (HTTP 408)
2016-05-05 15:53:33.162 8705 ERROR nova.compute.manager
<179>May 5 15:53:33 node-3 nova-compute: 2016-05-05 15:53:33.165 8705 ERROR nova.compute.manager [req-735f9ded-dec2-4302-8e58-2fc8f58a1cec 02d474c44fb44732a2fa1032e2634e9b aac24994050a4252b3d7a2450b8ca6cf - - -] [instance: 6129429
c-803b-47bb-a5cd-afb0419e2a12] Instance failed to spawn

[Daniel Weber (daniel-weber-ch)]

I think the problem seems to be related to the newest Patch of the following link:
https://review.openstack.org/gitweb?p=openstack/vmware-nsx.git;a=commit;h=d9d5e226c9e9b9ac3b0f78d69e1d41f9c2f188e5

I've solved the problem by not creating all the machines at the same time.
Each Machine should be created alone by using:
depends_on: other_machine

After changing my Heat-Template it's now deploying without errors!

But still the question relies, if this has to be fixed.

If the Edge of DHCP sends back that it is a duplication, maybe it has to be checked if it's the same as we try to create. If this is true, we should not create an Exception.

[Gary Kotton (garyk)]

This has been fixed in patch https://review.openstack.org/317337

[Johny Dawn (totalsportektv)]

i have also facing the same issue on my client's site: https://totalsportektv.com/