System upgrade after reboot - output is somehow inaccurent

[j-mracek]

1. Output does not contain scriptlets, but scriptlets are in dnf5.log. Scriptlets requires a lot of time (nearly 2 minutes on my fast system) and user might get worried what is going on.

dnf5 system-upgrade log --number=1

Sep 02 10:07:32 jmracek-thinkpadt14gen4.brq.csb dnf5[1346]: [5159/5161] Erasing tzdata-0:2024a-2.fc 100% |  50.7 KiB/s |   1.8 KiB |  00m00s
Sep 02 10:07:32 jmracek-thinkpadt14gen4.brq.csb dnf5[1346]: [5160/5161] Erasing ncurses-base-0:6.4- 100% |   5.3 KiB/s | 179.0   B |  00m00s
Sep 02 10:07:43 jmracek-thinkpadt14gen4.brq.csb dracut[12340]: dracut-102-2.fc40
...
Sep 02 10:09:22 jmracek-thinkpadt14gen4.brq.csb dnf5[1346]: [5161/5161] Erasing libgcc-0:13.3.1-1.f 100% |   0.0   B/s |  11.0   B |  01m50s
Sep 02 10:09:22 jmracek-thinkpadt14gen4.brq.csb dnf5[1346]: Warning: skipped PGP checks for 2687 packages from repository: @stored_transaction
Sep 02 10:09:22 jmracek-thinkpadt14gen4.brq.csb dnf5[1346]: Transaction complete! Cleaning up and rebooting...
Sep 02 10:09:22 jmracek-thinkpadt14gen4.brq.csb systemd[1]: Shutting down.

dnf5.log

2024-09-02T08:07:32+0000 [1346] INFO RPM callback uninstall stop "libgcc-0:13.3.1-1.fc39.x86_64" amount 11 total 11
2024-09-02T08:07:32+0000 [1346] INFO RPM callback start post-uninstall scriptlet "libgcc-0:13.3.1-1.fc39.x86_64"
...
2024-09-02T08:09:21+0000 [1346] INFO RPM callback start trigger-install scriptlet "fedora-third-party-0:0.10-8.fc40.noarch"
2024-09-02T08:09:21+0000 [1346] INFO RPM callback stop trigger-install scriptlet "fedora-third-party-0:0.10-8.fc40.noarch" return code 0
2024-09-02T08:09:21+0000 [1346] INFO RPM callback start trigger-install scriptlet "vlc-libs-1:3.0.21-3.fc40.x86_64"
2024-09-02T08:09:21+0000 [1346] INFO RPM callback stop trigger-install scriptlet "vlc-libs-1:3.0.21-3.fc40.x86_64" return code 0
2024-09-02T08:09:21+0000 [1346] INFO RPM callback start trigger-install scriptlet "graphviz-0:9.0.0-11.fc40.x86_64"
2024-09-02T08:09:21+0000 [1346] INFO RPM callback stop trigger-install scriptlet "graphviz-0:9.0.0-11.fc40.x86_64" return code 0
2024-09-02T08:09:21+0000 [1346] INFO RPM callback start trigger-install scriptlet "gtk3-0:3.24.43-1.fc40.x86_64"
2024-09-02T08:09:21+0000 [1346] INFO RPM callback stop trigger-install scriptlet "gtk3-0:3.24.43-1.fc40.x86_64" return code 0
2024-09-02T08:09:21+0000 [1346] INFO RPM callback start trigger-install scriptlet "ibus-0:1.5.30-6.fc40.x86_64"
2024-09-02T08:09:21+0000 [1346] INFO RPM callback stop trigger-install scriptlet "ibus-0:1.5.30-6.fc40.x86_64" return code 0
2024-09-02T08:09:22+0000 [1346] INFO RPM callback start trigger-install scriptlet "man-db-0:2.12.0-6.fc40.x86_64"
2024-09-02T08:09:22+0000 [1346] INFO RPM callback stop trigger-install scriptlet "man-db-0:2.12.0-6.fc40.x86_64" return code 0
2024-09-02T08:09:22+0000 [1346] INFO Transaction complete! Cleaning up and rebooting...
2024-09-02T08:09:22+0000 [1346] INFO Cleaning up downloaded data...
2024-09-02T08:09:22+0000 [1346] INFO DNF5 finished

2. Logs does not fit with output
   Please carefully investigate timestamp in previous outputs => it says that scriptlets (postrans) were performed between [5160/5161] Erasing ncurses-base-0:6.4- and [5161/5161] Erasing libgcc-0:13.3.1-1.f 100%, but this is incorrect. I am thinking that something is wrong with flushing. dnf5.log shows a different story (correct output).

[m-blaha]

Regarding outputs, offline transactions use their own PlymouthTransCB transaction callbacks, which currently seem to only notify the user about elem_progress events. You're right that scriptlets can take a disturbingly long time to complete, so we should provide clearer information to the user about what's happening.

As far as logs are concerned, the system-upgrade log command simply outputs the section of the systemd journal associated with the given boot ID. Unlike dnf5.log, it doesn't exclusively show dnf5 outputs, so it's possible for logs from other processes (e.g., the line in question generated by dracut) to appear mixed with dnf5 logs.