In openQA, there is a test which tries to check GNOME Software can correctly find and install updates (not upgrades), with whatever packages are in the update being tested. Note the test is *not* checking that GNOME Software can install the *update under test itself*, but that *with that update installed*, GNOME Software can still find and install a 'dummy' update. The test does this: 1) Boot a clean disk image of the release under test (created by virt-manager) 2) Log in as a user account created as part of the install 3) Run through the user-mode gnome-initial-setup that appears on this first login 4) From the clean desktop, switch to a VT, log in as root 5) Fiddle with the repo definitions a bit (switch from metalink to mirrorlist) 5) Install Bodhi CLI client, download the packages from the update to a scratch directory, create a local repo for the directory 6) Run 'dnf -y update' 7) Reboot 8) Log into the desktop again 9) Switch to a VT, log in as root 10) With dnf, remove python3-kickstart, if it is installed 11) With dnf, install a dummy python3-kickstart-1.1 package from a special side repo 12) Switch back to the desktop 13) Run gnome-software, go to the Updates pane 14) Click the 'refresh' button At this point, what the test expects to happen is: gnome-software should notice that an update is available for python3-kickstart (as we know for sure the distro will contain a higher-versioned python3-kickstart package) and show that an update is available for install. At which point the test clicks the 'apply' button and carries on from there. However, many times when this test runs on F27 and F28, that is not what happens. Instead, after 14), gnome-software thinks for a bit and then shows the "Software is up to date" screen. i.e. it does *not* think an update is available. If I add a workaround to the test which makes it retry when this happens - spot the 'Software is up to date' screen, and click the 'refresh' button again - then it seems to always work on the *second* try. The update is found and the test proceeds. I believe at least for some time, openQA was running into https://bugzilla.redhat.com/show_bug.cgi?id=1314991 here. For a while we actually got the "Cancelled by user action" error mentioned in comment #7 there, and the workaround cued off that. But I'm not so sure that's the case any *more*. We aren't seeing that error, and after I poked at the problem a bit and did some debugging, I'm not convinced it's a 'transaction collision' problem that we're seeing now. I have tweaked the test a bit on the staging instance so it restarts PackageKit in debugging mode (with --verbose) and runs gnome-software with --verbose also, and captures the output from those. I have also been testing with custom gnome-software builds that actually add additional debugging statements: these are all prefaced with 'XXX:' for easy identification. I will attach the patch file so you can see at what points in the code I actually added these statements. Basically, from the logs, it seems like on the *first* refresh attempt, gnome-software does notice in some sense that an update is available for python3-kickstart. But when the 'generic update' plugin - which does the work of gathering updates for things that don't have appdata into a generic "OS Updates" entry - runs the `gs_plugin_generic_updates_merge_os_update` function which is supposed to tell it whether it should include a given package update into that, it returns FALSE, and that's the problem. The "list of packages to be put into the generic OS Updates app" winds up being empty, which means the generic OS Updates 'app' is not created (this is all in `gs_plugin_refine`), and so we're told no updates are available. On the *second* refresh attempt, `gs_plugin_generic_updates_merge_os_update` returns TRUE, and python3-kickstart *is* added into the list for the 'OS Updates' entry, which - because the list is not empty - now actually gets created and shows up in the UI. I have not yet figured out *why* this is happening. From my debug log statements, it seems that it is hitting this conditional on the first attempt: /* this is only for grouping system-installed packages */ if (gs_app_get_bundle_kind (app) != AS_BUNDLE_KIND_PACKAGE || gs_app_get_scope (app) != AS_APP_SCOPE_SYSTEM) { g_debug ("XXX merge_os_update returning FALSE!"); return FALSE; } (note the added log statement, which we see in the logs), and so it returns FALSE. But on the second attempt, it does not hit that one - it gets past it and hits this one instead: if (gs_app_get_kind (app) == AS_APP_KIND_GENERIC) { g_debug ("XXX merge_os_update returning TRUE (generic)!"); return TRUE; } and returns TRUE. So somehow, the 'bundle kind' is not 'package' or the 'scope' is not 'system' on the *first* try, but on the *second* try, both those things are true. I don't know why this might be, yet. This bug does not appear to be affecting F29 yet, but I'm not *sure* if that means it's actually been fixed, or if there might be some sort of difference in how the images or repos behave or something in F29.
Created attachment 1493063 [details] the diff showing the debug statements I added to gnome-software for testing
Created attachment 1493077 [details] the verbose output from gnome-software, with my added debug statements
Created attachment 1493078 [details] PackageKit log messages from the run Timings for the run (to try and cross compare with the logs): 1. First boot reaches g-i-s about 21:05:11 2. First boot reaches desktop and switches to VT about 21:06:24 3. First boot finishes installing updates and reboots at 21:13:21.0441 4. Second boot reaches clean desktop about 21:14:55 5. Second boot finishes setting up the dummy update about 21:16:45 6. gnome-software launched about 21:17:51 7. First 'refresh' attempt at 21:18:04 8. 'Software is up to date' screen appears within the 60 seconds before 21:20:08.0377 (cannot be more precise) 9. Second 'refresh' attempt at 21:20:09
I just did a variant run of the test where I had it just sit at the front page of Software for two minutes before switching to the Updates screen, in case that made it work on the first refresh...but nope. Still failed on the first refresh, worked on the second.
I think this may be an ordering issue. I just added a few more debug statements, notably in gs-plugin-packagekit-refine.c gs_plugin_refine_app() , which is the most obvious thing that would *set* the scope and kind for an update like this, and that looks like a bingo. In this run, the *first* 'refresh' click was at 01:33:36.0868 and the *second* was at 01:34:02.0142 . Check this log extract: 01:34:00:0168 As run 0x55dfcfdde450~GsPlugin::generic-updates(gs_plugin_add_updates;gs_plugin_refine) 01:34:00:0168 Gs XXX in app_list loop for app (null)! 01:34:00:0168 Gs XXX in merge_os_update for app (null) / python3-kickstart 01:34:00:0168 Gs XXX merge_os_update returning FALSE! 01:34:00:0168 Gs XXX kind was: (null) 01:34:00:0168 Gs XXX scope was: (null) 01:34:00:0168 Gs XXX in app_list loop for app (null)! 01:34:00:0168 Gs XXX in merge_os_update for app (null) / python3-ordered-set 01:34:00:0168 Gs XXX merge_os_update returning FALSE! 01:34:00:0168 Gs XXX kind was: (null) 01:34:00:0168 Gs XXX scope was: (null) 01:34:00:0168 Gs XXX returning TRUE at point 2! 01:34:00:0168 As run 0x55dfcfdde450~GsPlugin::packagekit-refine(gs_plugin_add_updates;gs_plugin_refine) 01:34:00:0168 As run 0x55dfcfdde450~packagekit-refine[name->id] 01:34:00:0168 As run 0x55dfcfdde450~packagekit-refine[id->update-details] 01:34:00:0168 PK role now get-update-detail 01:34:00:0181 Gs emitting global waiting 01:34:00:0275 As run 0x55dfcd1ac230~packagekit-refine[source->license] 01:34:00:0276 As run 0x55dfcd1ac230~packagekit-refine[update-urgency] 01:34:00:0276 Gs plugin packagekit-refine took 2.2 seconds to do refine 01:34:00:0276 GsPluginPackageKit XXX In PK gs_plugin_refine_app for app (null) / python3-kickstart 01:34:00:0276 GsPluginPackageKit XXX set scope to SYSTEM 01:34:00:0276 Gs XXX In gs_app_set_bundle_kind for app (null) / python3-kickstart 01:34:00:0276 GsPluginPackageKit XXX set kind to PACKAGE 01:34:00:0276 GsPluginPackageKit XXX In PK gs_plugin_refine_app for app (null) / python3-ordered-set 01:34:00:0276 GsPluginPackageKit XXX set scope to SYSTEM 01:34:00:0276 Gs XXX In gs_app_set_bundle_kind for app (null) / python3-ordered-set 01:34:00:0276 GsPluginPackageKit XXX set kind to PACKAGE 01:34:00:0276 Gs emitting global finished ... 01:34:08:0931 As run 0x55dfd0c55000~GsPlugin::generic-updates(gs_plugin_add_updates;gs_plugin_refine) 01:34:08:0931 Gs XXX in app_list loop for app (null)! 01:34:08:0931 Gs XXX in merge_os_update for app (null) / python3-kickstart 01:34:08:0931 Gs XXX merge_os_update returning TRUE (generic)! 01:34:08:0931 Gs XXX in app_list loop for app (null)! 01:34:08:0931 Gs XXX in merge_os_update for app (null) / python3-ordered-set 01:34:08:0931 Gs XXX merge_os_update returning TRUE (generic)! 01:34:08:0932 Gs XXX reached point 3 'create new meta object'! 01:34:08:0932 As run GsPlugin::packagekit-history(gs_plugin_refine;gs_plugin_refine) 01:34:08:0932 Gs autogenerating unique-id for org.gnome.Software.OsUpdate 01:34:08:0932 Gs */*/*/os-update/org.gnome.Software.OsUpdate/* non-transient state now updatable-live 01:34:08:0932 As run GsPlugin::packagekit-refine-repos(gs_plugin_refine;gs_plugin_refine) 01:34:08:0932 As run packagekit-refine-repos[repo-filename->id] 01:34:08:0932 Gs moving python3-kickstart to parent */*/*/os-update/org.gnome.Software.OsUpdate/* 01:34:08:0932 Gs 2nd resolve pass for unadopted wildcards 01:34:08:0932 Gs moving python3-ordered-set to parent */*/*/os-update/org.gnome.Software.OsUpdate/* Basically, it looks to me like on the *first* refresh, we find the package update, then run the generic-updates plugin - which does not add the package to 'OS Updates' because its kind and scope are null - *then* run packagekit-refine , which sets the kind and scope to PACKAGE and SYSTEM...but too late for this round, because generic-updates *already ran* and didn't work right. But now the kind and scope have been set, on the *second* refresh, generic-updates does the right thing and adds the package to "OS Updates". So...basically to fix this, packagekit-refine needs to happen before generic-updates...I think.
Hah - and gnome-software git master has exactly that added: gs_plugin_add_rule (plugin, GS_PLUGIN_RULE_RUN_AFTER, "packagekit-refine"); It was part of this commit: https://gitlab.gnome.org/GNOME/gnome-software/commit/37103e6e5f15d39843d468775da2b53ab145bd2a so I think it wasn't actually intended to fix this, but I think will have had the *effect* of fixing this. I'm going to try making just that change on top of the F28 package, and see if it makes this problem go away...
Aha - and there's a plausible explanation for why this broke, too - this commit: https://gitlab.gnome.org/GNOME/gnome-software/commit/9eab01082b07acd525b8a390ab6b43136cf400a5 which appeared in 3.28.1. That's the commit that *added* this check for 'scope' and 'kind' - it should have also ensured that generic-updates ran after packagekit-refine, but it didn't. I will send an MR upstream to fix this on the 3-28 branch, and do updates for F27 and F28...
https://gitlab.gnome.org/GNOME/gnome-software/merge_requests/116
gnome-software-3.28.2-4.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-5a93cc4270
gnome-software-3.28.2-4.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-d2d222fe5c
gnome-software-3.28.2-4.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-5a93cc4270
gnome-software-3.28.2-4.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-d2d222fe5c
gnome-software-3.28.2-4.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.
gnome-software-3.28.2-4.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.