Comment 6 for bug 1969592

@Oleg: thanks for the logs. Here is the relevant part of it:

$ egrep -e 'Starting instance..|Successfully created port:|Successfully updated port|Preparing to wait for external event network-vif-plugged-|Received event|nova.virt.libvirt.vif.* plug|Timeout waiting for' nova-compute-debug-log
2022-04-27 22:01:03.119 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Starting instance... _do_build_and_run_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2197
2022-04-27 22:01:04.215 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Successfully created port: 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 _create_port_minimal /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:533
2022-04-27 22:01:05.291 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Successfully updated port: 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 _update_port /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:571
2022-04-27 22:01:05.792 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Preparing to wait for external event network-vif-plugged-13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 prepare_for_instance_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:281
2022-04-27 22:01:05.795 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - 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=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:01:03Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} plug /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:721
2022-04-27 22:01:07.209 7 DEBUG nova.compute.manager [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Received event network-changed-13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 external_instance_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:10483
2022-04-27 22:06:06.825 7 WARNING nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Timeout waiting for [('network-vif-plugged', '13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36')] for instance with vm_state building and task_state spawning: eventlet.timeout.Timeout: 300 seconds

So there was only one port 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 involved. From nova perspective the port was created then bound to the compute then the vif was plugged from nova side. Then nova waited for the network-vif-plugged event that is not received within the 300 sec timeout. From the timestamps and the port ID the networking folks should be able to dig into the neutron logs to see the reason.

Based on the logs this does not seems to be a nova bug.