VirtualInterfaceCreateException caused by vif-plugged timeout it seems.

eg. http://logs.openstack.org/69/553069/2/check/networking-midonet-grenade-ml2/0c364ef/logs/screen-n-cpu.txt.gz#_Mar_19_03_00_14_585858

Mar 19 03:00:14.585858 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: WARNING nova.virt.libvirt.driver [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] [instance: 61309612-e8e7-4693-9d1d-b442e7a46271] Timeout waiting for [('network-vif-plugged', u'e7ddb107-2a4f-4bb5-84e1-d95da46415ae')] for instance with vm_state active and task_state reboot_started_hard.: Timeout: 300 seconds
Mar 19 03:00:14.815753 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG nova.virt.libvirt.vif [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] vif_type=midonet instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2018-03-19T02:54:37Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=<?>,disable_terminate=False,display_description='tempest-ServerActionsTestJSON-server-2512996',display_name='tempest-ServerActionsTestJSON-server-2512996',ec2_ids=<?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(11),host='ubuntu-xenial-ovh-bhs1-0003046183',hostname='tempest-serveractionstestjson-server-2512996',id=2,image_ref='06d1e26e-0b8c-4af5-898d-60bc947997be',info_cache=InstanceInfoCache,instance_type_id=11,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDdB8TLRZ3QsAlXMBNh/2IRo2QikCcYkUVWPVCJLh3TPIoEneJYb/4YY3gLp7+oAtKKLHacqWk/O+drck+TWj0jGQrRIkT0Tf4laugjD4gurKbvy7g/gIuHhbj/B6denncd0V/3jAkywPYQzU9eQHlrW87CT0SwW7tJAH22lZI09Y8rY9+TJ9S7KyY5eG2Eii304Hte+TDa3HzbJoDZhNkBI6S2TIglfqSuG+3q6KCF13HNHrdT+e7Ra1U5sAST2d+ydToeHmFHkfq33qCHmSIyFAKVLfw8QQXE1lAdJZ37C3eusMW96x59EFx9tt9yR8i6cqm+7COuPD2WL5I/fJTl Generated-by-Nova',key_name='tempest-keypair-244702523',keypairs=<?>,launch_index=0,launched_at=2018-03-19T02:54:44Z,launched_on='ubuntu-xenial-ovh-bhs1-0003046183',locked=False,locked_by=None,memory_mb=64,metadata={},migration_context=<?>,new_flavor=None,node='ubuntu-xenial-ovh-bhs1-0003046183',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=<?>,power_state=1,progress=0,project_id='621f30444ee441c980636a2137e449ed',ramdisk_id='',reservation_id='r-nzh7a7s5',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='Member',image_base_image_ref='06d1e26e-0b8c-4af5-898d-60bc947997be',image_container_format='bare',image_disk_format='q
Mar 19 03:00:14.816815 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: cow2',image_min_disk='0',image_min_ram='0',owner_project_name='tempest-ServerActionsTestJSON-1272777388',owner_user_name='tempest-ServerActionsTestJSON-1272777388'},tags=<?>,task_state='reboot_started_hard',terminated_at=None,updated_at=2018-03-19T02:55:13Z,user_data='IyEvYmluL3NoCmVjaG8gIlByaW50aW5nIGNpcnJvcyB1c2VyIGF1dGhvcml6ZWQga2V5cyIKY2F0IH5jaXJyb3MvLnNzaC9hdXRob3JpemVkX2tleXMgfHwgdHJ1ZQo=',user_id='31b211ed48bf4d1494f8066677d50fd5',uuid=61309612-e8e7-4693-9d1d-b442e7a46271,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='active') vif={"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": null, "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [{"meta": {}, "version": 4, "type": "floating", "address": "172.24.5.10"}], "address": "10.1.0.6"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "10.1.0.0/28", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.1.0.1"}}], "meta": {"injected": false, "tenant_id": "621f30444ee441c980636a2137e449ed", "mtu": 1500}, "id": "fb988938-b409-45a4-882d-649f7b4238f0", "label": "tempest-ServerActionsTestJSON-1856867966-network"}, "devname": "tape7ddb107-2a", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:59:a1:83", "active": true, "type": "midonet", "id": "e7ddb107-2a4f-4bb5-84e1-d95da46415ae", "qbg_params": null} {{(pid=17330) unplug /opt/stack/old/nova/nova/virt/libvirt/vif.py:913}}
Mar 19 03:00:14.817457 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG nova.network.os_vif_util [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] Converting VIF {"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": null, "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [{"meta": {}, "version": 4, "type": "floating", "address": "172.24.5.10"}], "address": "10.1.0.6"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "10.1.0.0/28", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.1.0.1"}}], "meta": {"injected": false, "tenant_id": "621f30444ee441c980636a2137e449ed", "mtu": 1500}, "id": "fb988938-b409-45a4-882d-649f7b4238f0", "label": "tempest-ServerActionsTestJSON-1856867966-network"}, "devname": "tape7ddb107-2a", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:59:a1:83", "active": true, "type": "midonet", "id": "e7ddb107-2a4f-4bb5-84e1-d95da46415ae", "qbg_params": null} {{(pid=17330) nova_to_osvif_vif /opt/stack/old/nova/nova/network/os_vif_util.py:484}}
Mar 19 03:00:14.818026 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG nova.network.os_vif_util [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] No conversion for VIF type midonet yet {{(pid=17330) nova_to_osvif_vif /opt/stack/old/nova/nova/network/os_vif_util.py:500}}
Mar 19 03:00:14.818254 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo.privsep.daemon [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] privsep: request[140303701502064]: (3, 'nova.privsep.libvirt.unplug_midonet_vif', (u'e7ddb107-2a4f-4bb5-84e1-d95da46415ae',), {}) {{(pid=24359) loop /usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py:443}}
Mar 19 03:00:14.818445 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo_concurrency.processutils [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] Running cmd (subprocess): mm-ctl --unbind-port e7ddb107-2a4f-4bb5-84e1-d95da46415ae {{(pid=24359) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372}}
Mar 19 03:00:14.886101 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo_concurrency.processutils [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] CMD "mm-ctl --unbind-port e7ddb107-2a4f-4bb5-84e1-d95da46415ae" returned: 0 in 0.068s {{(pid=24359) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409}}
Mar 19 03:00:14.886394 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo.privsep.daemon [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] privsep: reply[140303701502064]: (4, None) {{(pid=24359) loop /usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py:456}}
Mar 19 03:00:14.889245 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG nova.compute.manager [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] [instance: 61309612-e8e7-4693-9d1d-b442e7a46271] Checking state {{(pid=17330) _get_power_state /opt/stack/old/nova/nova/compute/manager.py:1181}}
Mar 19 03:00:14.891927 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR nova.compute.manager [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] [instance: 61309612-e8e7-4693-9d1d-b442e7a46271] Cannot reboot instance: Virtual Interface creation failed: VirtualInterfaceCreateException: Virtual Interface creation failed
Mar 19 03:00:15.096612 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo_concurrency.lockutils [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s {{(pid=17330) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:273}}
Mar 19 03:00:15.171376 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: DEBUG oslo_concurrency.lockutils [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.075s {{(pid=17330) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285}}
Mar 19 03:00:15.171717 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: INFO nova.compute.manager [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] [instance: 61309612-e8e7-4693-9d1d-b442e7a46271] Successfully reverted task state from reboot_started_hard on failure for instance.
Mar 19 03:00:15.186057 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server [None req-da6d9470-be12-426c-aec8-25f121481e95 service nova] Exception during message handling: VirtualInterfaceCreateException: Virtual Interface creation failed
Mar 19 03:00:15.186218 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server Traceback (most recent call last):
Mar 19 03:00:15.186334 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
Mar 19 03:00:15.186429 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
Mar 19 03:00:15.186522 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
Mar 19 03:00:15.186636 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
Mar 19 03:00:15.186729 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
Mar 19 03:00:15.186819 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
Mar 19 03:00:15.186915 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/exception_wrapper.py", line 76, in wrapped
Mar 19 03:00:15.187004 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
Mar 19 03:00:15.187093 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Mar 19 03:00:15.187201 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     self.force_reraise()
Mar 19 03:00:15.187295 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Mar 19 03:00:15.187390 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
Mar 19 03:00:15.187483 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/exception_wrapper.py", line 67, in wrapped
Mar 19 03:00:15.187584 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
Mar 19 03:00:15.187672 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 186, in decorated_function
Mar 19 03:00:15.187773 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     "Error: %s", e, instance=instance)
Mar 19 03:00:15.187899 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Mar 19 03:00:15.188003 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     self.force_reraise()
Mar 19 03:00:15.188096 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Mar 19 03:00:15.188199 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
Mar 19 03:00:15.188289 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 156, in decorated_function
Mar 19 03:00:15.188395 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
Mar 19 03:00:15.188485 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/utils.py", line 976, in decorated_function
Mar 19 03:00:15.188584 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
Mar 19 03:00:15.188721 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 214, in decorated_function
Mar 19 03:00:15.188825 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     kwargs['instance'], e, sys.exc_info())
Mar 19 03:00:15.188928 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Mar 19 03:00:15.189022 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     self.force_reraise()
Mar 19 03:00:15.189115 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Mar 19 03:00:15.189241 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
Mar 19 03:00:15.189345 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 202, in decorated_function
Mar 19 03:00:15.189439 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
Mar 19 03:00:15.189532 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 3250, in reboot_instance
Mar 19 03:00:15.189646 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     self._set_instance_obj_error_state(context, instance)
Mar 19 03:00:15.189745 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Mar 19 03:00:15.189839 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     self.force_reraise()
Mar 19 03:00:15.189985 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Mar 19 03:00:15.190085 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
Mar 19 03:00:15.190180 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/compute/manager.py", line 3225, in reboot_instance
Mar 19 03:00:15.190285 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     bad_volumes_callback=bad_volumes_callback)
Mar 19 03:00:15.190384 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/virt/libvirt/driver.py", line 2644, in reboot
Mar 19 03:00:15.190483 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     block_device_info)
Mar 19 03:00:15.190581 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/virt/libvirt/driver.py", line 2755, in _hard_reboot
Mar 19 03:00:15.190687 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     block_device_info=block_device_info, reboot=True)
Mar 19 03:00:15.190803 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server   File "/opt/stack/old/nova/nova/virt/libvirt/driver.py", line 5529, in _create_domain_and_network
Mar 19 03:00:15.190952 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server     raise exception.VirtualInterfaceCreateException()
Mar 19 03:00:15.191072 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server VirtualInterfaceCreateException: Virtual Interface creation failed
Mar 19 03:00:15.191431 ubuntu-xenial-ovh-bhs1-0003046183 nova-compute[17330]: ERROR oslo_messaging.rpc.server