Software Updater show empty panels, stuck in ProblemResolver.resolve of apt_pkg.cpython-36m-x86_64-linux-gnu.so

[Christian Ehrhardt ]

I just happened to see that Software Updater popped up with an actually empty window:
1. nothing in "install or remove"
2. obviously no details for changes/descriptions

But at the same time it says "26.3 MB will be downloaded"
I'll attach a screenshot of that to show what I mean.

At the same time there are upgradable packages:
$ apt list --upgradable
Listing... Done
apturl/bionic-updates 0.5.2ubuntu14.2 amd64 [upgradable from: 0.5.2ubuntu14]
apturl-common/bionic-updates 0.5.2ubuntu14.2 amd64 [upgradable from: 0.5.2ubuntu14]
flashplugin-installer/bionic-updates,bionic-security 31.0.0.122ubuntu0.18.04.1 amd64 [upgradable from: 31.0.0.108ubuntu0.18.04.1]
gir1.2-javascriptcoregtk-4.0/bionic-updates,bionic-security 2.22.2-0ubuntu0.18.04.2 amd64 [upgradable from: 2.22.2-0ubuntu0.18.04.1]
[...]

And that matches the 26.3MB
$ sudo apt upgrade
[...]
22 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 26,3 MB of archives.

I can restart it to get the same symptom, done in console one indicator of a problem is:
$ /usr/bin/python3 /usr/bin/update-manager --no-update --no-focus-on-map
Failed to connect to https://changelogs.ubuntu.com/meta-release-lts. Check your Internet connection or proxy settings

Also https://changelogs.ubuntu.com/meta-release-lts is reachable for me.

But even if it would be not reachable, why then "26.3MB will be downloaded" - it seems to know some things?

I'd either expect a user visible error (UI) or listing the packages apt knows about to upgrade.
But not "nothing"

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: update-manager 1:18.04.11.5
ProcVersionSignature: Ubuntu 4.15.0-36.39-generic 4.15.18
Uname: Linux 4.15.0-36-generic x86_64
NonfreeKernelModules: zfs zunicode zavl icp zcommon znvpair
ApportVersion: 2.20.9-0ubuntu7.4
Aptdaemon:

Architecture: amd64
CurrentDesktop: ubuntu:GNOME
Date: Thu Oct 11 09:36:19 2018
ExecutablePath: /usr/bin/update-manager
GsettingsChanges:
 b'com.ubuntu.update-manager' b'show-details' b'true'
 b'com.ubuntu.update-manager' b'window-height' b'625'
 b'com.ubuntu.update-manager' b'first-run' b'false'
 b'com.ubuntu.update-manager' b'window-width' b'645'
 b'com.ubuntu.update-manager' b'launch-time' b'int64 1539243337'
InstallationDate: Installed on 2016-02-19 (964 days ago)
InstallationMedia: Kubuntu 15.10 "Wily Werewolf" - Release amd64 (20151021)
InterpreterPath: /usr/bin/python3.6
PackageArchitecture: all
Python3Details: /usr/bin/python3.6, Python 3.6.6, python3-minimal, 3.6.5-3ubuntu1
PythonDetails: /usr/bin/python2.7, Python 2.7.15rc1, python-minimal, 2.7.15~rc1-1
SourcePackage: update-manager
UpgradeStatus: Upgraded to bionic on 2018-05-03 (160 days ago)

[Christian Ehrhardt  (paelzer)]

Running with --debug

$ /usr/bin/python3 /usr/bin/update-manager --no-update --no-focus-on-map --debug
Failed to connect to https://changelogs.ubuntu.com/meta-release-lts. Check your Internet connection or proxy settings
INFO:root:holding back phased update libnautilus-extension1a (0 < 16)
DEBUG:root:WARNING: can not get name for '<Gtk.TreeViewAccessible object at 0x7ff8c226e048 (GtkTreeViewAccessible at 0x2e423b0)>'
DEBUG:root:WARNING: can not get name for '<Gtk.LabelAccessible object at 0x7ff8c226e7e0 (GtkLabelAccessible at 0x4499400)>'
DEBUG:root:WARNING: can not get name for '<Gtk.TreeSelection object at 0x7ff8c226e8b8 (GtkTreeSelection at 0x33b7a60)>'
DEBUG:root:WARNING: can not get name for '<Gtk.TextViewAccessible object at 0x7ff8c2270090 (GtkTextViewAccessible at 0x4616470)>'

Not sure if that is important, up to people understanding GTK :-)

[Christian Ehrhardt  (paelzer)]

I happened to add a bit of debug and found it blocking in pkg.mark_delete()

With the attached debugging I get:
[...]
DEBUG:root:process pkg.name linux-cloud-tools-4.15.0-32-lowlatency:i386
DEBUG:root:process pkg.name linux-cloud-tools-4.15.0-32:i386
DEBUG:root:process pkg.name linux-cloud-tools-4.15.0-33
DEBUG:root:append kernel_autoremove_pkgs linux-cloud-tools-4.15.0-33
DEBUG:root:mark delete linux-cloud-tools-4.15.0-33

It never leaves that, I'll take a look if/why it is hanging there.

[Christian Ehrhardt  (paelzer)]

It reaches fix.resolve() in /usr/lib/python3/dist-packages/apt/package.py and is stuck there.
I'll check further, but since this is src:python-apt I'll add a bug task for it.

[Christian Ehrhardt  (paelzer)]

Note: it enters that path as self._pcache._depcache.broken_count is 2 and auto_fix True.

[Christian Ehrhardt  (paelzer)]

That function is in:
/usr/lib/python3/dist-packages/apt_pkg.cpython-36m-x86_64-linux-gnu.so
(src:python-apt)

[Christian Ehrhardt  (paelzer)]

FYI - yes those packages would be in the autoremove list

$ sudo apt autoremove
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages will be REMOVED:
  linux-cloud-tools-4.15.0-33 linux-cloud-tools-4.15.0-33-generic linux-headers-4.15.0-33 linux-headers-4.15.0-33-generic linux-image-4.15.0-33-generic
  linux-modules-4.15.0-33-generic linux-modules-extra-4.15.0-33-generic linux-tools-4.15.0-33 linux-tools-4.15.0-33-generic
0 upgraded, 0 newly installed, 9 to remove and 22 not upgraded.
After this operation, 343 MB disk space will be freed.

I'd assume I can get around by removing them, but I wonder if we can fix the underlying issue.
Users that don't understand what is going on will just be stuck without updates through the update-manager.

[Christian Ehrhardt  (paelzer)]

In straces everything seems to spin on:
python3 3736 paelzer 3u unix 0xffff8fe4a2ba5000 0t0 2092674 type=STREAM
But that might just be GTK refreshs or such.
Yep that is only
u_str ESTAB 0 0 @/tmp/.X11-unix/X0 2091383 * 2092674

I'd need to see how to debug the actual resolve call.
PkgProblemResolverResolve of python-apt-1.7.0~rc1/python/depcache.cc is the implementation of this.
So fra trying to py-* in gdb's python support didn't grant me a lot useful things :-/

While still hanging in that resolve call threads look like this:

  Id Target Id Frame
* 1 Thread 0x7feada74a740 (LWP 3736) "python3" 0x00007feada28dbf9 in __GI___poll (fds=0xf2e670, nfds=5, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
  2 Thread 0x7feac9396700 (LWP 3737) "dconf worker" 0x00007feada28dbf9 in __GI___poll (fds=0x1105250, nfds=1, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
  3 Thread 0x7feac8b95700 (LWP 3738) "gmain" 0x00007feada28dbf9 in __GI___poll (fds=0x7feac4006880, nfds=2, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
  4 Thread 0x7feac3fff700 (LWP 3739) "gdbus" 0x00007feada28dbf9 in __GI___poll (fds=0x7feac4021b30, nfds=3, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29

Thread 3+4 are of GTK and seem not interesting.
Thread 1 is pythin, but it seems to spin in Gtk.main()

(gdb) py-bt-full
#11 Frame 0xb6bc78, for file /usr/bin/update-manager, line 118, in <module> ()
    Gtk.main()

(gdb) py-list
 113 settings.set_int64("launch-time", int(time.time()))
 114 init_proxy(settings)
 115
 116 app = UpdateManager(data_dir, options)
 117 app.start_update()
>118 Gtk.main()

That is not where the resolver is stuck.
Which leaves Thread 2
  2 Thread 0x7feac9396700 (LWP 3737) "dconf worker" 0x00007feada28dbf9 in __GI___poll (fds=0x1105250, nfds=1, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29

But I'm not sure if this is the right thread, it doesn't seem to by python more like Gnome-Settings related.

I'm not an cpython debug expert at all, but would want to know what to look further before the situation resolves and I can't check it anymore.

[Balint Reczey (rbalint)]

Could you please check if this is a duplicate of LP: #1795898 and give a try to u-m in bionic Unapproved to fix it?

[Christian Ehrhardt  (paelzer)]

The chaining of python -> cc -> pytohn -> cc code here let me fail to follow it.
It seemed like a loop between python/depcache.cc and cache.py, but that might only be my lack of understanding of how this was architectured.
But due to that I wasn't able to debug further and would let it up to you to go on on this.

I'll give the upload rbalint mentioned a try, but it doesn't feel to be the same thing ...

[Christian Ehrhardt  (paelzer)]

Our last ideas were around:
- one process waiting on the GIL, but not getting it (deadlock)
- the thread that would update the package list (resolver) dying which would leave the GTK/Ui
  threads spinning (as we see them), but never populate the objects to be displayed.
  I see plenty of processes get created and die, but no clear point to fix.
  Many of them end with:
    0.000126 futex(0x7fbc78003160, FUTEX_WAIT_PRIVATE, 0, {tv_sec=14, tv_nsec=999999129}) = -1 ETIMEDOUT (Connection timed out) <15.000111>
    0.795429 madvise(0x7fbc69a07000, 8368128, MADV_DONTNEED) = 0 <0.000017>
    0.000049 exit(0) = ?
  But I have not found a link what they actually try to get before they die (they don't do much
  more)

But the debug data wasn't strong enough for either to further debug or try a fix.

I was trying rbalints fix from [1] where I put it.
And even thou the sytmptom was rather different IMHO it resolved the issue.

Marking as a Dup

[1]: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/3472