Bug 1943943 - Hitting "Update All" in Plasma Discover sometimes does nothing, just cycles back
Summary: Hitting "Update All" in Plasma Discover sometimes does nothing, just cycles back
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: plasma-discover
Version: 34
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Rex Dieter
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: openqa RejectedBlocker
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-03-28 16:50 UTC by Adam Williamson
Modified: 2021-04-12 21:57 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug


Attachments (Terms of Use)
tarball of /var/log from a failure with packagekit in debug mode (2.14 MB, application/octet-stream)
2021-03-30 00:53 UTC, Adam Williamson
no flags Details

Description Adam Williamson 2021-03-28 16:50:36 UTC
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.

Comment 1 Geoffrey Marr 2021-03-29 18:35:54 UTC
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

Comment 2 Adam Williamson 2021-03-29 20:43:16 UTC
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).

Comment 3 Adam Williamson 2021-03-29 23:52:57 UTC
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.

Comment 4 Adam Williamson 2021-03-30 00:53:23 UTC
Created attachment 1767510 [details]
tarball of /var/log from a failure with packagekit in debug mode

Comment 5 Adam Williamson 2021-03-30 00:56:53 UTC
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

Comment 6 Adam Williamson 2021-04-01 22:27:51 UTC
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).

Comment 7 Rex Dieter 2021-04-02 14:53:18 UTC
Makes a bit of sense now.  The systray applet is probably what helped force a metadata refresh before, until we disabled it. :-/

Comment 8 Rex Dieter 2021-04-02 14:53:51 UTC
(Assuming these tests are using the live image... otherwise, disregard)

Comment 9 Adam Williamson 2021-04-02 15:39:08 UTC
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.

Comment 10 Rex Dieter 2021-04-12 18:20:16 UTC
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

Comment 11 Adam Williamson 2021-04-12 21:57:20 UTC
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).


Note You need to log in before you can comment on or make changes to this bug.