Bug 1912243

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