Safer reload handling

[SkewedZeppelin]

I've been using fapolicyd for a few months now under Fedora 39.

I've encountered an issue that happens probably 1 in every 3 or 4 times when running eg. dnf update or dnf install.
fapolicyd will reload after dnf completes, but something happens and all future executions are entirely denied locking up the system

I think it might actually be a race condition where sometimes after dnf runs, dnf makecache is immediately automatically invoked.
So fapolicyd is already in the middle of reloading and tries to reload again or maybe makecache takes a lock on the rpm database and prevents reading?

It seems more likely to occur on my faster desktop than it does on my slower laptop as well.

Apr 05 05:54:03 localhost sudo[29251]:      admin : TTY=pts/2 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/bin/dnf update --enablerepo=*updates-testing kernel* -y
Apr 05 05:58:08 localhost systemd[1]: Starting dnf-makecache.service - dnf makecache...
Apr 05 05:58:08 localhost fapolicyd[2187]: It looks like there was an update of the system... Syncing DB.
Apr 05 05:58:08 localhost fapolicyd[2187]: Loading rpmdb backend
Apr 05 05:58:09 localhost dnf[58832]: Divested RPM Repository                         3.0 kB/s | 968  B     00:00
Apr 05 05:58:09 localhost dnf[58832]: Fedora 39 - x86_64                              103 kB/s |  24 kB     00:00
Apr 05 05:58:10 localhost dnf[58832]: Fedora 39 openh264 (From Cisco) - x86_64        6.4 kB/s | 989  B     00:00
Apr 05 05:58:10 localhost dnf[58832]: Fedora 39 - x86_64 - Updates                    121 kB/s |  23 kB     00:00
Apr 05 05:58:10 localhost fapolicyd[2187]: Updating trust database
Apr 05 05:58:10 localhost fapolicyd[2187]: Creating trust database
Apr 05 05:58:10 localhost fapolicyd[2187]: Loading trust data from rpmdb backend
Apr 05 05:58:11 localhost fapolicyd[2187]: Loading trust data from file backend
Apr 05 05:58:11 localhost fapolicyd[2187]: Updated
Apr 05 05:58:11 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=-1 pid=58862 exe=/usr/lib/systemd/systemd : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:58:11 localhost dnf[58832]: RPM Fusion for Fedora 39 - Free                 3.1 kB/s | 3.6 kB     00:01
Apr 05 05:58:12 localhost dnf[58832]: RPM Fusion for Fedora 39 - Free - Updates       3.5 kB/s | 3.0 kB     00:00
Apr 05 05:58:12 localhost dnf[58832]: Meadminata cache created.
Apr 05 05:58:13 localhost systemd[1]: dnf-makecache.service: Deactivated successfully.
Apr 05 05:58:13 localhost systemd[1]: Finished dnf-makecache.service - dnf makecache.
Apr 05 05:58:13 localhost audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 05 05:58:13 localhost audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 05 05:58:13 localhost systemd[1]: dnf-makecache.service: Consumed 2.057s CPU time.
Apr 05 05:58:45 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58875 exe=/usr/bin/bash : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:58:48 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58877 exe=/usr/bin/bash : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:58:50 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58879 exe=/usr/bin/bash : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:58:51 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58880 exe=/usr/bin/bash : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:58:51 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58881 exe=/usr/bin/bash : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:59:03 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58958 exe=/usr/libexec/gnome-session-binary : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0
Apr 05 05:59:03 localhost fapolicyd[2187]: rule=16 dec=deny_log perm=execute auid=1000 pid=58978 exe=/usr/lib/systemd/systemd : path=/usr/lib64/ld-linux-x86-64.so.2 ftype=application/x-sharedlib trust=0

edit: package versions

rpm -qa | grep -i -e fapolicyd -e dnf -e rpm | grep -v srpm | sort -u
deltarpm-3.6.3-11.fc39.x86_64
dnf-4.19.2-1.fc39.noarch
dnf5-5.1.17-1.fc39.x86_64
dnf5-plugins-5.1.17-1.fc39.x86_64
dnf-data-4.19.2-1.fc39.noarch
dnf-plugins-core-4.6.0-1.fc39.noarch
dnf-utils-4.6.0-1.fc39.noarch
drpm-0.5.2-3.fc39.x86_64
fapolicyd-1.3.2-2.fc39.x86_64
fapolicyd-selinux-1.3.2-2.fc39.noarch
libdnf-0.73.1-1.fc39.x86_64
libdnf5-5.1.17-1.fc39.x86_64
libdnf5-cli-5.1.17-1.fc39.x86_64
pyproject-rpm-macros-1.12.0-1.fc39.noarch
python3-dnf-4.19.2-1.fc39.noarch
python3-dnf-plugins-core-4.6.0-1.fc39.noarch
python3-libdnf-0.73.1-1.fc39.x86_64
python3-rpm-4.19.1.1-1.fc39.x86_64
python3-rpmautospec-0.6.3-1.fc39.noarch
python3-rpmautospec-core-0.1.4-1.fc39.noarch
python3-rpm-generators-14-7.fc39.noarch
python3-rpm-macros-3.12-4.fc39.noarch
python-qt5-rpm-macros-5.15.10-2.fc39.noarch
python-rpm-macros-3.12-4.fc39.noarch
redhat-rpm-config-266-1.fc39.noarch
rpm-4.19.1.1-1.fc39.x86_64
rpmautospec-0.6.3-1.fc39.noarch
rpmautospec-rpm-macros-0.6.3-1.fc39.noarch
rpm-build-4.19.1.1-1.fc39.x86_64
rpm-build-libs-4.19.1.1-1.fc39.x86_64
rpmdevtools-9.6-4.fc39.noarch
rpm-libs-4.19.1.1-1.fc39.x86_64
rpmlint-2.5.0-5.fc39.noarch
rpmlint-fedora-license-data-1.44-1.fc39.noarch
rpm-plugin-fapolicyd-4.19.1.1-1.fc39.x86_64
rpm-plugin-selinux-4.19.1.1-1.fc39.x86_64
rpm-plugin-systemd-inhibit-4.19.1.1-1.fc39.x86_64
rpm-sequoia-1.6.0-1.fc39.x86_64
rpm-sign-libs-4.19.1.1-1.fc39.x86_64
systemd-rpm-macros-254.10-1.fc39.noarch

[stevegrubb]

@radosroka Is the dnf plugin still shipped in Fedora? Or do you think rpm is doing this? If it is rpm, maybe we need to see how it retriggers a load.

[radosroka]

rpm-plugin-fapolicyd is present on the list.

@SkewedZeppelin can you provide fapolicyd logs when running in debug mode?

[radosroka]

@SkewedZeppelin would you check whether #297 fix your issue?

[SkewedZeppelin]

@radosroka
I actually haven't hit this yet since updating to F40, but I think it is still a chance thing.
I've compiled and installed it, will run with it a few days and see if I hit it again or not. Thank you.

[SkewedZeppelin]

Closing, haven't encountered this at all under F40. Thank you.

[SkewedZeppelin]

Just hit this for this first time on f40 with fapolicyd-1.3.3-4.fc40
So it still happens just far less common

[radosroka]

@SkewedZeppelin thank you for the update. I will continue with investigation.

[SkewedZeppelin]

I've been experiencing this more frequently.

Can there be an sanity check added to not make the reload effective if its entry count is substantially smaller ie. likely broken?
or maybe a failsafe that exempts some basics like sync and shutdown binaries so that a somewhat clean shutdown can be performed instead of a hard power off