Description of problem: VM instance on the overcloud fails to spawn with 'failed to allocate network(s)' error, nova-compute.log showing 2018-10-04 10:33:19.548 1 DEBUG nova.virt.libvirt.driver [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] CPU mode 'host-model' model '' was chosen, with extra flags: '' _get_guest_cpu_model_config /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:3841 2018-10-04 10:33:19.554 1 DEBUG oslo_concurrency.lockutils [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Lock "compute_resources" released by "nova.compute.resource_tracker.abort_instance_claim" :: held 0.572s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: 7c8f7701-09c0-4e73-8 dc4-81b7b0668b45] Failed to allocate network(s): VirtualInterfaceCreateException: Virtual Interface creation failed 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] Traceback (most recent call last): 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2118, in _build_and_run_instance 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] block_device_info=block_device_info) 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3080, in spawn 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] destroy_disks_on_failure=True) 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 5639, in _create_domain_and_netwo rk 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] raise exception.VirtualInterfaceCreateException() 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] VirtualInterfaceCreateException: Virtual Interface creation failed 2018-10-04 10:33:19.554 1 ERROR nova.compute.manager [instance: 7c8f7701-09c0-4e73-8dc4-81b7b0668b45] 2018-10-04 10:33:19.556 1 DEBUG nova.compute.utils [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: 7c8f7701-09c0-4e73-8dc 4-81b7b0668b45] Virtual Interface creation failed notify_about_instance_usage /usr/lib/python2.7/site-packages/nova/compute/utils.py:381 2018-10-04 10:33:19.563 1 ERROR nova.compute.manager [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: 7c8f7701-09c0-4e73-8 dc4-81b7b0668b45] Build of instance 7c8f7701-09c0-4e73-8dc4-81b7b0668b45 aborted: Failed to allocate the network(s), not rescheduling.: BuildAbortException: Build of instance 7c8f7701-09c0-4e73-8dc4-81b7b0668b45 aborted: Failed to allocate the network(s), not rescheduling. 2018-10-04 10:33:19.565 1 DEBUG nova.compute.manager [req-1cb3e40b-74f0-4ede-a9b8-e2d8c0eb50ca a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: 7c8f7701-09c0-4e73-8 the log of the intannce itself: 2018-10-04 09:28:16.534+0000: starting up libvirt version: 3.9.0, package: 14.el7_5.8 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2018-09-04-07:27:24, x86-019.build.eng.bos.redhat.com), qemu version: 2.10.0(qemu-kvm-rhev-2.10.0-21.el7_5.7), hostname: compute-1.localdomain LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOME=/root QEMU_AUDIO_DRV=none /usr/libexec/qemu-kvm -name guest=instance-00000017,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-4-instance-00000017/master-key.aes -machine pc-i440fx-rhel7.5.0,accel=kvm,usb=off,dump-guest-core=off -cpu SandyBridge,vme=on,ss=on,pcid=on,hypervisor=on,arat=on,tsc_adjust=on,xsaveopt=on -m 128 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 7c8f7701-09c0-4e73-8dc4-81b7b0668b45 -smbios 'type=1,manufacturer=Red Hat,product=OpenStack Compute,version=18.0.1-0.20180922012453.518fdc7.el7ost,serial=3fdd7cb2-065b-4d7e-9cb8-0ab03057e615,uuid=7c8f7701-09c0-4e73-8dc4-81b7b0668b45,family=Virtual Machine' -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-4-instance-00000017/monitor.sock,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -boot strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive file=/var/lib/nova/instances/7c8f7701-09c0-4e73-8dc4-81b7b0668b45/disk,format=qcow2,if=none,id=drive-virtio-disk0,cache=none -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -netdev tap,fd=78,id=hostnet0,vhost=on,vhostfd=80 -device virtio-net-pci,rx_queue_size=512,host_mtu=1450,netdev=hostnet0,id=net0,mac=fa:16:3e:d8:55:b6,bus=pci.0,addr=0x3 -add-fd set=2,fd=82 -chardev pty,id=charserial0,logfile=/dev/fdset/2,logappend=on -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0,bus=usb.0,port=1 -vnc 172.17.1.14:0 -k en-us -device cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5 -msg timestamp=on 2018-10-04T09:28:17.308659Z qemu-kvm: -chardev pty,id=charserial0,logfile=/dev/fdset/2,logappend=on: char device redirected to /dev/pts/1 (label charserial0) 2018-10-04T09:33:17.409328Z qemu-kvm: terminating on signal 15 from pid 39112 (/usr/sbin/libvirtd) 2018-10-04 09:33:17.809+0000: shutting down, reason=destroyed docker logs nova_libvirt: 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error 2018-10-03 23:00:55.942+0000: 39112: error : virNetSocketReadWire:1808 : End of file while reading data: Input/output error (it looks like it hasn't been updated for last 10+ hours) after restarting: Running command: '/usr/sbin/libvirtd' 2018-10-04 09:52:36.598+0000: 718813: info : libvirt version: 3.9.0, package: 14.el7_5.8 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2018-09-04-07:27:24, x86-019.build.eng.bos.redhat.com) 2018-10-04 09:52:36.598+0000: 718813: info : hostname: compute-1.localdomain 2018-10-04 09:52:36.598+0000: 718813: error : logStrToLong_ui:2564 : Failed to convert 'virtio0' to unsigned int 2018-10-04 09:52:36.599+0000: 718813: error : virPCIGetDeviceAddressFromSysfsLink:2643 : internal error: Failed to parse PCI config address 'virtio0' 2018-10-04 09:52:36.600+0000: 718813: error : logStrToLong_ui:2564 : Failed to convert 'virtio1' to unsigned int 2018-10-04 09:52:36.600+0000: 718813: error : virPCIGetDeviceAddressFromSysfsLink:2643 : internal error: Failed to parse PCI config address 'virtio1' 2018-10-04 09:52:36.602+0000: 718813: error : logStrToLong_ui:2564 : Failed to convert 'virtio2' to unsigned int 2018-10-04 09:52:36.602+0000: 718813: error : virPCIGetDeviceAddressFromSysfsLink:2643 : internal error: Failed to parse PCI config address 'virtio2' Version-Release number of selected component (if applicable): osp14 (puddle 2018-09-27.3) + opendaylight 8.3.0-3 (odl is possibly irrelevant here) How reproducible: 100% (it happens after https://bugzilla.redhat.com/show_bug.cgi?id=1631490 occurs when the neutron server restart is required) Steps to Reproduce: 1. deploy osp14 2. restart neutron_api 3. Actual results: failed to allocate virtual interface Expected results: success to allocate virtual interface Additional info:
I've checked whether it may be a rabbitmq clustering issue (as described in https://bugzilla.redhat.com/show_bug.cgi?id=1601561) but the rabbitmq cluster looks ok: [root@controller-2 nova]# docker exec -it rabbitmq-bundle-docker-2 rabbitmqctl cluster_status Cluster status of node 'rabbit@controller-2' [{nodes,[{disc,['rabbit@controller-0','rabbit@controller-1', 'rabbit@controller-2']}]}, {running_nodes,['rabbit@controller-1','rabbit@controller-0', 'rabbit@controller-2']}, {cluster_name,<<"rabbit">>}, {partitions,[]}, {alarms,[{'rabbit@controller-1',[]}, {'rabbit@controller-0',[]}, {'rabbit@controller-2',[]}]}]
Can you report the logs of neutron agent and server. Usually such exception is raised because a bad return from Neutron.
Created attachment 1490470 [details] sosreports_bz1636034
this makes OSP14 + ODL deployments not working at all hence changing the prio/severity
Thanks for the logs, Waldek. From a quick perusal, it seems there are two compute nodes and three controllers. We see the failures you note above on compute-1. I'm noting these below just for my own records as I continue investigating this. Firstly, the logs from compute-1. (these logs are from 'sosreport-notestname-compute-1-20181004120135/var/log/containers/nova/nova-compute.log') 2018-10-04 09:53:28.785 1 DEBUG nova.compute.manager [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Starting instance... _do_build_and_run_instance /usr/lib/python2.7/site-packages/nova/compute/manager.py:1899 2018-10-04 09:53:29.033 1 DEBUG oslo_concurrency.lockutils [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Lock "compute_resources" acquired by "nova.compute.resource_tracker.instance_claim" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273 2018-10-04 09:53:29.036 1 DEBUG nova.compute.resource_tracker [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Memory overhead for 128 MB instance; 0 MB instance_claim /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:205 2018-10-04 09:53:29.037 1 DEBUG nova.compute.resource_tracker [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Disk overhead for 0 GB instance; 0 GB instance_claim /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:208 2018-10-04 09:53:29.037 1 DEBUG nova.compute.resource_tracker [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] CPU overhead for 1 vCPUs instance; 0 vCPU(s) instance_claim /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:211 2018-10-04 09:53:29.070 1 INFO nova.compute.claims [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Attempting claim on node compute-1.localdomain: memory 128 MB, disk 0 GB, vcpus 1 CPU [snip] 2018-10-04 09:58:39.965 1 WARNING nova.virt.libvirt.driver [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Timeout waiting for [('network-vif-plugged', u'ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7')] for instance with vm_state building and task_state spawning.: Timeout: 300 seconds 2018-10-04 09:58:40.842 1 DEBUG nova.virt.libvirt.vif [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] vif_type=ovs 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-10-04T08:53:24Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='vm1',display_name='vm1',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(20),host='compute-1.localdomain',hostname='vm1',id=14,image_ref='86c29d45-7cff-49ac-875e-39eafaa08731',info_cache=InstanceInfoCache,instance_type_id=20,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='compute-1.localdomain',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=<?>,new_flavor=None,node='compute-1.localdomain',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='873e0d69004c4b0381c701bd2ac85bf6',ramdisk_id='',reservation_id='r-u6rx98g4',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='admin,reader,member',image_base_image_ref='86c29d45-7cff-49ac-875e-39eafaa08731',image_container_format='bare',image_disk_format='qcow2',image_min_disk='0',image_min_ram='0',network_allocated='True',owner_project_name='admin',owner_user_name='admin'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2018-10-04T08:53:30Z,user_data=None,user_id='a8deb6344f3a4546b786fd40da85c012',uuid=cba74bb9-6b02-4629-94a9-8440fe5b895f,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"profile": {}, "ovs_interfaceid": "ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "192.168.99.21"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "192.168.99.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "192.168.99.1"}}], "meta": {"injected": false, "tunneled": true, "tenant_id": "873e0d69004c4b0381c701bd2ac85bf6", "physical_network": null, "mtu": 1450}, "id": "18f3f229-9b33-48bb-89ae-b1bc5de0b021", "label": "net1"}, "devname": "tapce741f63-fe", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {}, "address": "fa:16:3e:db:51:c6", "active": false, "type": "ovs", "id": "ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7", "qbg_params": null} unplug /usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py:924 2018-10-04 09:58:40.843 1 DEBUG nova.network.os_vif_util [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Converting VIF {"profile": {}, "ovs_interfaceid": "ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "192.168.99.21"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "192.168.99.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "192.168.99.1"}}], "meta": {"injected": false, "tunneled": true, "tenant_id": "873e0d69004c4b0381c701bd2ac85bf6", "physical_network": null, "mtu": 1450}, "id": "18f3f229-9b33-48bb-89ae-b1bc5de0b021", "label": "net1"}, "devname": "tapce741f63-fe", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {}, "address": "fa:16:3e:db:51:c6", "active": false, "type": "ovs", "id": "ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7", "qbg_params": null} nova_to_osvif_vif /usr/lib/python2.7/site-packages/nova/network/os_vif_util.py:511 2018-10-04 09:58:40.846 1 DEBUG nova.network.os_vif_util [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:db:51:c6,bridge_name='br-int',has_traffic_filtering=False,id=ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7,network=Network(18f3f229-9b33-48bb-89ae-b1bc5de0b021),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tapce741f63-fe') nova_to_osvif_vif /usr/lib/python2.7/site-packages/nova/network/os_vif_util.py:523 2018-10-04 09:58:40.847 1 DEBUG os_vif [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Unplugging vif VIFOpenVSwitch(active=False,address=fa:16:3e:db:51:c6,bridge_name='br-int',has_traffic_filtering=False,id=ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7,network=Network(18f3f229-9b33-48bb-89ae-b1bc5de0b021),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tapce741f63-fe') unplug /usr/lib/python2.7/site-packages/os_vif/__init__.py:109 2018-10-04 09:58:40.849 1 INFO os_vif [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] Successfully unplugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:db:51:c6,bridge_name='br-int',has_traffic_filtering=False,id=ce741f63-fe19-4d0e-9e2e-75b4ff48c5f7,network=Network(18f3f229-9b33-48bb-89ae-b1bc5de0b021),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tapce741f63-fe') 2018-10-04 09:58:40.850 1 INFO nova.virt.libvirt.driver [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Deleting instance files /var/lib/nova/instances/cba74bb9-6b02-4629-94a9-8440fe5b895f_del 2018-10-04 09:58:40.852 1 INFO nova.virt.libvirt.driver [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Deletion of /var/lib/nova/instances/cba74bb9-6b02-4629-94a9-8440fe5b895f_del complete 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [req-dbc5b0ee-4d40-4bd7-b499-ac90aaa5ebfe a8deb6344f3a4546b786fd40da85c012 873e0d69004c4b0381c701bd2ac85bf6 - default default] [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Instance failed to spawn: VirtualInterfaceCreateException: Virtual Interface creation failed 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] Traceback (most recent call last): 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2354, in _build_resources 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] yield resources 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2118, in _build_and_run_instance 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] block_device_info=block_device_info) 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3080, in spawn 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] destroy_disks_on_failure=True) 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 5639, in _create_domain_and_network 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] raise exception.VirtualInterfaceCreateException() 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] VirtualInterfaceCreateException: Virtual Interface creation failed 2018-10-04 09:58:41.085 1 ERROR nova.compute.manager [instance: cba74bb9-6b02-4629-94a9-8440fe5b895f] So the instance is eventually being killed because neutron didn't reply with the error message. So, let's look at the logs for the controller nodes around this time, starting with controller 0. (these logs are from file:///home/sfinucan/.cache/.fr-xPKGf0/bz1636034/20181004_120127-no_test_name-sosreport-controller-0/sosreport-notestname-controller-0-20181004120133/var/log/containers/neutron/server.log) 2018-10-04 06:01:18.668 29251 DEBUG networking_odl.journal.journal [req-dfd667f1-e123-4691-81f2-1303f67b8232 - - - - -] Start processing journal entries sync_pending_entries /usr/lib/python2.7/site-packages/networking_odl/journal/journal.py:250 2018-10-04 06:01:18.682 1 INFO oslo_service.service [-] Child 29249 exited with status 0 2018-10-04 06:01:18.683 1 WARNING oslo_service.service [-] pid 29249 not in child list: OSError: [Errno 3] No such process 2018-10-04 06:01:18.695 1 INFO oslo_service.service [-] Child 29252 exited with status 0 2018-10-04 06:01:18.703 1 INFO oslo_service.service [-] Child 29253 exited with status 0 2018-10-04 06:01:18.729 29251 DEBUG networking_odl.journal.journal [req-dfd667f1-e123-4691-81f2-1303f67b8232 - - - - -] No journal entries to process sync_pending_entries /usr/lib/python2.7/site-packages/networking_odl/journal/journal.py:254 2018-10-04 06:01:18.748 29251 DEBUG oslo_concurrency.lockutils [-] Acquired semaphore "singleton_lock" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212 2018-10-04 06:01:18.749 29251 DEBUG oslo_concurrency.lockutils [-] Releasing semaphore "singleton_lock" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:228 2018-10-04 06:01:18.769 1 INFO oslo_service.service [-] Child 29251 exited with status 0 2018-10-04 10:25:43.135 1 INFO neutron.common.config [-] Logging enabled! 2018-10-04 10:25:43.136 1 INFO neutron.common.config [-] /usr/bin/neutron-server version 13.0.2.dev7 2018-10-04 10:25:43.137 1 DEBUG neutron.common.config [-] command line: /usr/bin/neutron-server --config-file /usr/share/neutron/neutron-dist.conf --config-dir /usr/share/neutron/server --config-file /etc/neutron/neutron.conf --config-file /etc/neutron/plugin.ini --config-dir /etc/neutron/conf.d/common --config-dir /etc/neutron/conf.d/neutron-server --log-file=/var/log/neutron/server.log setup_logging /usr/lib/python2.7/site-packages/neutron/common/config.py:103 2018-10-04 10:25:43.138 1 INFO neutron.common.config [-] Logging enabled! So it looks like the neutron server was down while this instance was booting. Based on this, I'm guessing this at least some kind of networking-odl issue here though it's not necessarily the cause of this particular issue. Moving onto controller 1, it seems either the logs are incomplete: I only see ~40 seconds of logs and none of the startup/shutdown logging, so I'm not sure what's going on here. Perhaps another thing to investigate. Finally, controller 2. This seems to be the one that serviced the request. This doesn't appear to be issuing the 'network-vif-plugged' notification for whatever reason. I'm trying to figure out why this is happening at the moment.
*** This bug has been marked as a duplicate of bug 1631335 ***