Looks like nova-compute missed neutron-server notification about port binding.
Spawning:
2016-04-28 11:14:05.336 3707 INFO nova.virt.libvirt.driver Creating image
2016-04-28 11:14:11.124 3707 INFO nova.compute.manager VM Started (Lifecycle Event)
2016-04-28 11:14:11.181 3707 INFO nova.compute.manager VM Paused (Lifecycle Event)
2016-04-28 11:14:11.277 3707 INFO nova.compute.manager During sync_power_state the instance has a pending task (spawning). Skip.
Here we're waiting for portbinding and neutron does it perfectly:
2016-04-28 11:14:12.332 23427 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'tag': u'ec35f707-7e9e-4d93-850c-de765411f5f1', u'name': u'network-vif-plugged', u'server_uuid': u'aa1af326-ff02-471c-a546-a4efdc871f63', u'code': 200}
2016-04-28 11:14:12.459 23438 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'tag': u'2be1b1be-f700-49da-b150-b82a3ae983cd', u'name': u'network-vif-plugged', u'server_uuid': u'aa1af326-ff02-471c-a546-a4efdc871f63', u'code': 200}
2016-04-28 11:15:22.997 23375 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'tag': u'ec35f707-7e9e-4d93-850c-de765411f5f1', u'name': u'network-vif-plugged', u'server_uuid': u'aa1af326-ff02-471c-a546-a4efdc871f63', u'code': 200}
2016-04-28 11:14:12.313 14444 INFO nova.api.openstack.compute.server_external_events Creating event network-vif-plugged:ec35f707-7e9e-4d93-850c-de765411f5f1 for instance aa1af326-ff02-471c-a546-a4efdc871f63
2016-04-28 11:14:12.451 14467 INFO nova.api.openstack.compute.server_external_events Creating event network-vif-plugged:2be1b1be-f700-49da-b150-b82a3ae983cd for instance aa1af326-ff02-471c-a546-a4efdc871f63
2016-04-28 11:15:22.989 14467 INFO nova.api.openstack.compute.server_external_events Creating event network-vif-plugged:ec35f707-7e9e-4d93-850c-de765411f5f1 for instance aa1af326-ff02-471c-a546-a4efdc871f63
But actually nova-compute didn't get it and raise a timeout in nova.virt.libvirt.driver.LibvirtDriver#_create_domain_and_network:
Looks like nova-compute missed neutron-server notification about port binding.
Spawning:
2016-04-28 11:14:05.336 3707 INFO nova.virt. libvirt. driver Creating image manager VM Started (Lifecycle Event) manager VM Paused (Lifecycle Event) manager During sync_power_state the instance has a pending task (spawning). Skip.
2016-04-28 11:14:11.124 3707 INFO nova.compute.
2016-04-28 11:14:11.181 3707 INFO nova.compute.
2016-04-28 11:14:11.277 3707 INFO nova.compute.
Here we're waiting for portbinding and neutron does it perfectly:
2016-04-28 11:14:12.332 23427 INFO neutron. notifiers. nova [-] Nova event response: {u'status': u'completed', u'tag': u'ec35f707- 7e9e-4d93- 850c-de765411f5 f1', u'name': u'network- vif-plugged' , u'server_uuid': u'aa1af326- ff02-471c- a546-a4efdc871f 63', u'code': 200} notifiers. nova [-] Nova event response: {u'status': u'completed', u'tag': u'2be1b1be- f700-49da- b150-b82a3ae983 cd', u'name': u'network- vif-plugged' , u'server_uuid': u'aa1af326- ff02-471c- a546-a4efdc871f 63', u'code': 200} notifiers. nova [-] Nova event response: {u'status': u'completed', u'tag': u'ec35f707- 7e9e-4d93- 850c-de765411f5 f1', u'name': u'network- vif-plugged' , u'server_uuid': u'aa1af326- ff02-471c- a546-a4efdc871f 63', u'code': 200}
2016-04-28 11:14:12.459 23438 INFO neutron.
2016-04-28 11:15:22.997 23375 INFO neutron.
2016-04-28 11:14:12.313 14444 INFO nova.api. openstack. compute. server_ external_ events Creating event network- vif-plugged: ec35f707- 7e9e-4d93- 850c-de765411f5 f1 for instance aa1af326- ff02-471c- a546-a4efdc871f 63 openstack. compute. server_ external_ events Creating event network- vif-plugged: 2be1b1be- f700-49da- b150-b82a3ae983 cd for instance aa1af326- ff02-471c- a546-a4efdc871f 63 openstack. compute. server_ external_ events Creating event network- vif-plugged: ec35f707- 7e9e-4d93- 850c-de765411f5 f1 for instance aa1af326- ff02-471c- a546-a4efdc871f 63
2016-04-28 11:14:12.451 14467 INFO nova.api.
2016-04-28 11:15:22.989 14467 INFO nova.api.
But actually nova-compute didn't get it and raise a timeout in nova.virt. libvirt. driver. LibvirtDriver# _create_ domain_ and_network:
2016-04-28 11:19:11.124 3707 WARNING nova.virt. libvirt. driver [req-6e606db9- d0cf-4ea5- 82aa-8bdb4d7ed6 3d ff83fb6171cf411 db4a05126c9663c cf 2161feb2f5c5425 f815e468f30894f 4b - - -] [instance: aa1af326- ff02-471c- a546-a4efdc871f 63] Timeout waiting for vif plugging callback for instance aa1af326- ff02-471c- a546-a4efdc871f 63