Bug 1749868 - GNOME Software doesn't prepare offline updates
Summary: GNOME Software doesn't prepare offline updates
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: gnome-software
Version: 31
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Richard Hughes
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: RejectedBlocker
Depends On: 1752249
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-09-06 15:46 UTC by Jiri Eischmann
Modified: 2019-09-30 23:16 UTC (History)
13 users (show)

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


Attachments (Terms of Use)
Error message (42.80 KB, image/png)
2019-09-06 15:46 UTC, Jiri Eischmann
no flags Details


Links
System ID Priority Status Summary Last Updated
Red Hat Bugzilla 1750414 None CLOSED inaccessible workstation repos make gnome-software and dnf unusable 2019-09-28 19:32:57 UTC

Description Jiri Eischmann 2019-09-06 15:46:14 UTC
Created attachment 1612448 [details]
Error message

GNOME Software fails to prepare offline updates. I click "Reboot and install" and am prompted to restart the computer, but the computer boots into the desktop session without installing any updates.
I'm attaching a screenshot of the error message Software is showing.

Comment 1 Kamil Páral 2019-09-09 07:42:37 UTC
This works fine for me in a clean F31 VM. Must be something specific to Jiri's system.

Comment 2 Lukas Ruzicka 2019-09-09 10:19:47 UTC
I have also seen this message on my Fedora, which is always the newest Beta version including updates-testing. The system started as Fedora 25 and has been continuously updated until Fedora 31. The error could possibly be affected by this, but I did not have any such messages, until I downgraded packages and distrosynced them for testing purposes to test other bugs reported by @kparal. 

So I tend to believe that this has something to do with the distrosync and downgrade of the packages.

Unfortunately, the error is only displayed in GUI, I could not see it in journal or pkmon.

Comment 3 Lukas Ruzicka 2019-09-09 10:21:08 UTC
PackageKit journal logs:

-- Logs begin at Mon 2018-07-16 23:05:42 CEST, end at Mon 2019-09-09 11:20:49 CEST. --
Sep 09 11:15:10 platypus systemd[1]: Starting PackageKit Daemon...
Sep 09 11:15:10 platypus PackageKit[1482]: daemon start
Sep 09 11:15:10 platypus systemd[1]: Started PackageKit Daemon.
Sep 09 11:15:35 platypus PackageKit[1482]: uid 1000 is trying to obtain org.freedesktop.packagekit.system-sources-refresh auth (only_trusted:0)
Sep 09 11:15:35 platypus PackageKit[1482]: uid 1000 obtained auth for org.freedesktop.packagekit.system-sources-refresh
Sep 09 11:15:41 platypus PackageKit[1482]: refresh-cache transaction /10437_abadeddb from uid 1000 finished with success after 6141ms
Sep 09 11:15:41 platypus PackageKit[1482]: resolve transaction /10438_ebebbabb from uid 1000 finished with failed after 338ms
Sep 09 11:15:42 platypus PackageKit[1482]: resolve transaction /10439_cebdaaee from uid 1000 finished with failed after 346ms
Sep 09 11:15:42 platypus PackageKit[1482]: resolve transaction /10440_adebebac from uid 1000 finished with failed after 370ms
Sep 09 11:15:43 platypus PackageKit[1482]: resolve transaction /10441_deadbacc from uid 1000 finished with failed after 1219ms
Sep 09 11:15:45 platypus PackageKit[1482]: get-updates transaction /10442_aabcabbd from uid 1000 finished with success after 1515ms
Sep 09 11:15:45 platypus PackageKit[1482]: resolve transaction /10443_dadeabda from uid 1000 finished with failed after 304ms
Sep 09 11:15:45 platypus PackageKit[1482]: resolve transaction /10444_ccbcabac from uid 1000 finished with failed after 356ms
Sep 09 11:15:47 platypus PackageKit[1482]: resolve transaction /10445_bebacbde from uid 1000 finished with failed after 377ms
Sep 09 11:16:45 platypus PackageKit[1482]: resolve transaction /10446_bcdeacce from uid 1000 finished with failed after 376ms
Sep 09 11:17:01 platypus PackageKit[1482]: uid 1000 is trying to obtain org.freedesktop.packagekit.system-sources-refresh auth (only_trusted:0)
Sep 09 11:17:01 platypus PackageKit[1482]: uid 1000 obtained auth for org.freedesktop.packagekit.system-sources-refresh
Sep 09 11:17:04 platypus PackageKit[1482]: refresh-cache transaction /10447_eabcacea from uid 1000 finished with success after 3159ms
Sep 09 11:17:10 platypus PackageKit[1482]: uid 1000 is trying to obtain org.freedesktop.packagekit.system-sources-refresh auth (only_trusted:0)
Sep 09 11:17:10 platypus PackageKit[1482]: uid 1000 obtained auth for org.freedesktop.packagekit.system-sources-refresh
Sep 09 11:17:35 platypus PackageKit[1482]: refresh-cache transaction /10448_ddedaaab from uid 1000 finished with success after 24927ms
Sep 09 11:17:41 platypus PackageKit[1482]: resolve transaction /10449_eebcecce from uid 1000 finished with failed after 1261ms
Sep 09 11:17:46 platypus PackageKit[1482]: get-updates transaction /10450_aabeeecb from uid 1000 finished with success after 846ms
Sep 09 11:17:47 platypus PackageKit[1482]: resolve transaction /10451_abedbbee from uid 1000 finished with failed after 306ms
Sep 09 11:18:27 platypus PackageKit[1482]: uid 1000 is trying to obtain org.freedesktop.packagekit.system-sources-refresh auth (only_trusted:0)
Sep 09 11:18:27 platypus PackageKit[1482]: uid 1000 obtained auth for org.freedesktop.packagekit.system-sources-refresh
Sep 09 11:19:14 platypus PackageKit[1482]: refresh-cache transaction /10452_aaddbade from uid 1000 finished with success after 46935ms
Sep 09 11:19:25 platypus PackageKit[1482]: get-updates transaction /10453_eacebebb from uid 1000 finished with success after 842ms
Sep 09 11:19:27 platypus PackageKit[1482]: resolve transaction /10454_ddcedbbe from uid 1000 finished with failed after 307ms
Sep 09 11:19:27 platypus PackageKit[1482]: get-updates transaction /10455_ecabeaed from uid 1000 finished with success after 279ms
Sep 09 11:19:29 platypus PackageKit[1482]: resolve transaction /10456_bedcdecc from uid 1000 finished with failed after 281ms
Sep 09 11:19:50 platypus PackageKit[1482]: resolve transaction /10457_dddbbeda from uid 1000 finished with failed after 1301ms

Comment 4 Lukas Ruzicka 2019-09-09 10:48:41 UTC
I have found a reproducer:

1. Install Fedora Workstation 31 (latest compose)
2. Use gnome-software to install updates -> it will find some updates and install them without any problems.
3. Then disable testing repos and distrosync the system, it will downgrade some packages.
4. Attempt to update your system again -> you will hit this problem.

Comment 5 Jiri Eischmann 2019-09-09 11:37:57 UTC
My system has been upgraded since Fedora 26, so it could indeed have something to do with upgrades. I'm also adding that it started occurring for me on F30 and fairly recently (1-2 months ago).

Comment 6 Kamil Páral 2019-09-09 12:47:28 UTC
I still couldn't reproduce this, but I'll mark this as a potential blocker, because we now have 2 people who experienced it.

Comment 7 Jiri Eischmann 2019-09-09 13:09:15 UTC
It seems I've found a culprit of the problem: it fails when you have repos that are unavailable which are currently in F31 even repos that are enabled after the user opts in to use 3rd party software (phracek's PyCharm Copr repo, RPM Fusion Nvidia repo...). When I disabled them, the error disappeared.

Comment 8 Kamil Páral 2019-09-09 13:52:37 UTC
OK, I finally reproduced the same error message ("Prepared update not found"), even though I'm not sure if I used the same path to achieve it:

1. The Updates tab must show some available updates already
2. Enable extra workstation repos (a banner at the top of gnome-software)
3. Enable some of them through menu (e.g. Steam or Nvidia repo)
4. Go back to Updates tab and hit Download/Reboot, the error will appear

If I refresh the Updates tab, or close GS and reopen it, the Updates tab is empty and the error is not there. (OTOH, the tab says "there are no updates", which is also completely wrong. There are sometimes error dialogs visible that a repo metadata failed to download, but that's somewhat difficult to read and easy to overlook). Jiri said, however, that his content in Updates tab stayed even after refreshing. Whatever the case, it seems that the error is related to a non-accessible mandatory repo.

Comment 9 Kamil Páral 2019-09-09 14:47:21 UTC
I have reported bug 1750414 to deal with non-functional workstation repositories. That doesn't resolve this bug though. This bug is a generic problem that occurs when any mandatory repo is down.

Comment 10 Geoffrey Marr 2019-09-09 20:03:54 UTC
Discussed during the 2019-09-09 blocker review meeting: [0]

The decision to delay the classification of this as a blocker bug was made as this looks like a serious issue, but there are a few uncertainties and we're also waiting on the outcome of the FESCo ticket before making a decision here.

[0] https://meetbot.fedoraproject.org/fedora-blocker-review/2019-09-03/f31-blocker-review.2019-09-03-16.01.txt

Comment 12 Geoffrey Marr 2019-09-16 18:26:47 UTC
Discussed during the 2019-09-16 blocker review meeting: [0]

The decision to delay the classification of this as a blocker bug was made as we believe the reversion of the DNF skip_if_unavailable default to True should mean this is no longer a big enough problem to be a blocker, but we will confirm this once the reversion is done.

[0] https://meetbot.fedoraproject.org/fedora-blocker-review/2019-09-16/f31-blocker-review.2019-09-16-16.02.txt

Comment 13 Jaroslav Mracek 2019-09-17 18:42:21 UTC
Can anyone test the theory from comment 12?

Comment 14 Miro Hrončok 2019-09-17 23:07:37 UTC
I won't be able to test this.

For the other who run Fedora 31 and have GNOME Software, I suppose you can change the default in /etc/dnf/dnf.conf to skip_if_unavailable=True and test again.

Comment 15 Kamil Páral 2019-09-18 13:37:25 UTC
(In reply to Jaroslav Mracek from comment #13)
> Can anyone test the theory from comment 12?

I put skip_if_unavailable=True into dnf.conf, rebooted the machine and tested the reproducer in comment 8. It works fine. But I want to say "of course it does" because we've added the same configs to each workstation repos in the meantime. And I can't edit the repos, because that would break the reproducer.

With an artificially constructed situation I've at least verified that PackageKit inherits skip_if_unavailable=True from dnf.conf, at least for gnome-software's update purposes. This means if DNF team decides to fix this by editing dnf.conf, it should be fine.

So overall, this bug is most definitely solved with default fedora repos and extra workstation repos already. It is also most definitely still present with any third-party repo that either has skip_if_unavailable=False or the defaults are False (hopefully reverted soon). But honestly, this is the least of our problems. When such a repo is present in the system, it makes the whole gnome-software totally unusable, with very little error reporting. The "Explore" tab is empty, you can't search for most apps (only recommended ones show up in search results), and you can't get any system updates. And you can see an error message about the inaccessible repo only when manually checking for updates, nowhere else. Fortunately this situation will be quite rare, once skip_if_unavailable is defaulting back to True.

Comment 16 Daniel Mach 2019-09-20 07:29:40 UTC
The default skip_if_unavailable behavior is going to be changed in dnf/libdnf (bug#1752249).
From my POV, the fix should be enough and this bug is probably no longer a blocker.

On the other hand this bug is still valid and should be fixed.
Gnome Software should error out on unavailable repos with skip_if_unavailable=False:
 * refuse to prepare the upgrade (the system must NOT attempt to upgrade during next reboot)
 * disable the "Reboot and install" button if the upgrade is not ready
It should also provide information about the mandatory but unavailable repos so user knows about the problem.

Comment 17 mattias.eriksson 2019-09-20 12:52:01 UTC
I added skip_if_unavailable=True to /etc/dnf/dnf.conf, rebooted just to make sure. Still can't do any updates with Gnome Software. Just thought you would like to know.

Comment 18 Torsten Casselt 2019-09-21 20:31:04 UTC
This sounds to me like the problem I encountered since upgrading F30 to F31 beta. Seems to be unrelated to the upgrade though since it happened to Robin Lee on F29:

https://www.mail-archive.com/users@lists.fedoraproject.org/msg131393.html

Look at journalctl -r -b -1 after a failed upgrade and search for these lines:

> dnf[1168]: File "/usr/lib/python3.7/site-packages/dnf-plugins/system_upgrade.py", line 404, in configure_upgrade
> dnf[1168]:   repo.gpgcheck = repo.id in self.state.gpgcheck_repos
> dnf[1168]: TypeError: argument of type 'NoneType' is not iterable

It is “fixed” by removing python3-dnf-plugin-system-upgrade. I still don’t understand why a dnf system upgrade plugin is used in packagekit based offline upgrades. I’d be glad if someone could elaborate on this.

TL;DR:

Try
sudo dnf remove python3-dnf-plugin-system-upgrade

Comment 19 mattias.eriksson 2019-09-22 18:17:47 UTC
I do indeed see the python error you are refering to in my logs, so it seems that this probably is the real cause rather than teh skip_if_unavailable or a combination of both. 

sep 20 14:47:25 zaphod systemd[1]: Failed to start System Upgrade using DNF.
sep 20 14:47:25 zaphod systemd[1]: dnf-system-upgrade.service: Failed with result 'exit-code'.
sep 20 14:47:25 zaphod systemd[1]: dnf-system-upgrade.service: Main process exited, code=exited, status=1/FAILURE
sep 20 14:47:25 zaphod pk-offline-update[937]: percentage 6%
sep 20 14:47:25 zaphod pk-offline-update[937]: percentage 5%
sep 20 14:47:25 zaphod pk-offline-update[937]: percentage 4%
sep 20 14:47:25 zaphod pk-offline-update[937]: percentage 3%
sep 20 14:47:25 zaphod dnf[935]: TypeError: argument of type 'NoneType' is not iterable
sep 20 14:47:25 zaphod dnf[935]:     repo.gpgcheck = repo.id in self.state.gpgcheck_repos
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf-plugins/system_upgrade.py", line 410, in configure_upgrade
sep 20 14:47:25 zaphod dnf[935]:     subfunc()
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf-plugins/system_upgrade.py", line 347, in _call_sub
sep 20 14:47:25 zaphod dnf[935]:     self._call_sub("configure")
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf-plugins/system_upgrade.py", line 335, in configure
sep 20 14:47:25 zaphod dnf[935]:     self.command.configure()
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf/cli/cli.py", line 970, in configure
sep 20 14:47:25 zaphod dnf[935]:     cli.configure(list(map(ucd, args)), option_parser())
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf/cli/main.py", line 94, in _main
sep 20 14:47:25 zaphod dnf[935]:     return _main(base, args, cli_class, option_parser_class)
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf/cli/main.py", line 65, in main
sep 20 14:47:25 zaphod dnf[935]:     errcode = main(args)
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/lib/python3.7/site-packages/dnf/cli/main.py", line 191, in user_main
sep 20 14:47:25 zaphod dnf[935]:     main.user_main(sys.argv[1:], exit_code=True)
sep 20 14:47:25 zaphod dnf[935]:   File "/usr/bin/dnf", line 58, in <module>
sep 20 14:47:25 zaphod dnf[935]: Traceback (most recent call last):
sep 20 14:47:25 zaphod python3[935]: error sending data to ABRT daemon: 
sep 20 14:47:25 zaphod python3[935]: can't communicate with ABRT daemon, is it running? [Errno 2] Filen eller katalogen finns inte
sep 20 14:47:25 zaphod pk-offline-update[937]: percentage 2%
sep 20 14:47:25 zaphod python3[935]: detected unhandled Python exception in '/usr/bin/dnf'

Comment 20 Torsten Casselt 2019-09-22 19:14:52 UTC
(In reply to mattias.eriksson from comment #19)
> I do indeed see the python error you are refering to in my logs, so it seems
> that this probably is the real cause rather than teh skip_if_unavailable or
> a combination of both. 

I can confirm that this happens even if skip_if_unavailable is true, I tested it prior to removing the python package because I too thought of it being the culprit. Thus the issue is with the python plugin.

Since it still is the recommended way of upgrading via CLI (https://fedoraproject.org/wiki/DNF_system_upgrade#What_is_DNF_system_upgrade.3F) I think this is an issue because some people might upgrade a release via dnf and do the normal upgrades via GNOME Software. One method should certainly not break the other, especially not just because it is installed.

Comment 21 Adam Williamson 2019-09-23 16:34:40 UTC
The case Mattias reports looks like it might be a different bug that has the same symptom.

Does anyone who has that traceback also see this in their logs anywhere?

"Failed loading state file: /var/lib/dnf/system-upgrade.json, continuing with empty state."

I can sort of see how this bug would happen, actually, it's definitely a possibility in the code.

Comment 22 Adam Williamson 2019-09-23 16:38:22 UTC
Adding Pavla, who seems to be maintaining dnf-plugin-system-upgrade lately - Pavla, I can sorta see how this happens...self.state.gpgcheck_repos is read in by State._prop(), which will give None if the state file it's reading doesn't have the key. Then configure_upgrade just assumes it will be an iterable, with no protection against it possibly being None. It's hard to tell precisely why it winds up None in this case, but it's definitely something that *can* happen and which configure_upgrade doesn't protect against.

Comment 23 Adam Williamson 2019-09-23 16:40:00 UTC
Also, Lukas / Kamil, do you see that traceback in your reproducers?

Comment 24 mattias.eriksson 2019-09-23 17:35:19 UTC
I do not see the "Failed loading state file" in my logs.

Comment 25 Geoffrey Marr 2019-09-23 17:55:18 UTC
Discussed during the 2019-09-23 blocker review meeting: [0]

The decision to delay the classification of this as a blocker bug was made as we are still waiting to see the impact of the skip_if_unavailable change here, and also it seems that another cause of the same error may have been discovered, and we should look into that a bit too.

[0] https://meetbot.fedoraproject.org/fedora-blocker-review/2019-09-23/f31-blocker-review.2019-09-23-16.03.txt

Comment 26 Torsten Casselt 2019-09-23 19:03:06 UTC
Looking at the meeting logs I want to add: I disabled all third-party repos and it still failed.
I will try to create a reproducer on a new installation if time permits.

Comment 27 Pavla Kratochvilova 2019-09-24 06:33:20 UTC
Thank you Adam, for adding me here. For the problem described in comment 18, there is already filed bug 1751103.

> It's hard to tell precisely why it winds up None in this case

Not that it matters, but it can happen for example if you run "dnf system-upgrade reboot" without running "dnf system-upgrade download" first. I am not sure how the system-upgrade plugin is used in PackageKit.

> but it's definitely something that *can* happen and which configure_upgrade doesn't protect against.

Agreed, I'll try to fix it and build for F31 and F32 this week. (F30 and lower are not affected.)

Comment 28 Pavla Kratochvilova 2019-09-27 06:51:31 UTC
I made a build for F32 and F31 and submitted an update for Fedora 31: https://bodhi.fedoraproject.org/updates/FEDORA-2019-6a6b241835
Note that this update fixes only the problem described in comment 18. Let's keep this bug only for tracking the first issue (the one related to skip_if_unavailable).

Comment 29 Adam Williamson 2019-09-30 16:46:20 UTC
For reference, we have another bug for the issue from #c18 now: https://bugzilla.redhat.com/show_bug.cgi?id=1751103 . It has several dupes indicating many people were able to trigger it somehow.

Comment 30 Geoffrey Marr 2019-09-30 23:16:03 UTC
Discussed during the 2019-09-30 blocker review meeting: [0]

The decision to classify this bug as a "RejectedBlocker" was made as we are still waiting to check the status of this with the dnf default changed back, but to avoid it clogging up the list we're going to assume for now that it'll be fine once that change happens; if it turns out still to be a problem it can be re-proposed.

[0] https://meetbot.fedoraproject.org/fedora-blocker-review/2019-09-30/f31-blocker-review.2019-09-30-16.00.txt


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