In the openQA graphical update test - where we make sure an update is available, then run the package management tool and try to apply it - quite often in Plasma Discover, when the test goes to the updates view and hits "Update All", it doesn't really do anything. It seems to spin briefly then go back to exactly the same screen, with the "Update All" button still shown. I had to adjust the test to keep clicking on the button until something else happens. Eventually we reach the "The system requires a restart to apply updates" button, but it often takes three or four clicks on the "Update All" button before that actually happens. Proposing as a Final blocker as a violation of Beta criterion "The installed system must be able appropriately to install, remove, and update software with the default tool for the relevant software type in all release-blocking desktops (e.g. default graphical package manager). This includes downloading of packages to be installed/updated" - https://fedoraproject.org/wiki/Fedora_34_Beta_Release_Criteria#Installing.2C_removing_and_updating_software . I'm not sure having to click the button multiple times to make it work is an acceptable workaround. Someone might give up after two or three tries and conclude that it's just broken. It's not a good look.
Discussed during the 2021-03-29 blocker review meeting: [0] The decision to classify this bug as an "AcceptedBlocker (Final)" was made as it violates the following criterion: "The installed system must be able to...update software with the default tool for the relevant software type in all release-blocking desktops" [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2021-03-29/f34-blocker-review.2021-03-29-16.00.txt
CCing hughsie as this may be a PackageKit issue, especially since the GNOME test had issues today too (filing a separate bug for that right now).
this is the console output from plasma-discover in a session that hit the bug, though I don't think there's anything too enlightening: file:///usr/lib64/qt5/qml/org/kde/kirigami.2/ActionToolBar.qml:109:18: QML ToolBarLayout: Binding loop detected for property "actions" adding empty sources model QStandardItemModel(0x55de30a200f0) could not list fwupd remotes Error calling StartServiceByName for org.freedesktop.fwupd: Timeout was reached adding empty sources model FwupdSourcesModel(0x55de3083abb0) kf.newstuff.core: The CustomName property is deprecated and will be removed in KF6 invalid kns backend! "/usr/share/knsrcfiles/servicemenu.knsrc" because: "Config group not found! Check your KNS3 installation." kf.newstuff.core: The ChecksumPolicy feature is defunct kf.newstuff.core: The SignaturePolicy feature is defunct kf.newstuff.core: The ChecksumPolicy feature is defunct kf.newstuff.core: The SignaturePolicy feature is defunct org.kde.plasma.libdiscover: Couldn't find a category for "fwupd-backend" file:///usr/lib64/qt5/qml/org/kde/kirigami.2/private/PrivateActionToolButton.qml:74:5: QML Binding: Binding loop detected for property "value" org.kde.plasma.discover: couldn't open file "/home/test/.cache/discover/featured-5.9.json" "No such file or directory" org.kde.plasma.discover: couldn't open file "/home/test/.cache/discover/featured-5.9.json" "No such file or directory" org.kde.plasma.discover: couldn't open file "/home/test/.cache/discover/featured-5.9.json" "No such file or directory" The Theme singleton is deprecated (since 5.39). Import Kirigami 2.2 or higher and use the attached property instead. file:///usr/lib64/qt5/qml/org/kde/kirigami.2/ActionToolBar.qml:109:18: QML ToolBarLayout: Binding loop detected for property "actions" file:///usr/lib64/qt5/qml/org/kde/kirigami.2/ActionToolBar.qml:109:18: QML ToolBarLayout: Binding loop detected for property "actions" file:///usr/lib64/qt5/qml/org/kde/kirigami.2/ActionToolBar.qml:109:18: QML ToolBarLayout: Binding loop detected for property "actions" I also didn't see anything obviously useful in the journal, so I'll try and get PackageKit running verbose and then get those logs.
Created attachment 1767510 [details] tarball of /var/log from a failure with packagekit in debug mode
I attached the /var/log tarball, you can inspect the journal with journalctl --file var/log/journal/blahblah, but here are the packagekit lines from around when discover starts up (I think): Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit CreateTransaction method called Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit job count now 2 Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit job count is now at 1 Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit transaction now new Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit setting sender to :1.84 Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit adding transaction 0x55e3eb287160 Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit sending object path: '/2_ccaeaebb' Mar 29 17:43:32 fedora packagekitd[1956]: 20:43:32 PackageKit notify::connected Mar 29 17:43:32 fedora systemd[1]: Started Firmware update daemon. Mar 29 17:43:32 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=fwupd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit locale changed to en_US.UTF-8 Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit GetUpdates method called Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit transaction now ready Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit changing transaction to exclusive mode Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit 1 transactions in list, 1 committed but not finished Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit transaction now running Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit install uid now 1000 Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit install cmdline now PackageKit: get-updates Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit setting role for /2_ccaeaebb to get-updates Mar 29 17:43:33 fedora packagekitd[1956]: 20:43:33 PackageKit-DNF got state query with hint (null) Mar 29 17:43:34 fedora packagekitd[1956]: 20:43:34 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:34 fedora packagekitd[1956]: 20:43:34 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:35 fedora packagekitd[1956]: 20:43:35 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:35 fedora packagekitd[1956]: 20:43:35 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:35 fedora packagekitd[1956]: 20:43:35 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:35 fedora packagekitd[1956]: 20:43:35 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:35 fedora packagekitd[1956]: 20:43:35 PackageKit-DNF created cached sack DnfSack::release_ver[34]::filelists|remote Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit emit package available, python3-kickstart;3.32-2.fc34;noarch;fedora, Python 3 library for manipulating kickstart files. Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit backend was running for 2993 ms Mar 29 17:43:36 fedora PackageKit[1956]: get-updates transaction /2_ccaeaebb from uid 1000 finished with success after 2993ms Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit emitting finished 'success', 2993 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit transaction now finished Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit 1 transactions in list, 0 committed but not finished Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit CreateTransaction method called Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit job count now 3 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit job count is now at 2 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit transaction now new Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit setting sender to :1.84 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit adding transaction 0x55e3eb2872e0 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit sending object path: '/3_adeddddd' Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit CreateTransaction method called Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit job count now 4 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit job count is now at 2 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit transaction now new Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit setting sender to :1.84 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit adding transaction 0x55e3eb287460 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit sending object path: '/4_adeccace' Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit locale changed to en_US.UTF-8 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit Resolve method called: 262144, python3-kickstart Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit transaction now ready Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit changing transaction to exclusive mode Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit 3 transactions in list, 1 committed but not finished Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit transaction now running Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit install uid now 1000 Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit install cmdline now PackageKit: resolve Mar 29 17:43:36 fedora packagekitd[1956]: 20:43:36 PackageKit setting role for /3_adeddddd to resolve Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit locale changed to en_US.UTF-8 Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit-DNF got state query with hint (null) Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit Resolve method called: 524288, python3-kickstart Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit transaction now ready Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit changing transaction to exclusive mode Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit 3 transactions in list, 2 committed but not finished Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:37 fedora packagekitd[1956]: 20:43:37 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF got state loading-cache with hint (null) Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF created cached sack DnfSack::release_ver[34]::filelists|remote|unavailable Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit emit package installed, python3-kickstart;1-1;noarch;installed:openqa-testrepo-1, Dummy summary Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit emit package available, python3-kickstart;3.32-2.fc34;noarch;fedora, Python 3 library for manipulating kickstart files. Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit backend was running for 1874 ms Mar 29 17:43:38 fedora PackageKit[1956]: resolve transaction /3_adeddddd from uid 1000 finished with success after 1874ms Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit emitting finished 'success', 1874 Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit transaction now finished Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit running /4_adeccace as previous one finished Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit transaction now running Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit 3 transactions in list, 1 committed but not finished Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit install uid now 1000 Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit install cmdline now PackageKit: resolve Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit setting role for /4_adeccace to resolve Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote|unavailable Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit backend was running for 12 ms Mar 29 17:43:38 fedora PackageKit[1956]: resolve transaction /4_adeccace from uid 1000 finished with success after 12ms Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit emitting finished 'success', 12 Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit transaction now finished Mar 29 17:43:38 fedora packagekitd[1956]: 20:43:38 PackageKit 3 transactions in list, 0 committed but not finished Mar 29 17:43:41 fedora packagekitd[1956]: 20:43:41 PackageKit transaction /2_ccaeaebb completed, removing Mar 29 17:43:41 fedora packagekitd[1956]: 20:43:41 PackageKit emitting destroy /2_ccaeaebb Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit CreateTransaction method called Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit job count now 5 Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit job count is now at 4 Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit transaction now new Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit setting sender to :1.84 Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit adding transaction 0x55e3eb2875e0 Mar 29 17:43:42 fedora packagekitd[1956]: 20:43:42 PackageKit sending object path: '/5_abceacbc' Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit locale changed to en_US.UTF-8 Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit GetDetails method called: python3-kickstart;3.32-2.fc34;noarch;fedora Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit transaction now ready Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit changing transaction to exclusive mode Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit 3 transactions in list, 1 committed but not finished Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit transaction now running Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit install uid now 1000 Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit install cmdline now PackageKit: get-details Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit setting role for /5_abceacbc to get-details Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote|unavailable Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit emitting details Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit backend was running for 39 ms Mar 29 17:43:43 fedora PackageKit[1956]: get-details transaction /5_abceacbc from uid 1000 finished with success after 39ms Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit emitting finished 'success', 39 Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit transaction now finished Mar 29 17:43:43 fedora packagekitd[1956]: 20:43:43 PackageKit 3 transactions in list, 0 committed but not finished Mar 29 17:43:44 fedora packagekitd[1956]: 20:43:44 PackageKit transaction /3_adeddddd completed, removing Mar 29 17:43:44 fedora packagekitd[1956]: 20:43:44 PackageKit emitting destroy /3_adeddddd Mar 29 17:43:44 fedora packagekitd[1956]: 20:43:44 PackageKit transaction /4_adeccace completed, removing Mar 29 17:43:44 fedora packagekitd[1956]: 20:43:44 PackageKit emitting destroy /4_adeccace Mar 29 17:43:48 fedora packagekitd[1956]: 20:43:48 PackageKit transaction /5_abceacbc completed, removing Mar 29 17:43:48 fedora packagekitd[1956]: 20:43:48 PackageKit emitting destroy /5_abceacbc Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit CreateTransaction method called Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit job count now 6 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit job count is now at 5 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now new Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit setting sender to :1.84 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit adding transaction 0x55e3eb2875e0 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit sending object path: '/6_aaecedce' Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit notify::connected Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit locale changed to en_US.UTF-8 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit UpdatePackages method called: python3-kickstart;3.32-2.fc34;noarch;fedora (transaction_flags: simulate) Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit changing transaction to exclusive mode Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit No authentication required Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now ready Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit changing transaction to exclusive mode Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit 1 transactions in list, 1 committed but not finished Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now running Mar 29 17:44:02 fedora PackageKit[1956]: new update-packages transaction /6_aaecedce scheduled from uid 1000 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit install uid now 1000 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit install cmdline now PackageKit: update-packages Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit setting role for /6_aaecedce to update-packages Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit emit package updating, python3-kickstart;3.32-2.fc34;noarch;fedora, Python 3 library for manipulating kickstart files. Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit backend was running for 52 ms Mar 29 17:44:02 fedora PackageKit[1956]: in /6_aaecedce for update-packages package python3-kickstart;3.32-2.fc34;noarch;fedora was updating for uid 1000 Mar 29 17:44:02 fedora PackageKit[1956]: update-packages transaction /6_aaecedce from uid 1000 finished with success after 52ms Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit emitting finished 'success', 52 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now finished Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit 1 transactions in list, 0 committed but not finished Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit CreateTransaction method called Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit job count now 7 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit job count is now at 6 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now new Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit setting sender to :1.84 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit adding transaction 0x55e3eb287460 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit sending object path: '/7_acecaedd' Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit locale changed to en_US.UTF-8 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit UpdatePackages method called: python3-kickstart;3.32-2.fc34;noarch;fedora (transaction_flags: only-trusted;only-download) Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit changing transaction to exclusive mode Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit No authentication required Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now ready Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit changing transaction to exclusive mode Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit 2 transactions in list, 1 committed but not finished Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit transaction now running Mar 29 17:44:02 fedora PackageKit[1956]: new update-packages transaction /7_acecaedd scheduled from uid 1000 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit install uid now 1000 Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit install cmdline now PackageKit: update-packages Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit setting role for /7_acecaedd to update-packages Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit-DNF got state download with hint python3-kickstart;3.32-2.fc34;noarch;fedora Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit emit package downloading, python3-kickstart;3.32-2.fc34;noarch;fedora, Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit-DNF got state download with hint python3-kickstart;3.32-2.fc34;noarch;fedora Mar 29 17:44:02 fedora packagekitd[1956]: 20:44:02 PackageKit-DNF got state request with hint (null) Mar 29 17:44:03 fedora packagekitd[1956]: 20:44:03 PackageKit-DNF got state test-commit with hint (null) Mar 29 17:44:03 fedora packagekitd[1956]: 20:44:03 PackageKit emitting allow-cancel 0 Mar 29 17:44:03 fedora packagekitd[1956]: 20:44:03 PackageKit opened logind fd 31 Mar 29 17:44:03 fedora packagekitd[1956]: 20:44:03 PackageKit 2 transactions in list, 1 committed but not finished Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit emitting allow-cancel 1 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit closed logind fd 31 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit 2 transactions in list, 1 committed but not finished Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit backend was running for 2260 ms Mar 29 17:44:04 fedora PackageKit[1956]: update-packages transaction /7_acecaedd from uid 1000 finished with success after 2260ms Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit emitting finished 'success', 2260 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit transaction now finished Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit 2 transactions in list, 0 committed but not finished Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit CreateTransaction method called Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit job count now 8 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit job count is now at 7 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit transaction now new Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit setting sender to :1.84 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit adding transaction 0x55e3eb2872e0 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit sending object path: '/8_daaaeddd' Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit locale changed to en_US.UTF-8 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit GetUpdates method called Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit transaction now ready Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit changing transaction to exclusive mode Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit 3 transactions in list, 1 committed but not finished Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit transaction now running Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit install uid now 1000 Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit install cmdline now PackageKit: get-updates Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit setting role for /8_daaaeddd to get-updates Mar 29 17:44:04 fedora packagekitd[1956]: 20:44:04 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit emit package available, python3-kickstart;3.32-2.fc34;noarch;fedora, Python 3 library for manipulating kickstart files. Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit backend was running for 95 ms Mar 29 17:44:05 fedora PackageKit[1956]: get-updates transaction /8_daaaeddd from uid 1000 finished with success after 95ms Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit emitting finished 'success', 95 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now finished Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit 3 transactions in list, 0 committed but not finished Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit CreateTransaction method called Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit job count now 9 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit job count is now at 8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now new Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit setting sender to :1.84 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit adding transaction 0x55e3eb287160 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit sending object path: '/9_abacbbae' Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit CreateTransaction method called Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit job count now 10 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit trying to open database '/var/lib/PackageKit/transactions.db' Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit job count is now at 8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now new Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit setting sender to :1.84 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit adding transaction 0x55e3eb287760 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit sending object path: '/10_dcaadabb' Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit locale changed to en_US.UTF-8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit Resolve method called: 262144, python3-kickstart Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now ready Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit changing transaction to exclusive mode Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit 5 transactions in list, 1 committed but not finished Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now running Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit SetHints method called: locale=en_US.UTF-8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit locale changed to en_US.UTF-8 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit Resolve method called: 524288, python3-kickstart Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit transaction now ready Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit changing transaction to exclusive mode Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit 5 transactions in list, 2 committed but not finished Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit install uid now 1000 Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit install cmdline now PackageKit: resolve Mar 29 17:44:05 fedora packagekitd[1956]: 20:44:05 PackageKit setting role for /9_abacbbae to resolve Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote|unavailable Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit emit package installed, python3-kickstart;1-1;noarch;installed:openqa-testrepo-1, Dummy summary Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit emit package available, python3-kickstart;3.32-2.fc34;noarch;fedora, Python 3 library for manipulating kickstart files. Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit backend was running for 50 ms Mar 29 17:44:06 fedora PackageKit[1956]: resolve transaction /9_abacbbae from uid 1000 finished with success after 50ms Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit emitting finished 'success', 50 Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit transaction now finished Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit running /10_dcaadabb as previous one finished Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit transaction now running Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit 5 transactions in list, 1 committed but not finished Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit install uid now 1000 Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit install cmdline now PackageKit: resolve Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit setting role for /10_dcaadabb to resolve Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit-DNF using cached sack DnfSack::release_ver[34]::filelists|remote|unavailable Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit backend was running for 12 ms Mar 29 17:44:06 fedora PackageKit[1956]: resolve transaction /10_dcaadabb from uid 1000 finished with success after 12ms Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit emitting finished 'success', 12 Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit transaction now finished Mar 29 17:44:06 fedora packagekitd[1956]: 20:44:06 PackageKit 5 transactions in list, 0 committed but not finished Mar 29 17:44:07 fedora packagekitd[1956]: 20:44:07 PackageKit transaction /6_aaecedce completed, removing Mar 29 17:44:07 fedora packagekitd[1956]: 20:44:07 PackageKit emitting destroy /6_aaecedce Mar 29 17:44:10 fedora packagekitd[1956]: 20:44:10 PackageKit transaction /7_acecaedd completed, removing Mar 29 17:44:10 fedora packagekitd[1956]: 20:44:10 PackageKit emitting destroy /7_acecaedd Mar 29 17:44:10 fedora packagekitd[1956]: 20:44:10 PackageKit transaction /8_daaaeddd completed, removing Mar 29 17:44:10 fedora packagekitd[1956]: 20:44:10 PackageKit emitting destroy /8_daaaeddd Mar 29 17:44:11 fedora packagekitd[1956]: 20:44:11 PackageKit transaction /9_abacbbae completed, removing Mar 29 17:44:11 fedora packagekitd[1956]: 20:44:11 PackageKit emitting destroy /9_abacbbae Mar 29 17:44:11 fedora packagekitd[1956]: 20:44:11 PackageKit transaction /10_dcaadabb completed, removing Mar 29 17:44:11 fedora packagekitd[1956]: 20:44:11 PackageKit emitting destroy /10_dcaadabb
Further update on this - hitting the Refresh button seems to fix things when running into this bug. After hitting that, the next hit of "Update All" works. That's how I have the openQA tests implemented now (if they hit "Update All" and it doesn't seem to work, they hit Refresh and try again).
Makes a bit of sense now. The systray applet is probably what helped force a metadata refresh before, until we disabled it. :-/
(Assuming these tests are using the live image... otherwise, disregard)
This test runs after install from the live image, and we also actually run 'pkcon refresh' from the console before starting the graphical environment. The app definitely knows an update is available, it shows it. It's just that hitting "Update All" doesn't trigger the update process properly.
consider using: pkcon refresh force (instead of just 'pkcon refresh')? Seems recent PK cache's is more aggressive recently.... since a release... (or 2?) ago
We re-considered this at today's blocker review meeting: https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2021-04-12/f34-blocker-review.2021-04-12-16.02.html It was rejected as a blocker, now, because we don't have any indication that people are hitting it in regular use (it may be triggered by some detail of openQA's test process), and we think anyone who does hit it will quite 'naturally' hit on the workaround (just hit the refresh button and try again).
This message is a reminder that Fedora Linux 34 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a 'version' of '34'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, change the 'version' to a later Fedora Linux version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora Linux 34 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora Linux, you are encouraged to change the 'version' to a later version prior to this bug being closed.
It's a bit tricky to tell if this bug is still present because I've changed the openQA workflow a bit, aside from implementing the workaround: I made it *always* refresh before trying to download updates. That seems to prevent this happening even on F34, where I'm pretty sure no fix was implemented, so it's hard to say whether the bug still exists if we *don't* do that.
Fedora Linux 34 entered end-of-life (EOL) status on 2022-06-07. Fedora Linux 34 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. Thank you for reporting this bug and we are sorry it could not be fixed.