Description of problem: virtlogd process exits after executing 'systemctl reload' Version-Release number of selected component (if applicable): libvirt-daemon-6.10.0-1.module+el8.4.0+8898+a84e86e1.x86_64 How reproducible: 100% Steps to Reproduce: 1.Start a guest: # virsh start avocado-vt-vm1 Domain avocado-vt-vm1 started 2.Check the virtlogd process: # pidof virtlogd 88893 3.Reload virtlogd: #systemctl reload virtlogd 4.Check the virtlogd process again: #pidof virtlogd no output 5.Check the log: #cat /var/log/messages Jan 4 03:49:51 dell-per440-14 systemd[1]: virtlogd.service: Main process exited, code=exited, status=9/n/a Jan 4 03:49:51 dell-per440-14 systemd[1]: virtlogd.service: Failed with result 'exit-code'. Actual results: virtlogd process exits after executing 'systemctl reload' Expected results: virtlogd process should not exit after executing 'systemctl reload' Additional info:
1) Can you please test it again with libvirt-7.0? 2) Please what is output of: # systemctl reload virtlogd # systemctl status virtlogd 3) Please attach log from virtlogd service, # journalctl -u virtlogd.service Thanks.
(In reply to Jaroslav Suchanek from comment #1) > 1) Can you please test it again with libvirt-7.0? > > 2) Please what is output of: > # systemctl reload virtlogd > # systemctl status virtlogd > > 3) Please attach log from virtlogd service, > # journalctl -u virtlogd.service > > Thanks. [root@dell xml]# systemctl reload virtlogd [root@dell xml]# systemctl status virtlogd ● virtlogd.service - Virtual machine log manager Loaded: loaded (/usr/lib/systemd/system/virtlogd.service; indirect; vendor preset: disabled) Active: failed (Result: exit-code) since Tue 2021-02-23 22:42:17 EST; 6s ago Docs: man:virtlogd(8) https://libvirt.org Process: 70837 ExecReload=/bin/kill -USR1 $MAINPID (code=exited, status=0/SUCCESS) Process: 70830 ExecStart=/usr/sbin/virtlogd $VIRTLOGD_ARGS (code=exited, status=9) Main PID: 70830 (code=exited, status=9) Feb 23 22:42:13 *.com systemd[1]: Started Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: Reloading Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: Reloaded Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: virtlogd.service: Main process exited, code=exited, status=9/n/a Feb 23 22:42:17 *.com systemd[1]: virtlogd.service: Failed with result 'exit-code'. [root@dell xml]# journalctl -u virtlogd.service -- Logs begin at Sun 2021-02-21 22:23:03 EST, end at Tue 2021-02-23 22:42:17 EST. -- Feb 22 05:01:07 *.com systemd[1]: Started Virtual machine log manager. Feb 23 22:41:08 *.com systemd[1]: Reloading Virtual machine log manager. Feb 23 22:41:08 *.com systemd[1]: Reloaded Virtual machine log manager. Feb 23 22:41:08 *.com systemd[1]: virtlogd.service: Main process exited, code=exited, status=9/n/a Feb 23 22:41:08 *.com systemd[1]: virtlogd.service: Failed with result 'exit-code'. Feb 23 22:41:50 *.com systemd[1]: virtlogd.service: Unit cannot be reloaded because it is inactive. Feb 23 22:42:13 *.com systemd[1]: Started Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: Reloading Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: Reloaded Virtual machine log manager. Feb 23 22:42:17 *.com systemd[1]: virtlogd.service: Main process exited, code=exited, status=9/n/a Feb 23 22:42:17 *.com systemd[1]: virtlogd.service: Failed with result 'exit-code'.
This is a regression caused by: commit 94e45d1042e21e03a15ce993f90fbef626f1ae41 Author: Nikolay Shirokovskiy <nshirokovskiy> Date: Thu Jul 23 09:53:04 2020 +0300 rpc: finish all threads before exiting main loop Currently we have issues like [1] on libvirtd shutdown as we cleanup while RPC and other threads are still running. Let's finish all threads other then main before cleanup. The approach to finish threads is suggested in [2]. In order to finish RPC threads serving API calls we let the event loop run but stop accepting new API calls and block processing any pending API calls. We also inform all drivers of shutdown so they can prepare for shutdown too. Then we wait for all RPC threads and driver's background thread to finish. If finishing takes more then 15s we just exit as we can't safely cleanup in time. The commit causes all daemons to terminate and close their FDs rather than persisting since we are exec-restarting. The same bug will be in virtlockd too.
The problem is both int virtlogd (reported here) and virtlockd (which shares the same code) The following patches fix the problem in virtlogd fully and in virtlockd partially: commit ccc6dd8f11f32f9387fd05de4ad98d61d4e88b69 Author: Peter Krempa <pkrempa> Date: Wed Mar 10 17:14:18 2021 +0100 virtlo(g|ck)d: Fix exec-restart Commit 94e45d1042e broke exec-restart of virtlogd and virtlockd as the code waiting for the daemon shutdown closed the daemons before exec-restarting. Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1912243 Fixes: 94e45d1042e Signed-off-by: Peter Krempa <pkrempa> Reviewed-by: Michal Privoznik <mprivozn> commit c363f03e6d0298416179c7f7b24f00da9d85a14f Author: Peter Krempa <pkrempa> Date: Wed Mar 10 17:01:23 2021 +0100 virnetdaemon: Introduce virNetDaemonQuitExecRestart Recent changes which meant to fix daemon shutdown broke the exec-restart capability of virtlogd and virtlockd, since the code actually closed all the sockets and shut down all the internals. Add virNetDaemonQuitExecRestart, which requests a shutdown of the process, but keeps all the services open and registered since they are preserved across the restart. Signed-off-by: Peter Krempa <pkrempa> Reviewed-by: Michal Privoznik <mprivozn> Another two patches are needed for virtlockd: commit eab7ae6bfe13503ea705e70e32edaa60357cbaa1 Author: Peter Krempa <pkrempa> Date: Fri Mar 12 10:16:11 2021 +0100 virLockSpaceNewPostExecRestart: Fix out-of-bounds array access 'res->owners' is allocated to 'res->nOwners' elements, but unfortunately 'res->nOwners' doesn't contain the proper value until after the allocation so 0 elements are allocated. The following loop which assumes that the array has the right number of elements then accesses the pointer out of bounds. The bug was also faithfully converted from VIR_ALLOC_N to g_new0. Fixes: 4a3d6ed5ee0 Signed-off-by: Peter Krempa <pkrempa> Reviewed-by: Michal Privoznik <mprivozn> commit 6b8e961399549c5c8fdf06875e5981c564829ad6 Author: Peter Krempa <pkrempa> Date: Fri Mar 12 10:12:51 2021 +0100 virLockSpacePreExecRestart: Avoid use-after-free Recent refactor marked 'object' which is returned from the function as autofree but forgot to use g_steal_pointer in the return statement to prevent freeing it. Fixes: 9a1651f64d7 Signed-off-by: Peter Krempa <pkrempa> Reviewed-by: Michal Privoznik <mprivozn>
Exception approved in review meeting on 12 Mar 2021.
Verified with libvirt-daemon-7.0.0-10.module+el8.4.0+10417+37f6984d.x86_64. Test steps: Scenario 1： Test for virtlogd 1.#systemctl reload virtlogd 2.# systemctl status virtlogd ● virtlogd.service - Virtual machine log manager Loaded: loaded (/usr/lib/systemd/system/virtlogd.service; indirect; vendor preset: disabled) Active: active (running) since Mon 2021-03-15 23:18:17 EDT; 6 days ago Docs: man:virtlogd(8) https://libvirt.org Process: 123853 ExecReload=/bin/kill -USR1 $MAINPID (code=exited, status=0/SUCCESS) Main PID: 7883 (virtlogd) Tasks: 1 (limit: 409591) Memory: 2.3M CGroup: /system.slice/virtlogd.service └─7883 /usr/sbin/virtlogd Mar 15 23:18:17 *.com systemd[1]: Started Virtual machine log manager. Mar 21 23:15:51 * systemd[1]: Reloading Virtual machine log manager. Mar 21 23:15:51 * systemd[1]: Reloaded Virtual machine log manager. ... [root@dell-per730-30 ~]# journalctl -u virtlogd.service -- Logs begin at Mon 2021-03-15 18:01:54 EDT, end at Mon 2021-03-22 03:14:10 EDT. -- Mar 15 23:18:17 *.com systemd[1]: Started Virtual machine log manager. Mar 21 23:15:51 *.com systemd[1]: Reloading Virtual machine log manager. Mar 21 23:15:51 *.com systemd[1]: Reloaded Virtual machine log manager. Mar 22 03:11:08 *.com systemd[1]: Reloading Virtual machine log manager. Mar 22 03:11:08 *.com systemd[1]: Reloaded Virtual machine log manager. Scenario 2: Test for virtlockd: 1.# systemctl reload virtlockd 2.# systemctl status virtlockd ● virtlockd.service - Virtual machine lock manager Loaded: loaded (/usr/lib/systemd/system/virtlockd.service; indirect; vendor preset: disabled) Active: active (running) since Mon 2021-03-22 03:12:30 EDT; 4min 25s ago Docs: man:virtlockd(8) https://libvirt.org Process: 123880 ExecReload=/bin/kill -USR1 $MAINPID (code=exited, status=0/SUCCESS) Main PID: 123826 (virtlockd) Tasks: 1 (limit: 409591) Memory: 2.0M CGroup: /system.slice/virtlockd.service └─123826 /usr/sbin/virtlockd Mar 22 03:12:30 *.redhat.com systemd[1]: Started Virtual machine lock manager. Mar 22 03:12:32 *.redhat.com systemd[1]: Reloading Virtual machine lock manager. Mar 22 03:12:32 *.redhat.com systemd[1]: Reloaded Virtual machine lock manager. 3.# journalctl -u virtlockd.service -- Logs begin at Mon 2021-03-15 18:01:54 EDT, end at Mon 2021-03-22 03:16:48 EDT. -- Mar 22 03:12:30 *.redhat.com systemd[1]: Started Virtual machine lock manager. Mar 22 03:12:32 *.redhat.com systemd[1]: Reloading Virtual machine lock manager. Mar 22 03:12:32 *.redhat.com systemd[1]: Reloaded Virtual machine lock manager.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (virt:av bug fix and enhancement update), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2021:2098