[Pkg-utopia-maintainers] Bug#1054650: dbus: makes the machine extremely slow, freezes on shutdown

Vincent Lefevre vincent at vinc17.net
Fri Oct 27 12:45:24 BST 2023 

Package: dbus
Version: 1.14.10-2
Severity: critical
Justification: breaks the whole system

dbus 1.14.10-2 makes the machine extremely slow (this affects the
boot, login, the su command, and package installation at least),
and it freezes on shutdown. This is reproducible (I've tested on
2 successive reboots).

Downgrading to dbus 1.14.10-1 solves the problem.

"systemd-analyze blame" gives

25.157s lightdm.service
25.049s plymouth-quit-wait.service
11.123s NetworkManager-wait-online.service
 3.410s loadcpufreq.service
 2.522s systemd-modules-load.service
 1.392s nvidia-persistenced.service
 1.306s gpm.service
 1.224s accounts-daemon.service
 1.143s networking.service
 1.041s udisks2.service
  997ms atopacct.service
  964ms cups.service
  936ms avahi-daemon.service
  724ms alsa-restore.service
  719ms atd.service
  700ms dev-sda5.device
  695ms NetworkManager.service
  644ms polkit.service
  588ms lm-sensors.service
  540ms e2scrub_reap.service
  500ms rtkit-daemon.service
  498ms ssh.service
  478ms systemd-udev-trigger.service
  435ms ModemManager.service
  413ms exim4.service
  401ms cpufrequtils.service
  395ms dbus.service
  357ms dictd.service
  345ms apache-htcacheclean.service
  317ms colord.service
  262ms wpa_supplicant.service
  238ms apache2.service
  226ms atop.service
  217ms systemd-journald.service
  181ms lvm2-monitor.service
  176ms systemd-udevd.service
  151ms rsyslog.service
  122ms systemd-user-sessions.service
  115ms systemd-journal-flush.service
  107ms keyboard-setup.service
  102ms apparmor.service
   77ms systemd-tmpfiles-setup.service
   70ms systemd-timesyncd.service
   54ms dev-disk-by\x2duuid-3a31982a\x2d76fe\x2d493b\x2da6b0\x2da627706c26c7.swap
   52ms systemd-tmpfiles-setup-dev-early.service
   44ms systemd-binfmt.service
   35ms binfmt-support.service
   31ms dev-hugepages.mount
   30ms dev-mqueue.mount
   29ms modprobe at fuse.service
   29ms sys-kernel-debug.mount
   28ms sys-kernel-tracing.mount
   26ms plymouth-start.service
   24ms systemd-random-seed.service
   24ms kmod-static-nodes.service
   22ms modprobe at configfs.service
   21ms systemd-remount-fs.service
   20ms systemd-update-utmp.service
   19ms plymouth-read-write.service
   16ms systemd-sysctl.service
   16ms systemd-tmpfiles-setup-dev.service
   15ms systemd-update-utmp-runlevel.service
   10ms proc-sys-fs-binfmt_misc.mount
   10ms console-setup.service
    7ms modprobe at loop.service
    6ms modprobe at efi_pstore.service
    5ms modprobe at drm.service
    5ms modprobe at dm_mod.service
    4ms ifupdown-pre.service
    4ms sys-fs-fuse-connections.mount
    4ms sys-kernel-config.mount
   35us blk-availability.service

With dbus 1.14.10-1:

10.967s NetworkManager-wait-online.service
 2.872s loadcpufreq.service
 2.525s systemd-modules-load.service
 1.593s accounts-daemon.service
 1.527s networking.service
 1.380s nvidia-persistenced.service
 1.274s atopacct.service
 1.115s gpm.service
 1.013s polkit.service
[...]

In the journalctl output:

Oct 27 13:18:04 cventin kernel: microcode: updated early: 0x2e -> 0x49, date = 2021-08-11
Oct 27 13:18:04 cventin kernel: Linux version 6.5.0-3-amd64 (debian-kernel at lists.debian.org) (gcc-13 (Debian 13.2.0-5) 13.2.0, GNU ld (GNU Binutils for Debian) 2.41) #1 SMP PREEMPT_DYNAMIC Debian 6.5.8-1 (2023-10-22)
Oct 27 13:18:04 cventin kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-6.5.0-3-amd64 root=UUID=4bcb3bbd-f516-4ddf-be96-6fa3a8cdc8a0 ro quiet
[...]
Oct 27 13:18:21 cventin systemd[1]: Starting exim4.service - exim Mail Transport Agent...
Oct 27 13:18:21 cventin dictd[1085]: Starting dictionary server: dictd.
Oct 27 13:18:21 cventin systemd[1]: Started dictd.service - LSB: Start and stop dictionary server daemon.
Oct 27 13:18:21 cventin systemd[1]: Started exim4.service - exim Mail Transport Agent.
Oct 27 13:18:31 cventin systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Oct 27 13:18:35 cventin systemd-timesyncd[563]: Contacted time server 162.159.200.123:123 (2.debian.pool.ntp.org).
Oct 27 13:18:35 cventin systemd-timesyncd[563]: Initial clock synchronization to Fri 2023-10-27 13:18:35.336765 CEST.
Oct 27 13:18:36 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:18:36 cventin lightdm[960]: Failed to get list of logind seats: Timeout was reached
Oct 27 13:18:36 cventin systemd[1]: Received SIGRTMIN+21 from PID 306 (plymouthd).
Oct 27 13:18:36 cventin systemd[1]: Received SIGRTMIN+21 from PID 306 (plymouthd).
Oct 27 13:18:36 cventin systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up.
Oct 27 13:18:36 cventin systemd[1]: Started getty at tty1.service - Getty on tty1.
Oct 27 13:18:36 cventin systemd[1]: Reached target getty.target - Login Prompts.
Oct 27 13:18:36 cventin systemd[1]: Reached target multi-user.target - Multi-User System.
Oct 27 13:18:36 cventin systemd[1]: Started lightdm.service - Light Display Manager.
Oct 27 13:18:36 cventin systemd[1]: Reached target graphical.target - Graphical Interface.
Oct 27 13:18:36 cventin systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP...
Oct 27 13:18:36 cventin systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully.
Oct 27 13:18:36 cventin systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP.
Oct 27 13:18:36 cventin systemd[1]: Startup finished in 4.224s (kernel) + 32.447s (userspace) = 36.671s.
Oct 27 13:18:39 cventin lightdm[1396]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=118) by (uid=0)
Oct 27 13:18:39 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.32' (uid=0 pid=1396 comm="lightdm --session-child 18 21")
Oct 27 13:18:39 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:18:39 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:18:39 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:18:39 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:18:40 cventin systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Oct 27 13:19:04 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:19:04 cventin lightdm[1396]: pam_systemd(lightdm-greeter:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:19:04 cventin lightdm[1396]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=118) by (uid=0)
Oct 27 13:19:04 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.33' (uid=0 pid=1396 comm="lightdm --session-child 18 21")
Oct 27 13:19:04 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:19:04 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:19:04 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:19:04 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:19:08 cventin sshd[1407]: Accepted publickey for [...]
Oct 27 13:19:08 cventin sshd[1407]: pam_unix(sshd:session): session opened for user vlefevre(uid=1000) by (uid=0)
Oct 27 13:19:29 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:19:29 cventin sshd[1407]: pam_systemd(sshd:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:19:29 cventin lightdm[1396]: pam_systemd(lightdm-greeter:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:19:29 cventin sshd[1407]: pam_env(sshd:session): deprecated reading of user environment enabled
Oct 27 13:19:30 cventin sshd[1414]: Received disconnect from 140.77.51.8 port 52346:11: disconnected by user
Oct 27 13:19:30 cventin systemd-journald[385]: /var/log/journal/dcbbbc34fb4249e4864ba967a9d3b514/user-1000.journal: Journal file uses a different sequence number ID, rotating.
Oct 27 13:19:30 cventin sshd[1414]: Disconnected from user vlefevre 140.77.51.8 port 52346
Oct 27 13:19:30 cventin sshd[1407]: pam_unix(sshd:session): session closed for user vlefevre
Oct 27 13:19:30 cventin dbus-daemon[1423]: [session uid=118 pid=1421] Activating service name='org.a11y.Bus' requested by ':1.0' (uid=118 pid=1412 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:19:30 cventin dbus-daemon[1423]: [session uid=118 pid=1421] Successfully activated service 'org.a11y.Bus'
Oct 27 13:19:31 cventin org.a11y.Bus[1432]: dbus-daemon[1432]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=118 pid=1412 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:19:31 cventin org.a11y.Bus[1432]: dbus-daemon[1432]: Successfully activated service 'org.a11y.atspi.Registry'
Oct 27 13:19:31 cventin org.a11y.Bus[1462]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
Oct 27 13:19:39 cventin lightdm[1460]: gkr-pam: unable to locate daemon control file
Oct 27 13:19:39 cventin lightdm[1460]: gkr-pam: stashed password to try later in open session
Oct 27 13:19:39 cventin lightdm[1396]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Oct 27 13:19:39 cventin lightdm[1396]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Oct 27 13:19:39 cventin lightdm[1460]: pam_unix(lightdm:session): session opened for user vlefevre(uid=1000) by (uid=0)
Oct 27 13:19:39 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.37' (uid=0 pid=1460 comm="lightdm --session-child 14 21")
Oct 27 13:19:39 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:19:39 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:19:39 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:19:39 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:19:58 cventin sshd[1473]: Accepted publickey for [...]
Oct 27 13:19:58 cventin sshd[1473]: pam_unix(sshd:session): session opened for user vlefevre(uid=1000) by (uid=0)
Oct 27 13:20:04 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:20:04 cventin sshd[1473]: pam_systemd(sshd:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:20:04 cventin lightdm[1460]: pam_systemd(lightdm:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:20:04 cventin lightdm[1460]: gkr-pam: unable to locate daemon control file
Oct 27 13:20:04 cventin sshd[1473]: pam_env(sshd:session): deprecated reading of user environment enabled
Oct 27 13:20:04 cventin lightdm[1460]: gkr-pam: gnome-keyring-daemon started properly and unlocked keyring
Oct 27 13:20:04 cventin lightdm[1460]: Failed to open CK session: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.ConsoleKit was not provided by any .service files
Oct 27 13:20:05 cventin dbus-daemon[1566]: [session uid=1000 pid=1560] Activating service name='ca.desrt.dconf' requested by ':1.3' (uid=1000 pid=1735 comm="light-locker --debug")
Oct 27 13:20:05 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.40' (uid=1000 pid=1735 comm="light-locker --debug")
Oct 27 13:20:05 cventin dbus-daemon[1566]: [session uid=1000 pid=1560] Successfully activated service 'ca.desrt.dconf'
Oct 27 13:20:05 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:20:05 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:20:05 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:20:05 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:20:30 cventin kernel: traps: light-locker[1735] trap int3 ip:7f68ae532587 sp:7ffc52daa780 error:0 in libglib-2.0.so.0.7800.1[7f68ae4ee000+99000]
Oct 27 13:20:30 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:21:12 cventin dbus-daemon[1566]: [session uid=1000 pid=1560] Activating service name='org.gtk.vfs.Daemon' requested by ':1.6' (uid=1000 pid=2190 comm="emacs")
Oct 27 13:21:12 cventin dbus-daemon[1566]: [session uid=1000 pid=1560] Successfully activated service 'org.gtk.vfs.Daemon'
Oct 27 13:21:54 cventin lightdm[1460]: pam_unix(lightdm:session): session closed for user vlefevre
Oct 27 13:21:54 cventin org.a11y.Bus[1462]: X connection to :0 broken (explicit kill or server shutdown).
Oct 27 13:21:54 cventin org.gtk.vfs.Daemon[2195]: A connection to the bus can't be made
Oct 27 13:21:54 cventin systemd[1]: home-vlefevre-.gvfs.mount: Deactivated successfully.
Oct 27 13:21:57 cventin /usr/sbin/gpm[757]: *** warning [daemon/old_main.c(254)]:
Oct 27 13:21:57 cventin /usr/sbin/gpm[757]: Data on strange file descriptor 4
Oct 27 13:21:57 cventin lightdm[2345]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=118) by (uid=0)
Oct 27 13:21:57 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.45' (uid=0 pid=2345 comm="lightdm --session-child 18 21")
Oct 27 13:21:57 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:21:57 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:21:57 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:21:57 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:22:22 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:22:22 cventin lightdm[2345]: pam_systemd(lightdm-greeter:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:22:22 cventin lightdm[2345]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=118) by (uid=0)
Oct 27 13:22:22 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.46' (uid=0 pid=2345 comm="lightdm --session-child 18 21")
Oct 27 13:22:22 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:22:22 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:22:22 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:22:22 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:22:47 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:22:47 cventin lightdm[2345]: pam_systemd(lightdm-greeter:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:22:48 cventin dbus-daemon[2360]: [session uid=118 pid=2358] Activating service name='org.a11y.Bus' requested by ':1.0' (uid=118 pid=2354 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:22:48 cventin dbus-daemon[2360]: [session uid=118 pid=2358] Successfully activated service 'org.a11y.Bus'
Oct 27 13:22:48 cventin org.a11y.Bus[2368]: dbus-daemon[2368]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=118 pid=2354 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:22:48 cventin org.a11y.Bus[2368]: dbus-daemon[2368]: Successfully activated service 'org.a11y.atspi.Registry'
Oct 27 13:22:48 cventin org.a11y.Bus[2397]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
Oct 27 13:22:52 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.47' (uid=118 pid=2354 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:22:52 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:22:52 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:22:52 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:22:52 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.
Oct 27 13:23:12 cventin su[2405]: (to root) vlefevre on pts/0
Oct 27 13:23:12 cventin su[2405]: pam_unix(su:session): session opened for user root(uid=0) by vlefevre(uid=1000)
Oct 27 13:23:17 cventin dbus-daemon[749]: [system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:23:17 cventin su[2405]: pam_systemd(su:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Oct 27 13:23:17 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service' requested by ':1.47' (uid=118 pid=2354 comm="/usr/sbin/lightdm-gtk-greeter")
Oct 27 13:23:17 cventin systemd[1]: Starting upower.service - Daemon for power management...
Oct 27 13:23:17 cventin dbus-daemon[749]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service' requested by ':1.49' (uid=0 pid=2407 comm="/usr/libexec/upowerd")
Oct 27 13:23:18 cventin systemd[1]: Starting modprobe at drm.service - Load Kernel Module drm...
Oct 27 13:23:18 cventin systemd[1]: modprobe at drm.service: Deactivated successfully.
Oct 27 13:23:18 cventin systemd[1]: Finished modprobe at drm.service - Load Kernel Module drm.
Oct 27 13:23:18 cventin systemd[1]: systemd-logind.service - User Login Management was skipped because no trigger condition checks were met.

-- System Information:
Debian Release: trixie/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'stable-updates'), (500, 'stable-security'), (500, 'unstable'), (500, 'testing'), (500, 'stable'), (1, 'experimental')
merged-usr: no
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 6.5.0-3-amd64 (SMP w/12 CPU threads; PREEMPT)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=POSIX, LC_CTYPE=C.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages dbus depends on:
ii  dbus-bin                1.14.10-2
ii  dbus-daemon             1.14.10-2
ii  dbus-system-bus-common  1.14.10-2
ii  init-system-helpers     1.64
ii  libc6                   2.37-12
ii  libdbus-1-3             1.14.10-2
ii  libexpat1               2.5.0-2
ii  libsystemd0             254.5-1

dbus recommends no packages.

Versions of packages dbus suggests:
ii  dbus-user-session [default-dbus-session-bus]  1.14.10-2
ii  dbus-x11 [dbus-session-bus]                   1.14.10-2

Versions of packages dbus is related to:
ii  dbus-x11      1.14.10-2
ii  systemd       254.5-1
ii  systemd-sysv  254.5-1

-- no debconf information

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)

More information about the Pkg-utopia-maintainers mailing list