dx-packages team mailing list archive

Thread
Date
[Bug 1871538] Re: dbus timeout-ed during an upgrade, taking services down including gdm

To: dx-packages@xxxxxxxxxxxxxxxxxxx
From: Iain Lane <1871538@xxxxxxxxxxxxxxxxxx>
Date: Fri, 25 Sep 2020 16:51:04 -0000
Reply-to: Bug 1871538 <1871538@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Yeah, sorry, I don't think that's a reproducer for the bug. You killed
dbus, gdm and everything else, and they obligingly died on you. :)

My feeling is that this bug is about a deadlock that somehow happens
when dbus and/or systemd are reloaded, possibly at the same time. It
looks like dbus stops responding to systemd, and so when it calls
GetNameOwner() to be able to watch type=dbus units, it gets no reply and
then decides to kill all type=dbus units, which is a lot of things. If
that's right, it's most likely to be a dbus bug that it can get into
this state. But I'm personally at a bit of a loss as to how to approach
it without being able to reproduce.

-- 
You received this bug notification because you are a member of DX
Packages, which is subscribed to accountsservice in Ubuntu.
Matching subscriptions: dx-packages
https://bugs.launchpad.net/bugs/1871538

Title:
  dbus timeout-ed during an upgrade, taking services down including gdm

Status in systemd:
  New
Status in accountsservice package in Ubuntu:
  Invalid
Status in dbus package in Ubuntu:
  Incomplete
Status in gnome-shell package in Ubuntu:
  Invalid
Status in accountsservice source package in Focal:
  Invalid
Status in dbus source package in Focal:
  Incomplete
Status in gnome-shell source package in Focal:
  Invalid

Bug description:
  This morning I found my computer on the login screen.
  But not the one of the screen log, no a new one - so something must have crashed.

  Logging in again confirmed that all apps were gone and the gnome shell
  was brought down what seems like triggered by a background update o
  accountsservice.

  As always things are not perfectly clear :-/
  The following goes *back* in time through my logs one by one.

  Multiple apps crashed at 06:09, but we will find later that this is a follow on issue of the underlying gnome/X/... recycling.
  -rw-r-----  1 paelzer  whoopsie 52962868 Apr  8 06:09 _usr_bin_konversation.1000.crash
  -rw-r-----  1 paelzer  whoopsie   986433 Apr  8 06:09 _usr_lib_x86_64-linux-gnu_libexec_drkonqi.1000.crash

  
  rdkit was failing fast and giving up (that will be a different bug, it just seems broken on my system):
  Apr 08 06:10:13 Keschdeichel systemd[1]: Started RealtimeKit Scheduling Policy Service.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Successfully called chroot.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Successfully dropped privileges.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Successfully limited resources.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: pthread_create failed: Resource temporarily unavailable
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Canary thread running.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Exiting canary thread.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Demoting known real-time threads.
  Apr 08 06:10:13 Keschdeichel rtkit-daemon[1729333]: Demoted 0 threads.
  Apr 08 06:10:13 Keschdeichel systemd[1]: rtkit-daemon.service: Main process exited, code=exited, status=1/FAILURE
  Apr 08 06:10:13 Keschdeichel systemd[1]: rtkit-daemon.service: Failed with result 'exit-code'.
  Apr 08 06:10:13 Keschdeichel dbus-daemon[1208]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.1176' (uid=121 pid=>
  Apr 08 06:10:13 Keschdeichel systemd[1]: rtkit-daemon.service: Start request repeated too quickly.
  Apr 08 06:10:13 Keschdeichel systemd[1]: rtkit-daemon.service: Failed with result 'exit-code'.
  Apr 08 06:10:13 Keschdeichel systemd[1]: Failed to start RealtimeKit Scheduling Policy Service.
  Apr 08 06:10:13 Keschdeichel bluetoothd[1729331]: Bluetooth daemon 5.53

  
  But that already was only triggered by a gnome restart that kicked of earlier:

  Apr 08 06:09:27 Keschdeichel systemd[1726656]: Started GNOME Shell on Wayland.
  Apr 08 06:09:27 Keschdeichel systemd[1726656]: Reached target GNOME Shell on Wayland.
  Apr 08 06:09:27 Keschdeichel systemd[1726656]: Reached target GNOME Session is initialized.
  Apr 08 06:09:27 Keschdeichel systemd[1726656]: Reached target GNOME Wayland Session.
  Apr 08 06:09:27 Keschdeichel systemd[1726656]: Reached target GNOME Session (session: gnome-login).

  
  X was recycleing before:
  Apr 08 06:09:19 Keschdeichel systemd[10683]: Stopping GNOME Shell on X11...
  ...
  Apr 08 06:09:22 Keschdeichel /usr/lib/gdm3/gdm-x-session[10710]: (EE) systemd-logind: ReleaseControl failed: Unknown object '/org/freedesktop/login1/session/_32'.
  Apr 08 06:09:22 Keschdeichel /usr/lib/gdm3/gdm-x-session[10710]: (II) Server terminated successfully (0). Closing log file.

  
  It seems like some internal service broke and everything that followed was a secondary issue to that:
  Apr 08 06:09:19 Keschdeichel systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel systemd[1]: wpa_supplicant.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel systemd[1]: thermald.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel thermald[1256]: [WARN]Terminating ...
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Got SIGTERM, quitting.
  Apr 08 06:09:19 Keschdeichel systemd[1]: udisks2.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel ModemManager[1308]: <info>  Caught signal, shutting down...
  Apr 08 06:09:19 Keschdeichel systemd[1]: switcheroo-control.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface vnet0.IPv6 with address fe80::fc54:ff:fe78:26c2.
  Apr 08 06:09:19 Keschdeichel systemd[1]: accounts-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface strswanbr2.IPv4 with address 192.168.2.0.
  Apr 08 06:09:19 Keschdeichel systemd[1]: gdm.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface virbr0.IPv4 with address 192.168.122.1.
  Apr 08 06:09:19 Keschdeichel systemd[1]: systemd-logind.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface strswanbr1.IPv4 with address 192.168.1.0.
  Apr 08 06:09:19 Keschdeichel systemd[1]: systemd-machined.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface lxdbr0.IPv6 with address fd42:fa18:c923:35d5::1.
  Apr 08 06:09:19 Keschdeichel systemd-machined[1255]: Failed to drop reference to machine scope, ignoring: Transport endpoint is not connected
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface lxdbr0.IPv4 with address 10.253.194.1.
  Apr 08 06:09:19 Keschdeichel systemd[1]: switcheroo-control.service: Succeeded.
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface wlp4s0.IPv6 with address fe80::6832:c873:a074:2c7b.
  Apr 08 06:09:19 Keschdeichel systemd[1]: systemd-machined.service: Succeeded.
  Apr 08 06:09:19 Keschdeichel bluetoothd[1724347]: Terminating
  Apr 08 06:09:19 Keschdeichel systemd[1]: avahi-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface wlp4s0.IPv4 with address 10.7.0.42.
  Apr 08 06:09:19 Keschdeichel systemd[1]: ModemManager.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface enp0s31f6.IPv6 with address fe80::80a8:743:6b37:e561.
  Apr 08 06:09:19 Keschdeichel systemd[1]: polkit.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface enp0s31f6.IPv4 with address 10.7.0.69.
  Apr 08 06:09:19 Keschdeichel systemd[1]: bolt.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface lo.IPv6 with address ::1.
  Apr 08 06:09:19 Keschdeichel systemd[1]: rtkit-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
  Apr 08 06:09:19 Keschdeichel systemd[1]: packagekit.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel wpa_supplicant[1265]: nl80211: deinit ifname=p2p-dev-wlp4s0 disabled_11b_rates=0
  Apr 08 06:09:19 Keschdeichel systemd[1]: colord.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel systemd[1]: upower.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel systemd[1]: bluetooth.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel systemd[1]: fwupd.service: Unexpected error response from GetNameOwner(): Connection terminated
  Apr 08 06:09:19 Keschdeichel xdg-desktop-por[11011]: xdg-desktop-portal-gtk: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.
  Apr 08 06:09:19 Keschdeichel NetworkManager[1209]: <info>  [1586318959.7797] caught SIGTERM, shutting down normally.
  Apr 08 06:09:19 Keschdeichel avahi-daemon[1204]: avahi-daemon 0.7 exiting.
  Apr 08 06:09:19 Keschdeichel systemd[1]: rtkit-daemon.service: Succeeded.
  Apr 08 06:09:19 Keschdeichel systemd[1]: Starting Process error reports when automatic reporting is enabled...
  Apr 08 06:09:19 Keschdeichel systemd[1]: colord.service: Succeeded.
  Apr 08 06:09:19 Keschdeichel systemd[10683]: Stopped target GNOME X11 Session (session: ubuntu).
  Apr 08 06:09:19 Keschdeichel systemd[10683]: Stopped target Current graphical user session.
  Apr 08 06:09:19 Keschdeichel systemd[10683]: unicast-local-avahi.path: Succeeded.
  Apr 08 06:09:19 Keschdeichel systemd[10683]: Stopped Path trigger for Avahi .local domain notifications.
  Apr 08 06:09:19 Keschdeichel systemd[10683]: update-notifier-release.path: Succeeded.
  Apr 08 06:09:19 Keschdeichel gnome-shell[11036]: gnome-shell: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.

  The last things before was systemd reload - maybe due to a background
  upgrade?

  Apr 08 06:08:54 Keschdeichel dbus-daemon[1208]: Unknown group "power" in message bus configuration file
  Apr 08 06:08:54 Keschdeichel dbus-daemon[1208]: [system] Reloaded configuration
  Apr 08 06:08:54 Keschdeichel dbus-daemon[1208]: Unknown group "power" in message bus configuration file
  Apr 08 06:08:54 Keschdeichel dbus-daemon[1208]: [system] Reloaded configuration
  Apr 08 06:08:54 Keschdeichel dbus-daemon[1208]: Unknown group "power" in message bus configuration file
  Apr 08 06:08:54 Keschdeichel systemd[1]: Reloading.

  
  And indeed there was an upgrade going on:

  40773 2020-04-08 06:08:46 status installed libc-bin:amd64 2.31-0ubuntu7                
  40774 2020-04-08 06:08:54 startup archives unpack                                      
  40775 2020-04-08 06:08:54 upgrade accountsservice:amd64 0.6.55-0ubuntu10 0.6.55-0ubuntu11
  40776 2020-04-08 06:08:54 status half-configured accountsservice:amd64 0.6.55-0ubuntu10
  40777 2020-04-08 06:08:54 status unpacked accountsservice:amd64 0.6.55-0ubuntu10       
  40778 2020-04-08 06:08:54 status half-installed accountsservice:amd64 0.6.55-0ubuntu10 
  40779 2020-04-08 06:08:54 status triggers-pending dbus:amd64 1.12.16-2ubuntu2          
  40780 2020-04-08 06:09:19 status unpacked accountsservice:amd64 0.6.55-0ubuntu11       
  40781 2020-04-08 06:09:20 upgrade libaccountsservice0:amd64 0.6.55-0ubuntu10 0.6.55-0ubuntu11
  40782 2020-04-08 06:09:20 status triggers-pending libc-bin:amd64 2.31-0ubuntu7         
  40783 2020-04-08 06:09:20 status half-configured libaccountsservice0:amd64 0.6.55-0ubuntu10
  40784 2020-04-08 06:09:20 status unpacked libaccountsservice0:amd64 0.6.55-0ubuntu10   
  40785 2020-04-08 06:09:20 status half-installed libaccountsservice0:amd64 0.6.55-0ubuntu10
  40786 2020-04-08 06:09:20 status unpacked libaccountsservice0:amd64 0.6.55-0ubuntu11

  Nothing suspicious before that time.

  ProblemType: Bug
  DistroRelease: Ubuntu 20.04
  Package: accountsservice 0.6.55-0ubuntu11
  ProcVersionSignature: Ubuntu 5.3.0-45.37~18.04.1-generic 5.3.18
  Uname: Linux 5.3.0-45-generic x86_64
  NonfreeKernelModules: zfs zunicode zavl icp zcommon znvpair
  ApportVersion: 2.20.11-0ubuntu24
  Architecture: amd64
  CurrentDesktop: ubuntu:GNOME
  Date: Wed Apr  8 07:51:03 2020
  InstallationDate: Installed on 2018-10-12 (543 days ago)
  InstallationMedia: Ubuntu 18.04.1 LTS "Bionic Beaver" - Release amd64 (20180725)
  SourcePackage: accountsservice
  UpgradeStatus: Upgraded to focal on 2020-04-03 (4 days ago)

To manage notifications about this bug go to:
https://bugs.launchpad.net/systemd/+bug/1871538/+subscriptions
References

[Bug 1871538] [NEW] Gnome Shell crashed on background upgrade of accountsservice
From: Christian Ehrhardt , 2020-04-08