Hi Nir,
Thank you very much for your detailed explanations.
The pid 6398 looks like it's HostedEngine:
/audit/audit.log:type=VIRT_CONTROL msg=audit(1644587639.935:7895):
pid=3629 uid=0 auid=4294967295 ses=4294967295
subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm op=start
reason=booted
//*vm="HostedEngine"*//uuid=37a75c8e-50a2-4abd-a887-8a62a75814cc
//*vm-pid=6398*//exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=?
res=success'UID="root" AUID="unset"/
So, I understand that SanLock has problems with the storage (it loses
connection with NFS storage). The watchdog begins to check connectivity
with the MV and after the established time, the order to
reboot the machine.
I don't know if I can somehow increase these timeouts, or try to make
sanlock force the reconnection or renewal with the storage and in this
way try to avoid host reboots for this reason.
Pablo.
El 16/02/2022 a las 23:37, Nir Soffer escribió:
On Wed, Feb 16, 2022 at 9:18 PM Nir Soffer<nsof...@redhat.com> wrote:
On Wed, Feb 16, 2022 at 5:12 PM Nir Soffer<nsof...@redhat.com> wrote:
On Wed, Feb 16, 2022 at 10:10 AM Pablo Olivera<p.oliv...@telfy.com> 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 (mockbu...@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@ovirt.org
To unsubscribe send an email to users-le...@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/FSVKKTSCWHLVVG3FT2W3KAGUKGOFUDU6/
