All overcloud VM's powered off on hypervisor when nova_libvirt is restarted

[Brendan Shephard]

Description:

Using TripleO. Noted that all VM's on a Hypervisor are powered off during the overcloud deployment. (I only have one Hypervisor sorry, I can't tell you if it would happen to more than one hypervisor).

Seems to happen when the nova_libvirt container is restarted.

Environment:
TripleO - Master
# podman exec -it nova_libvirt rpm -qa | grep nova
python3-nova-23.1.0-0.20210625160814.1f6c351.el8.noarch
openstack-nova-compute-23.1.0-0.20210625160814.1f6c351.el8.noarch
openstack-nova-common-23.1.0-0.20210625160814.1f6c351.el8.noarch
openstack-nova-migration-23.1.0-0.20210625160814.1f6c351.el8.noarch
python3-novaclient-17.5.0-0.20210601131008.f431295.el8.noarch

Reproducer:
At least for me:
1. Start a VM
2. Restart tripleo_nova_libvirt.service:
systemctl restart tripleo_nova_libvirt.service
3. All VM's are stopped

Relevant logs:
2021-07-22 16:31:05.532 3 DEBUG nova.compute.manager [req-19a38d0b-e019-472b-95c4-03c796040767 d2ab1d5792604ba094af82d7447e88cf c4740b2aba4147adb7f101a2782003c3 - default default] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] No wait
ing events found dispatching network-vif-plugged-d9b29fef-cd87-41db-ba79-8b8c65b74efb pop_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:319
2021-07-22 16:31:05.532 3 WARNING nova.compute.manager [req-19a38d0b-e019-472b-95c4-03c796040767 d2ab1d5792604ba094af82d7447e88cf c4740b2aba4147adb7f101a2782003c3 - default default] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Recei
ved unexpected event network-vif-plugged-d9b29fef-cd87-41db-ba79-8b8c65b74efb for instance with vm_state active and task_state None.
2021-07-22 16:31:30.583 3 DEBUG nova.compute.manager [req-7be814ae-0e3d-4631-8a4c-348ead46c213 - - - - -] Triggering sync for uuid b28cc3ae-6442-40cf-9d66-9d4938a567c7 _sync_power_states /usr/lib/python3.6/site-packages/nova/compute/man
ager.py:9695
2021-07-22 16:31:30.589 3 DEBUG oslo_concurrency.lockutils [-] Lock "b28cc3ae-6442-40cf-9d66-9d4938a567c7" acquired by "nova.compute.manager.ComputeManager._sync_power_states.<locals>._sync.<locals>.query_driver_power_state_and_sync" ::
 waited 0.000s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:359
2021-07-22 16:31:30.746 3 INFO nova.compute.manager [-] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] During _sync_instance_power_state the DB power_state (1) does not match the vm_power_state from the hypervisor (4). Updating power_
state in the DB to match the hypervisor.
2021-07-22 16:31:30.930 3 WARNING nova.compute.manager [-] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Instance shutdown by itself. Calling the stop API. Current vm_state: active, current task_state: None, original DB power_state:
1, current VM power_state: 4
2021-07-22 16:31:30.931 3 DEBUG nova.compute.api [-] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Going to try to stop instance force_stop /usr/lib/python3.6/site-packages/nova/compute/api.py:2584
2021-07-22 16:31:31.135 3 DEBUG oslo_concurrency.lockutils [-] Lock "b28cc3ae-6442-40cf-9d66-9d4938a567c7" released by "nova.compute.manager.ComputeManager._sync_power_states.<locals>._sync.<locals>.query_driver_power_state_and_sync" ::
 held 0.547s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:371
2021-07-22 16:31:31.161 3 DEBUG oslo_concurrency.lockutils [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] Lock "b28cc3ae-6442-40cf-9d66-9d4938a567c7" acquired by "nova.compute.manager.ComputeManager.stop_instance.<locals>.do_stop_
instance" :: waited 0.000s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:359
2021-07-22 16:31:31.162 3 DEBUG nova.compute.manager [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Checking state _get_power_state /usr/lib/python3.6/site-packages/nova/compute/man
ager.py:1561
2021-07-22 16:31:31.165 3 DEBUG nova.compute.manager [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Stopping instance; current vm_state: active, current task_state: powering-off, cu
rrent DB power_state: 4, current VM power_state: 4 do_stop_instance /usr/lib/python3.6/site-packages/nova/compute/manager.py:3095
2021-07-22 16:31:31.166 3 INFO nova.compute.manager [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Instance is already powered off in the hypervisor when stop is called.
2021-07-22 16:31:31.168 3 DEBUG nova.objects.instance [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] Lazy-loading 'flavor' on Instance uuid b28cc3ae-6442-40cf-9d66-9d4938a567c7 obj_load_attr /usr/lib/python3.6/site-packages/nova/$
bjects/instance.py:1103
2021-07-22 16:31:31.236 3 DEBUG nova.objects.instance [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] Lazy-loading 'metadata' on Instance uuid b28cc3ae-6442-40cf-9d66-9d4938a567c7 obj_load_attr /usr/lib/python3.6/site-packages/nov$
/objects/instance.py:1103
2021-07-22 16:31:31.302 3 INFO nova.virt.libvirt.driver [req-a87509b3-9674-49df-ad1f-9f8967871e10 - - - - -] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Instance already shutdown.
2021-07-22 16:31:31.308 3 INFO nova.virt.libvirt.driver [-] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Instance destroyed successfully.

I'll attach the full debug logs as well.

I couldn't see anything on the Controller node relevant to it. Just seems to be the compute node, but I can capture whatever we need.

[Brendan Shephard (bshephar)]

The specific container I'm using:

# podman inspect tripleo-director.ctlplane.localdomain:8787/tripleomaster/openstack-nova-libvirt:current-tripleo | jq .'[0] | "Id=\(.Id) Digest=\(.Digest) Created=\(.Created)"'

Id=0fde1ee060e9b7be5b9d8a64238c8a93a4b386960a37343156965ce049bae5a7 Digest=sha256:e836afb676525339785ea059f01a5350993efb72948fdc02542aa6464aba59ba
Created=2021-06-28T10:11:41.063297253Z"

[Brendan Shephard (bshephar)]

strace from qemu while it's crashing during that nova_libvirt restart:

# strace -p 31635
strace: Process 31635 attached
restart_syscall(<... resuming interrupted read ...>) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=31638, si_uid=0, si_status=143, si_utime=0, si_stime=0} ---
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [CHLD], 8) = 0
getpid() = 31635
gettid() = 31635
tgkill(31635, 31635, SIGUSR1) = 0
rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0
--- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_TKILL, si_pid=31635, si_uid=0} ---
write(17, "\1\0\0\0\0\0\0\0", 8) = 8
rt_sigreturn({mask=[CHLD]}) = 0
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call)
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 143}], WNOHANG, NULL) = 31638
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x5602b99c4420, FUTEX_WAKE_PRIVATE, 2147483647) = 0
wait4(-1, 0x7ffeccd93150, WNOHANG, NULL) = 0
fcntl(8, F_GETFL) = 0 (flags O_RDONLY)
fcntl(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
read(8, 0x7ffeccd91281, 8192) = -1 EAGAIN (Resource temporarily unavailable)
write(2, "[conmon:w]: stdio_input read fai"..., 69) = 69
fcntl(10, F_GETFL) = 0 (flags O_RDONLY)
fcntl(10, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
read(10, 0x7ffeccd91281, 8192) = -1 EAGAIN (Resource temporarily unavailable)
write(2, "[conmon:w]: stdio_input read fai"..., 69) = 69
fsync(6) = 0
close(3) = 0
getpeername(2, 0x7ffeccd92f70, [128]) = -1 ENOTSOCK (Socket operation on non-socket)
futex(0x7f48a8ba9f78, FUTEX_WAKE_PRIVATE, 2147483647) = 0
ioctl(2, TCGETS, 0x7ffeccd92f50) = -1 ENOTTY (Inappropriate ioctl for device)
getpid() = 31635
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0
write(2, "\n(conmon:31635): GLib-CRITICAL *"..., 95) = 95
openat(AT_FDCWD, "/var/run/libpod/exits/a28cd3cfd8caa04fc2d69f229afe898b512b06d998824c72314012046afa70f3.YKC560", O_RDWR|O_CREAT|O_EXCL, 0666) = 3
fallocate(3, 0, 0, 3) = 0
write(3, "143", 3) = 3
fstatfs(3, {f_type=TMPFS_MAGIC, f_bsize=4096, f_blocks=16466847, f_bfree=16466353, f_bavail=16466353, f_files=16466847, f_ffree=16465661, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOSUID|ST_NODEV}) = 0
lstat("/var/run/libpod/exits/a28cd3cfd8caa04fc2d69f229afe898b512b06d998824c72314012046afa70f3", 0x7ffeccd93190) = -1 ENOENT (No such file or directory)
close(3) = 0
rename("/var/run/libpod/exits/a28cd3cfd8caa04fc2d69f229afe898b512b06d998824c72314012046afa70f3.YKC560", "/var/run/libpod/exits/a28cd3cfd8caa04fc2d69f229afe898b512b06d998824c72314012046afa70f3") = 0
unlink("/var/run/libpod/socket/a28cd3cfd8caa04fc2d69f229afe898b512b06d998824c72314012046afa70f3/attach") = 0
close(14) = 0
close(7) = 0
close(4) = 0
wait4(-1, NULL, WNOHANG, NULL) = 0
close(3) ...

[David Vallee Delisle (valleedelisle)]

I've worked with Brendan on his lab and here's some leads:
- normally the qemu-kvm process should not be child of conmon/dumb-init. In his lab, this is the case.
- his containers are using /var/run instead of /run for the bind mounts, but this is probably not an issue here.
- There were other bindmounts differing between envs and we need to investigate into this.

Just a quick note, his lab was deployed 18ish months ago and has been updated consistently since then. That probably explains the difference between the containers.

We unfortunately ran out of time but I believe we should investigate this issue as it might bite us later when we support upgrades to this W or X from T.

[Lee Yarwood (lyarwood)]

Marking this as incomplete for Nova and adding TripleO.

The n-cpu logs just show the compute service reacting to the instances being stopped *already* on the host:

2021-07-22 16:31:30.930 3 WARNING nova.compute.manager [-] [instance: b28cc3ae-6442-40cf-9d66-9d4938a567c7] Instance shutdown by itself. Calling the stop API. Current vm_state: active, current task_state: None, original DB power_state:
1, current VM power_state: 4

1 == RUNNING
4 == SHUTDOWN

https://github.com/openstack/nova/blob/b241663b8929b638a1795c5cc2f859b103a1d468/nova/objects/fields.py#L1026-L1045

[Brendan Shephard (bshephar)]

This is an issue related to the runtime for podman. In my case crun caused the issue, runc works fine:
https://paste.opendev.org/show/807670/

For whatever reason I can't post that comment directly here.

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

[Brendan Shephard (bshephar)]

To elaborate on Davids comment, this is what we're seeing:

Process list:
# ps aufxwww

root 117161 0.0 0.0 4232 864 ? Ss 18:45 0:00 \_ dumb-init --single-child -- kolla_start
root 117164 0.0 0.0 14848 3176 ? S 18:45 0:00 | \_ /bin/bash /nova_libvirt_launcher.sh
root 117274 0.4 0.0 1999656 53624 ? Sl 18:45 1:01 | \_ /usr/sbin/libvirtd
qemu 118813 45.8 1.9 10997496 2547020 ? Sl 18:49 114:36 \_ /usr/libexec/qemu-kvm -name guest=instance-00000023

# pstree

        ├─conmon─┬─dumb-init───nova_libvirt_la───libvirtd───21*[{libvirtd}]
        │ ├─qemu-kvm───9*[{qemu-kvm}]
        │ ├─qemu-kvm───14*[{qemu-kvm}]
        │ └─{conmon}

So those child qemu-kvm processes are killed when the container is restarted.

Checking in an environment not experiencing the issue, we see:

qemu 179267 238 51.0 24276276 16721084 ? Sl Jul21 3693:12 /usr/libexec/qemu-kvm -name guest=instance-00000005,[...]
root 623581 0.0 0.0 143820 2460 ? Ssl 16:58 0:00 /usr/bin/conmon --api-version 1 [...]
root 623593 0.0 0.0 4232 832 ? Ss 16:58 0:00 \_ dumb-init --single-child -- kolla_start
root 623607 0.0 0.0 14848 3304 ? S 16:58 0:00 \_ /bin/bash /nova_libvirt_launcher.sh
root 623661 0.3 0.1 1921820 53492 ? Sl 16:58 0:20 \_ /usr/sbin/libvirtd

This seems to be an issue with the container runtime. If I change to runc instead of crun, I no longer have this problem.

With the runc runtime, this doesn't happen. So the bug seems to be related to crun here. I get the same result as the working environment with runc, and the working environment is also using runc rather than crun.

[Brendan Shephard (bshephar)]

In a CentOS9 env `ps aufxwww`

The process is on it's own and not nested under the conmon process. So the VM isn't impacted by the container restarting / stopping:
qemu 36218 2.7 2.9 1766604 222864 ? Sl 12:20 0:33 /usr/libexec/qemu-kvm -name guest=instance-00000002,debug-threads=on[..]

The container process is seperate in the output:
root 46870 0.0 0.0 81976 2144 ? Ssl 12:37 0:00 /usr/bin/conmon --api-version 1 -c 15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6 -u 15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6 -r /usr/bin/crun -b /var/lib/containers/storage/overlay-containers/15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6/userdata -p /run/containers/storage/overlay-containers/15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6/userdata/pidfile -n nova_libvirt --exit-dir /run/libpod/exits --full-attach -s -l k8s-file:/var/log/containers/stdouts/nova_libvirt.log --log-level warning --runtime-arg --log-format=json --runtime-arg --log --runtime-arg=/run/containers/storage/overlay-containers/15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6/userdata/oci-log --conmon-pidfile /var/run/nova_libvirt.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /var/lib/containers/storage --exit-command-arg --runroot --exit-command-arg /run/containers/storage --exit-command-arg --log-level --exit-command-arg warning --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /run/libpod --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --storage-opt --exit-command-arg overlay.mountopt=nodev,metacopy=on --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg container --exit-command-arg cleanup --exit-command-arg 15b34a5968ddfdf73f414deddc4a29034ca8b2f079ac1b7abad93f192a7bc1e6
root 46873 0.0 0.0 2496 940 ? Ss 12:37 0:00 \_ dumb-init --single-child -- kolla_start
root 46876 0.0 0.0 7116 3304 ? S 12:37 0:00 \_ /bin/bash /nova_libvirt_launcher.sh
root 46901 0.3 0.4 1198156 36368 ? Sl 12:37 0:00 \_ /usr/sbin/libvirtd --listen

So it must be something about crun on CentOS8.