search

rpm-software-management / dnf5

Next-generation RPM package management system
Other
238 stars 79 forks source link

dnf5 with --installroot does not log rpm transaction messages #1717

Open m-blaha opened 1 week ago

m-blaha commented 1 week ago

During the rpm transaction execution, dnf does not write rpm messages to log when the --installroot option is used. The logging stops after packages verification and starts again once the transaction finishes.

This is part of dnf.log for command dnf install acpi --installroot=/tmp/INSTALLROOT --use-host-config:

2024-09-20T10:30:35+0000 [714356] INFO --- DNF5 launched with arguments: "dnf install acpi --installroot=/tmp/INSTALLROOT" ---
------------- 8<------------------
2024-09-20T10:30:53+0000 [714413] DEBUG [librepo] lr_download: Downloading started
2024-09-20T10:30:53+0000 [714413] DEBUG [librepo] Transfer finished: Packages/a/acpi-1.7-21.fc39.x86_64.rpm (Effective url: https://mirror.karneval.cz/pub/linux/fedora/linux/releases/39/Everything/x86_64/os/Packages/a/acpi-1.7-21.fc39.x86_64.rpm)
2024-09-20T10:30:53+0000 [714413] DEBUG [librepo] check_finished_transfer_checksum: Checksum (sha256) 2a7b32f1b42732dc50529e6005a895602f886221951fbe97b378d4bfb6e58efe is OK
2024-09-20T10:30:53+0000 [714413] DEBUG [librepo] lr_download_packages: Restoring an old SIGINT handler
2024-09-20T10:30:53+0000 [714413] INFO RPM callback verify start, total 1
2024-09-20T10:30:53+0000 [714413] INFO RPM callback open file "/tmp/INSTALLROOT/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:30:53+0000 [714413] INFO RPM callback close file
2024-09-20T10:30:53+0000 [714413] INFO RPM callback verify stop, total 1
2024-09-20T10:30:53+0000 [714413] INFO RPM callback open file "/tmp/INSTALLROOT/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:30:53+0000 [714413] INFO RPM callback close file
2024-09-20T10:30:53+0000 [714413] INFO RPM callback verify start, total 1
2024-09-20T10:30:53+0000 [714413] INFO RPM callback open file "/tmp/INSTALLROOT/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:30:53+0000 [714413] INFO RPM callback close file
2024-09-20T10:30:53+0000 [714413] INFO RPM callback verify stop, total 1
2024-09-20T10:30:53+0000 [714413] INFO RPM callback open file "/tmp/INSTALLROOT/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:30:53+0000 [714413] INFO RPM callback close file
2024-09-20T10:30:54+0000 [714413] INFO DNF5 finished

If run without --installroot option:

2024-09-20T10:24:45+0000 [47] INFO --- DNF5 launched with arguments: "dnf5 install acpi" ---
------------- 8< ------------------
2024-09-20T10:24:52+0000 [47] DEBUG [librepo] lr_download: Downloading started
2024-09-20T10:24:52+0000 [47] DEBUG [librepo] Transfer finished: Packages/a/acpi-1.7-21.fc39.x86_64.rpm (Effective url: https://mirror.karneval.cz/pub/linux/fedora/linux/releases/39/Everything/x86_64/os/Packages/a/acpi-1.7-21.fc39.x86_64.rpm)
2024-09-20T10:24:52+0000 [47] DEBUG [librepo] check_finished_transfer_checksum: Checksum (sha256) 2a7b32f1b42732dc50529e6005a895602f886221951fbe97b378d4bfb6e58efe is OK
2024-09-20T10:24:52+0000 [47] DEBUG [librepo] lr_download_packages: Restoring an old SIGINT handler
2024-09-20T10:24:52+0000 [47] INFO RPM callback verify start, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback open file "/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:24:52+0000 [47] INFO RPM callback close file
2024-09-20T10:24:52+0000 [47] INFO RPM callback verify stop, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback transaction start, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback transaction stop, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback open file "/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:24:52+0000 [47] INFO RPM callback close file
2024-09-20T10:24:52+0000 [47] INFO RPM callback verify start, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback open file "/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:24:52+0000 [47] INFO RPM callback close file
2024-09-20T10:24:52+0000 [47] INFO RPM callback verify stop, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback transaction start, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback transaction stop, total 1
2024-09-20T10:24:52+0000 [47] INFO RPM callback open file "/var/cache/libdnf5/fedora-845d89688cb28f31/packages/acpi-1.7-21.fc39.x86_64.rpm"
2024-09-20T10:24:52+0000 [47] INFO RPM callback install start "acpi-0:1.7-21.fc39.x86_64" total 54172
2024-09-20T10:24:52+0000 [47] INFO RPM callback install stop "acpi-0:1.7-21.fc39.x86_64" amount 54172 total 54172
2024-09-20T10:24:52+0000 [47] INFO RPM callback close file
2024-09-20T10:24:52+0000 [47] INFO RPM callback start trigger-install scriptlet "glibc-common-0:2.38-11.fc39.x86_64"
2024-09-20T10:24:52+0000 [47] INFO RPM callback stop trigger-install scriptlet "glibc-common-0:2.38-11.fc39.x86_64" return code 0
2024-09-20T10:24:52+0000 [47] INFO DNF5 finished

As you can see, part from transaction start to the end of the transaction is missing.

I think the reason is that RotatingFileLogger::Impl::write() method, used to write the line to the log file, opens and closes the log file for each message. But during the transaction RPM enters chroot which alters the path resolution process. As a result, DNF5 cannot open the log file and code https://github.com/rpm-software-management/dnf5/blob/877f85559aaa11182d6a30cf6ec27a313158e410/libdnf5/logger/rotating_file_logger.cpp#L72-L75 fails with errno set to ENOENT (No such file or directory), because the log file path is incorrect in chrooted environment.