Log rotation sometimes doesn't respect the log_size option

[pkratoch]

Sometimes, one or more of the logs are a bit bigger than the log_size even though the last message is not bigger than the log_size itself. It happens when the last couple of messages are RPM callbacks.

I noticed this when reviewing the log-rotate test for dnf5 ( https://github.com/rpm-software-management/ci-dnf-stack/blob/main/dnf-behave-tests/dnf/log-rotate.feature ). I am preparing a patch that will adjust the test to dnf5, so the problem will be visible there, but in the meantime, I can describe it here. When a package is installed and removed couple of times with --setopt=log_size=1024 --setopt=log_rotate=2, the log files look like this:

# ls -l /tmp/dnf_ci_installroot_0ar4vnrf/var/log
total 12
-rw-r--r--. 1 root root   49 Nov  1 09:33 dnf5.log
-rw-r--r--. 1 root root 2302 Nov  1 09:33 dnf5.log.1
-rw-r--r--. 1 root root  952 Nov  1 09:33 dnf5.log.2

# cat /tmp/dnf_ci_installroot_0ar4vnrf/var/log/dnf5.log
2024-11-01T09:33:18+0000 [35] INFO DNF5 finished
[root@cdd4c76339ec dnf-behave-tests]# cat /tmp/dnf_ci_installroot_0ar4vnrf/var/log/dnf5.log.2
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "copr" ("/usr/lib64/dnf5/plugins/copr_cmd_plugin.so") version "0.1.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin file="/usr/lib64/dnf5/plugins/needs_restarting_cmd_plugin.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "needs_restarting" ("/usr/lib64/dnf5/plugins/needs_restarting_cmd_plugin.so") version "1.0.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin file="/usr/lib64/dnf5/plugins/repoclosure_cmd_plugin.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "repoclosure" ("/usr/lib64/dnf5/plugins/repoclosure_cmd_plugin.so") version "1.0.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin library file="/usr/lib64/libdnf5/plugins/actions.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded libdnf plugin "actions" ("/usr/lib64/libdnf5/plugins/actions.so"), version="1.2.0"
2024-11-01T09:33:18+0000 [35] DEBUG Trying to load more plugins using the "actions" plugin.

# cat /tmp/dnf_ci_installroot_0ar4vnrf/var/log/dnf5.log.2
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "copr" ("/usr/lib64/dnf5/plugins/copr_cmd_plugin.so") version "0.1.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin file="/usr/lib64/dnf5/plugins/needs_restarting_cmd_plugin.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "needs_restarting" ("/usr/lib64/dnf5/plugins/needs_restarting_cmd_plugin.so") version "1.0.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin file="/usr/lib64/dnf5/plugins/repoclosure_cmd_plugin.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded dnf5 plugin "repoclosure" ("/usr/lib64/dnf5/plugins/repoclosure_cmd_plugin.so") version "1.0.0"
2024-11-01T09:33:18+0000 [35] DEBUG Loading plugin library file="/usr/lib64/libdnf5/plugins/actions.so"
2024-11-01T09:33:18+0000 [35] INFO Loaded libdnf plugin "actions" ("/usr/lib64/libdnf5/plugins/actions.so"), version="1.2.0"
2024-11-01T09:33:18+0000 [35] DEBUG Trying to load more plugins using the "actions" plugin.
[root@cdd4c76339ec dnf-behave-tests]# cat /tmp/dnf_ci_installroot_0ar4vnrf/var/log/dnf5.log.1
2024-11-01T09:33:18+0000 [35] DEBUG End of loading plugins using the "actions" plugin.
2024-11-01T09:33:18+0000 [35] DEBUG Creating repo "dnf-ci-fedora" from config file "/tmp/dnf_ci_installroot_0ar4vnrf/etc/yum.repos.d/dnf-ci-fedora.repo" section "dnf-ci-fedora"
2024-11-01T09:33:18+0000 [35] DEBUG Loading system repo rpmdb from root "/"
2024-11-01T09:33:18+0000 [35] DEBUG Cannot find "/boot/vmlinuz-6.11.4-201.fc40.x86_64" to verify running kernel
2024-11-01T09:33:18+0000 [35] DEBUG Cannot find "/lib/modules/6.11.4-201.fc40.x86_64" to verify running kernel
2024-11-01T09:33:18+0000 [35] DEBUG Failed to find rpm package of a running kernel in sack
2024-11-01T09:33:18+0000 [35] INFO RPM callback transaction start, total 6
2024-11-01T09:33:18+0000 [35] INFO RPM callback transaction stop, total 6
2024-11-01T09:33:18+0000 [35] INFO RPM callback transaction start, total 6
2024-11-01T09:33:18+0000 [35] INFO RPM callback transaction stop, total 6
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "glibc-common-0:2.28-9.fc29.x86_64" total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "glibc-common-0:2.28-9.fc29.x86_64" amount 100 total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "glibc-0:2.28-9.fc29.x86_64" total 2
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "glibc-0:2.28-9.fc29.x86_64" amount 2 total 2
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "glibc-all-langpacks-0:2.28-9.fc29.x86_64" total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "glibc-all-langpacks-0:2.28-9.fc29.x86_64" amount 100 total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "basesystem-0:11-6.fc29.noarch" total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "basesystem-0:11-6.fc29.noarch" amount 100 total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "filesystem-0:3.9-2.fc29.x86_64" total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "filesystem-0:3.9-2.fc29.x86_64" amount 100 total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall start "setup-0:2.12.1-1.fc29.noarch" total 100
2024-11-01T09:33:18+0000 [35] INFO RPM callback uninstall stop "setup-0:2.12.1-1.fc29.noarch" amount 100 total 100

# cat /tmp/dnf_ci_installroot_0ar4vnrf/var/log/dnf5.log
2024-11-01T09:33:18+0000 [35] INFO DNF5 finished

When I tried different combinations of operations, if any of the logs was bigger, it was always the one that ended with these RPM callback messages. But I am not sure if it's always the case.

[m-blaha]

The root cause here is that dnf process is switched to chroot by rpm during the transaction execution. This changes the path resolution and effectively disables log rotation. See #1772 for details.
Important here is that CI tests run in the installroot.

[m-blaha]

Running the test with @no_installroot should help.