Bug 1636034
| Summary: | [CI] Virtual Interface creation failed | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat OpenStack | Reporter: | Waldemar Znoinski <wznoinsk> | ||||
| Component: | openstack-nova | Assignee: | OSP DFG:Compute <osp-dfg-compute> | ||||
| Status: | CLOSED DUPLICATE | QA Contact: | OSP DFG:Compute <osp-dfg-compute> | ||||
| Severity: | urgent | Docs Contact: | |||||
| Priority: | urgent | ||||||
| Version: | 14.0 (Rocky) | CC: | berrange, dasmith, eglynn, jhakimra, kchamart, sbauza, sferdjao, sgordon, stephenfin, vromanso | ||||
| Target Milestone: | --- | Keywords: | AutomationBlocker | ||||
| Target Release: | --- | ||||||
| Hardware: | x86_64 | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2018-10-10 14:00:04 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
|
Description
Waldemar Znoinski
2018-10-04 10:00:59 UTC
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 *** |