Comment 7 for bug 1944779

from Balazs Gibizer <email address hidden>

gibizer@riverbed:~/tmp/LOGS [000] [11:12:49]
$ egrep -e "instance: 09eff2ce-356f-430f-ab30-5de58f58d698.* Timeout waiting for|network-vif-plugged-0761ff2f-ff6a-40a5-85b7-c9b40386cbe0|network-vif-plugged-e64ddd6e-3128-44ee-afd6-07d13643a4be|network-vif-plugged-bf0f9dd2-4fd3-4028-a3dc-e2581ff081d0|network-vif-plugged-8a472e87-4a7a-4ad4-9fbb-fd9785136611|instance: 09eff2ce-356f-430f-ab30-5de58f58d698.* nova.exception.VirtualInterfaceCreateException" -R
compute0/logs/nova/nova-compute.log:2021-11-25 08:50:24.237 8 DEBUG nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Preparing to wait for external event network-vif-plugged-0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 prepare_for_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:280
compute0/logs/nova/nova-compute.log:2021-11-25 08:50:24.238 8 DEBUG nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Preparing to wait for external event network-vif-plugged-e64ddd6e-3128-44ee-afd6-07d13643a4be prepare_for_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:280
compute0/logs/nova/nova-compute.log:2021-11-25 08:50:24.240 8 DEBUG nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Preparing to wait for external event network-vif-plugged-bf0f9dd2-4fd3-4028-a3dc-e2581ff081d0 prepare_for_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:280
compute0/logs/nova/nova-compute.log:2021-11-25 08:50:24.241 8 DEBUG nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Preparing to wait for external event network-vif-plugged-8a472e87-4a7a-4ad4-9fbb-fd9785136611 prepare_for_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:280
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:00.817 8 DEBUG nova.compute.manager [req-310bc640-20d2-4ff8-8ab0-7a8ed6a49b32 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Received event network-vif-plugged-0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 external_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10439
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:00.819 8 DEBUG nova.compute.manager [req-310bc640-20d2-4ff8-8ab0-7a8ed6a49b32 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Processing event network-vif-plugged-0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 _process_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10205
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:02.903 8 DEBUG nova.compute.manager [req-19440830-f1bf-4a61-9cd8-40667c8d9e0a 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Received event network-vif-plugged-e64ddd6e-3128-44ee-afd6-07d13643a4be external_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10439
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:02.906 8 DEBUG nova.compute.manager [req-19440830-f1bf-4a61-9cd8-40667c8d9e0a 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Processing event network-vif-plugged-e64ddd6e-3128-44ee-afd6-07d13643a4be _process_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10205
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:05.702 8 DEBUG nova.compute.manager [req-393fcb9a-5c68-4b0a-af1b-661e73d947cb 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Received event network-vif-plugged-8a472e87-4a7a-4ad4-9fbb-fd9785136611 external_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10439
compute0/logs/nova/nova-compute.log:2021-11-25 08:51:05.705 8 DEBUG nova.compute.manager [req-393fcb9a-5c68-4b0a-af1b-661e73d947cb 01a75e3a9a9148218916d3beafae2120 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Processing event network-vif-plugged-8a472e87-4a7a-4ad4-9fbb-fd9785136611 _process_instance_event /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:10205
compute0/logs/nova/nova-compute.log:2021-11-25 08:55:31.293 8 WARNING nova.virt.libvirt.driver [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Timeout waiting for [('network-vif-plugged', '0761ff2f-ff6a-40a5-85b7-c9b40386cbe0'), ('network-vif-plugged', 'e64ddd6e-3128-44ee-afd6-07d13643a4be'), ('network-vif-plugged', 'bf0f9dd2-4fd3-4028-a3dc-e2581ff081d0'), ('network-vif-plugged', '8a472e87-4a7a-4ad4-9fbb-fd9785136611')] for instance with vm_state building and task_state spawning: eventlet.timeout.Timeout: 300 seconds
compute0/logs/nova/nova-compute.log:2021-11-25 08:55:47.294 8 ERROR nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Instance failed to spawn: nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
compute0/logs/nova/nova-compute.log:2021-11-25 08:55:47.294 8 ERROR nova.compute.manager [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
compute0/logs/nova/nova-compute.log:2021-11-25 08:55:48.763 8 ERROR nova.compute.manager [req-6eab0f2a-d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 49231caa42f34da8a9d10229b5c7a5d8 - default default] [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] Failed to allocate network(s): nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
compute0/logs/nova/nova-compute.log:2021-11-25 08:55:48.763 8 ERROR nova.compute.manager [instance: 09eff2ce-356f-430f-ab30-5de58f58d698] nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed

+ from Balazs Gibizer <email address hidden>

as a side note I pushed a small patch to nova to log the which event
was timed out https://review.opendev.org/c/openstack/nova/+/819817