libvirtd going into a tight loop causing instances to not transition to ACTIVE

There is an interesting sequence of log lines in the compute log for the nova instance (instance-00000001) that is reported in the repeated libvirt logs.

Oct 28 23:45:02.776968 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: INFO nova.virt.libvirt.driver [-] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Instance spawned successfully.
Oct 28 23:45:02.776968 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: INFO nova.compute.manager [None req-e609f22f-0c5b-4e75-8fed-2cc5ea78decb admin admin] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Took 326.09 seconds to spawn the instance on the hypervisor.
Oct 28 23:45:02.777289 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: DEBUG nova.compute.manager [None req-e609f22f-0c5b-4e75-8fed-2cc5ea78decb admin admin] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Checking state {{(pid=16413) _get_power_state /opt/stack/nova/nova/compute/manager.py:1557}}
Oct 28 23:45:02.828879 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: DEBUG nova.compute.manager [None req-1efcbd1f-1af9-4e08-8572-e04879fa08fb None None] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Checking state {{(pid=16413) _get_power_state /opt/stack/nova/nova/compute/manager.py:1557}}
Oct 28 23:45:02.832224 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: DEBUG nova.compute.manager [None req-1efcbd1f-1af9-4e08-8572-e04879fa08fb None None] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Synchronizing instance power state after lifecycle event "Resumed"; current vm_state: building, current task_state: deleting, current DB power_state: 0, VM power_state: 1 {{(pid=16413) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1294}}
Oct 28 23:45:02.865991 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: INFO nova.compute.manager [None req-1efcbd1f-1af9-4e08-8572-e04879fa08fb None None] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] During sync_power_state the instance has a pending task (deleting). Skip.
Oct 28 23:45:03.052749 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: DEBUG nova.compute.utils [None req-e609f22f-0c5b-4e75-8fed-2cc5ea78decb admin admin] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Conflict updating instance 7a343084-ac33-4dcb-8343-744fe2c1fb26. Expected: {'task_state': ['spawning']}. Actual: {'task_state': 'deleting'} {{(pid=16413) notify_about_instance_usage /opt/stack/nova/nova/compute/utils.py:429}}
Oct 28 23:45:03.065608 nested-virt-ubuntu-bionic-vexxhost-ca-ymq-1-0021169707 nova-compute[16413]: DEBUG nova.compute.manager [None req-e609f22f-0c5b-4e75-8fed-2cc5ea78decb admin admin] [instance: 7a343084-ac33-4dcb-8343-744fe2c1fb26] Instance disappeared during build. {{(pid=16413) _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:2266}}

nova reports that the instance is built successfully and right after it it reports that the instance is disappeared during build.

It seems that the whole libvirt error loop happens after nova resumed the guest in libvirt. The fact that the overall instance boot took mo...

Posting the start and end of the libvirt tight loop from the libvirtd log file. (As the pastebins expire.)

tl;dr: The libvirt version in the above logs is libvirt-5.4.0 (and libglib-2.56.4) ; and libvirt developers suggest that there are some fixes in this area in the upstream libvirt 6.7.0; and it might potentially also be fixed in libvirt-6.1.0 (or higher).

Long
----

Talking to Michal from the upstream libvirt team, this sounds like a libvirt bug. To quote him from IRC:

"When we [libvirt] start a guest and open its [QEMU] monitor we put the FD into our event loop. And whenever QEMU emits an event, a handler is called. But in this instance the handler was called over and over. On the other hand, there were some issues in glib's event loop once we [libvirt] switched to that."

So the preferred order of testing libvirt versions (based on what's available):

- try libvirt-6.9.0; if not
- try libvirt-6.7.0; if not
- try libvirt-6.1.0

@Michael J.: is there a way to change the libvirt version in the octavia jobs to see if the above suggestion helps?

I'm not sure, it is being installed via the nova devstack plugin. Is there a way to point nova to a different version?

2020-10-28 23:07:50.003 | + lib/nova_plugins/hypervisor-libvirt:install_nova_hypervisor:84 :   install_libvirt
2020-10-28 23:07:50.523 | Get:25 http://mirror.ca-ymq-1.vexxhost.opendev.org/ubuntu-cloud-archive bionic-updates/train/main amd64 libvirt-daemon amd64 5.4.0-0ubuntu5.4~cloud0 [1,412 kB]

I also see that the job is running on bionic, we could try flipping that to focal which might pull in a newer version.

Yeah flipping that to Focal on master is a good idea (and was a V cycle goal anyhow)

Do we still seeing this issue?

Yes, here:

https://zuul.opendev.org/t/openstack/build/bacab9bbb16d4c8288e5fe1962b40291/log/controller/logs/screen-n-cpu.txt?severity=4#3531

stable Train job on bionic

And here:
https://zuul.opendev.org/t/openstack/build/08d983af63ef48f09e3f83074acd4358/log/controller/logs/screen-n-cpu.txt?severity=4#5102

stable victoria job on bionic

What do we want to do with this bug? Ultimately the underlying issue is with the version of libvirt shipped in Bionic that's outside of our control. Should we move the bug to the libvirt component and ask the Ubuntu team if a rebase is even feasible?

Thanks for the bump to this one.
I've marked it fixed in Focal according to the reports above.
By that it also is fixed in the Ubuntu Cloud Archive Ussuri which is availble for Bionic.
Only the libvirt version in bionic itself (4.0.0-1ubuntu8.19) is affected by this still.

From your testing and discussions - was in the meantime already a chance to identify:
a) an individual (set of) commits that fixed this between 64.0 and 6.0
   Comment 3 mentioned further improvements in 6.1 and 6.7, but since the tests report 6.0 as
   ok maybe the change we would need it smaller than one might have thought.
b) did in the meantime anywhere a smaller/simpler test come up that is easier
   than "run openstacks tests"?