[ovirt-users] Re: Random reboots

On Wed, Feb 16, 2022 at 9:18 PM Nir Soffer <nsoffer(a)redhat.com&gt; wrote: > > On Wed, Feb 16, 2022 at 5:12 PM Nir Soffer <nsoffer(a)redhat.com&gt; wrote: >> >> On Wed, Feb 16, 2022 at 10:10 AM Pablo Olivera <p.olivera(a)telfy.com&gt; wrote: >>> >>> Hi community, >>> >>> We're dealing with an issue as we occasionally have random reboots on >>> any of our hosts. >>> We're using ovirt 4.4.3 in production with about 60 VM distributed over >>> 5 hosts. We've a virtualized engine and a DRBD storage mounted by NFS. >>> The infrastructure is interconnected by a Cisco 9000 switch. >>> The last random reboot was yesterday February 14th at 03:03 PM (in the >>> log it appears as: 15:03 due to our time configuration) of the host: >>> 'nodo1'. >>> At the moment of the reboot we detected in the log of the switch a >>> link-down in the port where the host is connected. >>> I attach log of the engine and host 'nodo1' in case you can help us to >>> find the cause of these random reboots. >> >> >> According to messages: >> >> 1. Sanlock could not renew the lease for 80 seconds: >> >> Feb 14 15:03:06 nodo1 sanlock[2017]: 2022-02-14 15:03:06 1655257 >> [2017]: s1 check_our_lease failed 80 >> >> >> 2. In this case sanlock must terminate the processes holding a lease >> on the that storage - I guess that pid 6398 is vdsm. >> >> Feb 14 15:03:06 nodo1 sanlock[2017]: 2022-02-14 15:03:06 1655257 >> [2017]: s1 kill 6398 sig 15 count 1 >> Feb 14 15:03:06 nodo1 sanlock[2017]: 2022-02-14 15:03:06 1655258 >> [2017]: s1 kill 6398 sig 15 count 2 > > pid 6398 is not vdsm: > > Feb 14 15:02:51 nodo1 vdsm[4338] > > The fact that we see "sig 15" means sanlock is trying to send SIGTERM. > If pid 6398 is a VM (hosted engine vm?) we would expect to see: > >> [2017]: s1 kill 6398 sig 100 count 1 > > Exactly once - which means run the killpath program registered by libvirt, > which will terminate the vm. I reproduce this issue locally - we never use killpath program, because we don't configure libvirt on_lockfailure in the domain xml. So we get the default behavior, which is sanlock terminating the vm. > > So my guess is that this is not a VM, so the only other option is hosted > engine broker, using a lease on the whiteboard. > >> ... >> Feb 14 15:03:36 nodo1 sanlock[2017]: 2022-02-14 15:03:36 1655288 >> [2017]: s1 kill 6398 sig 15 count 32 >> >> 3. Terminating pid 6398 stopped here, and we see: >> >> Feb 14 15:03:36 nodo1 wdmd[2033]: test failed rem 19 now 1655288 ping >> 1655237 close 1655247 renewal 1655177 expire 1655257 client 2017 >> sanlock_a5c35d19-4c34-4571-ac77-1b10de484426:1 > > According to David, this means we have 19 more attempts to kill the process > holding the lease. > >> >> 4. So it looks like wdmd rebooted the host. >> >> Feb 14 15:08:09 nodo1 kernel: Linux version >> 4.18.0-193.28.1.el8_2.x86_64 (mockbuild(a)kbuilder.bsys.centos.org) (gcc >> version 8.3.1 20191121 (Red Hat 8.3.1-5) (GCC)) #1 SMP Thu Oct 22 >> 00:20:22 UTC 2020 >> >> >> This is strange, since sanlock should try to kill pid 6398 40 times, >> and then switch >> to SIGKILL. The watchdog should not reboot the host before sanlock >> finish the attempt to kill the processes. >> >> David, do you think this is expected? do we have any issue in sanlock? > > I discussed it with David (sanlock author). What we see here may be truncated > logs when a host is rebooted by the watchdog. The last time logs were synced > to storage was probably Feb 14 15:03:36. Any message written after that was > lost in the host page cache. > > >> It is possible that sanlock will not be able to terminate a process if >> the process is blocked on inaccessible storage. This seems to be the >> case here. >> >> In vdsm log we see that storage is indeed inaccessible: >> >> 2022-02-14 15:03:03,149+0100 WARN (check/loop) [storage.check] >> Checker '/rhev/data-center/mnt/newstoragedrbd.andromeda.com:_var_nfsshare_data/a5c35d19-4c34-4571-ac77-1b10de484426/dom_md/metadata' >> is blocked for 60.00 seconds (check:282) >> >> But we don't see any termination request - so this host is not the SPM. >> >> I guess this host was running the hosted engine vm, which uses a storage lease. >> If you lose access to storage, sanlcok will kill the hosted engine vm, >> so the system >> can start it elsewhere. If the hosted engine vm is stuck on storage, sanlock >> cannot kill it and it will reboot the host. > > Pablo, can you locate the process with pid 6398? > > Looking in hosted engine logs and other logs on the system may reveal what > was this process. When we find the process, we can check the source to > understand > why it was not terminating - likely blocked on the inaccessible NFS server. The process is most likely a VM - I reproduced the exact scenario locally. You can file a vdsm bug for this. The system behave as designed, but the design is problematic; one VM with a lease stuck on NFS server can cause the entire host to be rebooted. With block storage we don't have this issue, since we have exact control over multipath timeouts. Multipath will fail I/O in 80 seconds, after sanlock failed to renew the lease. When I/O fails, the process block on storage will unblocked an will be terminated by the kernel.

On NFS the timeouts are very unpredictable, and it can take more than 180 seconds until the io fails. During this time the VM is stuck in D state, and in this state it cannot be stopped or killed, so the host watchdog timeout and the host is rebooted. Related bugs: https://bugzilla.redhat.com/1569926 Sanlock timeouts: https://pagure.io/sanlock/blob/master/f/src/timeouts.h Libvirt events configuration: https://libvirt.org/formatdomain.html#events-configuration Nir _______________________________________________ Users mailing list -- users(a)ovirt.org To unsubscribe send an email to users-leave(a)ovirt.org Privacy Statement: https://www.ovirt.org/privacy-policy.html oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/message/4XXUOLDWCS6...