Hangs in apt/methods/http(s)

[paulmenzel]

Debian sid/unstable with packagekit 1.2.4-1 and libapt-pkg6.0 2.3.13.

My root disk only had 7 MB of free space left. This seems to have caused packagekitd to hang despite, after cleaning up, enough free space is available now.

$ LANG=C sudo apt update
Reading package lists... Done
E: Could not get lock /var/lib/apt/lists/lock. It is held by process 753 (packagekitd)
N: Be aware that removing the lock file is not a solution and may break your system.
E: Unable to lock directory /var/lib/apt/lists/

$ ps auxf | more
[…]
root         753  0.1  0.7 459896 121024 ?       Ssl  08:43   0:04 /usr/libexec/packagekitd
_apt        1572  0.0  0.0  26684 13396 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/https
_apt        1573  0.0  0.0  26684 13676 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/https
_apt        1574  0.0  0.0  23648 10264 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/http
_apt        1575  0.0  0.0  26684 13660 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/https
_apt        1576  0.0  0.0  26696 13440 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/https
_apt        1577  0.0  0.0  23648 10124 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/http
_apt        1578  0.0  0.0  23780 10396 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/http
_apt        1579  0.0  0.0  23648 10140 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/http
_apt        1607  0.0  0.0  15956  6808 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/gpgv
_apt        1817  0.0  0.0  24328  8388 ?        S    08:43   0:01  \_ /usr/lib/apt/methods/store
_apt        2293  0.0  0.0  16828  8340 ?        S    08:43   0:01  \_ /usr/lib/apt/methods/rred
_apt        2368  0.0  0.0  16828  8344 ?        S    08:43   0:01  \_ /usr/lib/apt/methods/rred
_apt        2369  0.0  0.0  16832  8336 ?        S    08:43   0:01  \_ /usr/lib/apt/methods/rred
_apt        2370  0.0  0.0  16832  7676 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/rred
_apt        2371  0.0  0.0  17560  7960 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/rred
_apt        2372  0.0  0.0  17560  8332 ?        S    08:43   0:00  \_ /usr/lib/apt/methods/rred
[…]

$ sudo strace -ff -p753
strace: Process 753 attached with 4 threads
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=180024} <unfinished ...>
[pid   794] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   795] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid   753] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid  1565] <... select resumed>)       = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000} <unfinished ...>
[pid   753] <... restart_syscall resumed>) = 0
[pid   753] poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}], 2, 9998 <unfinished ...>
[pid  1565] <... select resumed>)       = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}) = 0 (Timeout)
[pid  1565] select(42, [13 14 15 17 19 21 23 25 27 29 31 33 35 37 39 41], [], NULL, {tv_sec=0, tv_usec=500000}^Cstrace: Process 753 detached
strace: Process 794 detached
strace: Process 795 detached
strace: Process 1565 detached
 <detached ...>

No idea, why process with id 1565 does not show up in the output of ps:

$ sudo ls -ld /proc/1565/exe
lrwxrwxrwx 1 root root 0  2. Dez 10:45 /proc/1565/exe -> /usr/libexec/packagekitd
$ ps aux | grep 1565
joey     6875  0.0  0.0   6548  2272 pts/5    S+   10:46   0:00 grep --color=auto 1565

Some backtraces captured with GNU gdb:

$ sudo gdb --pid 753
[…]
0x00007fe10136ee2f in __GI___poll (fds=0x5612658d7c50, nfds=2, timeout=9991) at ../sysdeps/unix/sysv/linux/poll.c:29
29	../sysdeps/unix/sysv/linux/poll.c: Datei oder Verzeichnis nicht gefunden.
[…]
(gdb) bt
#0  0x00007fe10136ee2f in __GI___poll (fds=0x5612658d7c50, nfds=2, timeout=9991) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007fe101945ebe in g_main_context_poll
    (priority=<optimized out>, n_fds=2, fds=0x5612658d7c50, timeout=<optimized out>, context=0x5612658a9290) at ../../../glib/gmain.c:4478
#2  g_main_context_iterate (context=0x5612658a9290, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../../../glib/gmain.c:4170
#3  0x00007fe101946213 in g_main_loop_run (loop=loop@entry=0x5612658a9380) at ../../../glib/gmain.c:4373
#4  0x0000561264cc7d9a in main (argc=<optimized out>, argv=<optimized out>) at ../src/pk-main.c:245

$ sudo gdb --pid 1565
[…]
0x00007fe101371543 in __GI___select (nfds=42, readfds=0x7fe0fd814810, writefds=0x7fe0fd814890, exceptfds=0x0, timeout=0x7fe0fd8147a0)
    at ../sysdeps/unix/sysv/linux/select.c:41
41	../sysdeps/unix/sysv/linux/select.c: Datei oder Verzeichnis nicht gefunden.
[…]
(gdb) bt
#0  0x00007fe101371543 in __GI___select (nfds=42, readfds=0x7fe0fd814810, writefds=0x7fe0fd814890, exceptfds=0x0, timeout=0x7fe0fd8147a0)
    at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fe0feed10f5 in pkgAcquire::Run(int) () at /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
#2  0x00007fe0fefd1c2d in AcquireUpdate(pkgAcquire&, int, bool, bool) () at /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
#3  0x00007fe0fefd211e in ListUpdate(pkgAcquireStatus&, pkgSourceList&, int) () at /lib/x86_64-linux-gnu/libapt-pkg.so.6.0
#4  0x00007fe0ff8d36ae in AptIntf::refreshCache() (this=this@entry=0x56126599f000) at /usr/include/apt-pkg/cachefile.h:78
#5  0x00007fe0ff8e1ada in pk_backend_refresh_cache_thread(PkBackendJob*, GVariant*, gpointer)
    (job=0x5612659bc450 [PkBackendJob], params=<optimized out>, user_data=<optimized out>) at ../backends/aptcc/pk-backend-aptcc.cpp:575
#6  0x0000561264cdc8aa in pk_backend_job_thread_setup (thread_data=0x5612658a6f00) at ../src/pk-backend-job.c:724
#7  0x00007fe10196fecd in g_thread_proxy (data=0x7fe0f800d800) at ../../../glib/gthread.c:827
#8  0x00007fe101449eae in start_thread (arg=0x7fe0fd815640) at pthread_create.c:46

$ sudo gdb --pid 1572
[…]
0x00007fc52b0df4f6 in __GI___select (nfds=1, readfds=0x7ffe1f8c2080, writefds=0x0, exceptfds=0x0, timeout=0x0)
    at ../sysdeps/unix/sysv/linux/select.c:41
41	../sysdeps/unix/sysv/linux/select.c: Datei oder Verzeichnis nicht gefunden.
[…]
(gdb) bt
#0  0x00007fc52b0df4f6 in __GI___select (nfds=1, readfds=0x7ffe1f8c2080, writefds=0x0, exceptfds=0x0, timeout=0x0)
    at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fc52b7ae913 in WaitFd (Fd=<optimized out>, write=<optimized out>, timeout=0) at ./apt-pkg/contrib/fileutl.cc:844
#2  0x00005569f35c9e58 in ?? ()
#3  0x00005569f35ad3d0 in ?? ()
#4  0x00007fc52b011e4a in __libc_start_main (main=0x5569f35ad350, argc=1, argv=0x7ffe1f8c2798, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7ffe1f8c2788) at ../csu/libc-start.c:314
#5  0x00005569f35ad52a in ?? ()

[paulmenzel]

I killed the process, and the journal only contains:

Dez 02 10:56:19 ersatz sudo[7254]:  joey : TTY=pts/5 ; PWD=/home/joey ; USER=root ; COMMAND=/usr/bin/kill 753
Dez 02 10:56:19 ersatz sudo[7254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=5272)
Dez 02 10:56:19 ersatz sudo[7254]: pam_unix(sudo:session): session closed for user root
Dez 02 10:56:19 ersatz gnome-software[1404]: not handling error failed for action refresh: PackageKit daemon disappeared
Dez 02 10:56:19 ersatz dbus-daemon[444]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' request>
Dez 02 10:56:19 ersatz systemd[1]: packagekit.service: Deactivated successfully.
Dez 02 10:56:19 ersatz systemd[1]: packagekit.service: Consumed 12.584s CPU time.

[ximion]

Is this still an issue with the latest version of APT and PK?

[paulmenzel]

No idea, as this is not easily reproducible. Therefore, I am closing the issue.

[ximion]

I have done quite a bit of work on the APT backend, so try the latest PK 1.2.6 and hopefully the issue won't happen again (I did not find anything that would cause this behavior explicitly though).