Installing/purging authd-msentraid snap sometimes causes D-Bus daemon to hang

adombeck commented 3 months ago

Describe the issue

I can somewhat reliably reproduce the error with the steps to reproduce below.

I first encountered the issue with my force-clean-install script.

Steps to reproduce it

Install authd and authd-mesentraid:

sudo apt install -y authd
sudo snap install authd-msentraid --edge

Stop authd and reinstall authd-msentraid with a single sudo command:

sudo sh -c "systemctl stop authd; snap remove --purge authd-msentraid; snap install authd-msentraid --edge"

Observe how the installation of authd-msentraid hangs in the Run install hook of "authd-msentraid" snap if present step.
Open another terminal and try to run command with sudo:
```
sudo journalctl
```
Wait ~20 seconds

Observe sudo failing with the following error message:

could not get current available brokers: couldn't connect to authd daemon: connection error: desc = "error reading server preface: read unix @->/run/authd.sock: use of closed network connection"
sudo: PAM authentication error: Unknown error -1
sudo: a password is required

Wait until the installation of authd-msentraid succeeds. Sometimes gnome-shell crashes before the installation of authd-msentraid succeeds.

System information and logs

Relevant snippet from the journal:

Aug 16 12:56:23 ubuntu snapd[849]: api_snaps.go:427: Installing snap "authd-msentraid" revision unset
Aug 16 12:56:24 ubuntu systemd[1]: Reloading requested from client PID 15691 ('systemctl') (unit snapd.service)...
Aug 16 12:56:24 ubuntu systemd[1]: Reloading...
Aug 16 12:56:25 ubuntu systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
Aug 16 12:56:25 ubuntu systemd[1]: Reloading finished in 249 ms.
Aug 16 12:56:25 ubuntu systemd[1]: Cannot find unit for notify message of PID 15691, ignoring.
Aug 16 12:56:25 ubuntu systemd[1]: Mounting snap-authd\x2dmsentraid-30.mount - Mount unit for authd-msentraid, revision 30...
Aug 16 12:56:25 ubuntu kernel: loop18: detected capacity change from 0 to 34480
Aug 16 12:56:25 ubuntu systemd[1]: Mounted snap-authd\x2dmsentraid-30.mount - Mount unit for authd-msentraid, revision 30.
Aug 16 12:56:26 ubuntu systemd[1]: Starting authd.service - Authd daemon service...
Aug 16 12:56:26 ubuntu kernel: audit: type=1400 audit(1723805786.858:256): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.authd-msentraid" pid=15843 comm="apparmor_parser"
Aug 16 12:56:26 ubuntu kernel: audit: type=1400 audit(1723805786.918:257): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.hook.install" pid=15845 comm="apparmor_parser"
Aug 16 12:56:26 ubuntu kernel: audit: type=1400 audit(1723805786.921:258): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.authd-msentraid" pid=15844 comm="apparmor_parser"
Aug 16 12:56:27 ubuntu systemd[1]: Reloading requested from client PID 15846 ('systemctl') (unit snapd.service)...
Aug 16 12:56:27 ubuntu systemd[1]: Reloading...
Aug 16 12:56:27 ubuntu systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
Aug 16 12:56:27 ubuntu systemd[1]: Reloading finished in 226 ms.
Aug 16 12:56:27 ubuntu systemd[1]: Cannot find unit for notify message of PID 15846, ignoring.
Aug 16 12:56:28 ubuntu systemd[1]: Cannot find unit for notify message of PID 15976, ignoring.
Aug 16 12:56:28 ubuntu systemd[1]: Cannot find unit for notify message of PID 15980, ignoring.
Aug 16 12:56:29 ubuntu kernel: audit: type=1400 audit(1723805789.075:259): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/21759/usr/lib/snapd/snap-confine" pid=15992 comm="apparmor_parser"
Aug 16 12:56:29 ubuntu kernel: audit: type=1400 audit(1723805789.075:260): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/21759/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=15992 comm="apparmor_parser"
Aug 16 12:56:29 ubuntu kernel: audit: type=1400 audit(1723805789.171:261): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.authd-msentraid.authd-msentraid" pid=15994 comm="apparmor_parser"
Aug 16 12:56:29 ubuntu kernel: audit: type=1400 audit(1723805789.176:262): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.authd-msentraid" pid=15996 comm="apparmor_parser"
Aug 16 12:56:29 ubuntu kernel: audit: type=1400 audit(1723805789.177:263): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.hook.install" pid=15997 comm="apparmor_parser"
Aug 16 12:56:57 ubuntu sudo[16010]:     user : PAM authentication error: Unknown error -1 ; TTY=pts/2 ; PWD=/home/user ; USER=root ; COMMAND=/usr/bin/journalctl -e
Aug 16 12:57:51 ubuntu dbus-daemon[782]: [system] Reloaded configuration
Aug 16 12:57:51 ubuntu cups-browsed[1157]: WARNING: Unhandled message: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=ActivatableServicesChanged
Aug 16 12:57:56 ubuntu systemd[1]: authd.service: start operation timed out. Terminating.
Aug 16 12:57:57 ubuntu systemd[1]: NetworkManager.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: systemd-networkd.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: udisks2.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: switcheroo-control.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: power-profiles-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: gnome-remote-desktop.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: accounts-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: gdm.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: wpa_supplicant.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: thermald.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: systemd-oomd.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: Got SIGTERM, quitting.
Aug 16 12:57:57 ubuntu systemd[1]: systemd-logind.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: Leaving mDNS multicast group on interface enp1s0.IPv6 with address fe80::5054:ff:fec1:cee5.
Aug 16 12:57:57 ubuntu systemd[1]: avahi-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: Leaving mDNS multicast group on interface enp1s0.IPv4 with address 192.168.122.54.
Aug 16 12:57:57 ubuntu systemd[1]: ModemManager.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: Leaving mDNS multicast group on interface lo.IPv6 with address ::1.
Aug 16 12:57:57 ubuntu systemd[1]: polkit.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Aug 16 12:57:57 ubuntu systemd[1]: wpa_supplicant.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu ModemManager[12091]: <msg> caught signal, shutting down...
Aug 16 12:57:57 ubuntu systemd[1]: systemd-timesyncd.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: systemd-resolved.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: systemd-timedated.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: packagekit.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: rtkit-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: upower.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: fwupd.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu systemd[1]: colord.service: Unexpected error response from GetNameOwner(): Connection terminated
Aug 16 12:57:57 ubuntu fwupd[12649]: 10:57:57.875 FuMain               Received SIGTERM
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session-wayland@ubuntu.target - GNOME Wayland Session (session: ubuntu).
Aug 16 12:57:57 ubuntu avahi-daemon[11597]: avahi-daemon 0.8 exiting.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-afc-volume-monitor.service - Virtual filesystem service - Apple File Conduit monitor...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-daemon.service - Virtual filesystem service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-goa-volume-monitor.service - Virtual filesystem service - GNOME Online Accounts monitor...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-gphoto2-volume-monitor.service - Virtual filesystem service - digital camera monitor...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-metadata.service - Virtual filesystem metadata service...
Aug 16 12:57:57 ubuntu systemd[1]: accounts-daemon.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-mtp-volume-monitor.service - Virtual filesystem service - Media Transfer Protocol monitor...
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Owner of volume monitor org.gtk.vfs.AfcVolumeMonitor disconnected from the bus; removing drives/volumes/mounts
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping gvfs-udisks2-volume-monitor.service - Virtual filesystem service - disk device monitor...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping xdg-desktop-portal-gnome.service - Portal service (GNOME implementation)...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping xdg-desktop-portal.service - Portal service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping xdg-document-portal.service - flatpak document portal service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping xdg-permission-store.service - sandboxed app permission store...
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Owner of volume monitor org.gtk.vfs.GoaVolumeMonitor disconnected from the bus; removing drives/volumes/mounts
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Owner of volume monitor org.gtk.vfs.MTPVolumeMonitor disconnected from the bus; removing drives/volumes/mounts
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Owner of volume monitor org.gtk.vfs.GPhoto2VolumeMonitor disconnected from the bus; removing drives/volumes/mounts
Aug 16 12:57:57 ubuntu systemd[1]: run-user-1000-gvfs.mount: Deactivated successfully.
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Owner of volume monitor org.gtk.vfs.UDisks2VolumeMonitor disconnected from the bus; removing drives/volumes/mounts
Aug 16 12:57:57 ubuntu systemd[1]: avahi-daemon.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped xdg-permission-store.service - sandboxed app permission store.
Aug 16 12:57:57 ubuntu systemd[1]: run-user-1000-doc.mount: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1]: polkit.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-daemon.service - Virtual filesystem service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-udisks2-volume-monitor.service - Virtual filesystem service - disk device monitor.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-goa-volume-monitor.service - Virtual filesystem service - GNOME Online Accounts monitor.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-gphoto2-volume-monitor.service - Virtual filesystem service - digital camera monitor.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-afc-volume-monitor.service - Virtual filesystem service - Apple File Conduit monitor.
Aug 16 12:57:57 ubuntu systemd[1]: rtkit-daemon.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-mtp-volume-monitor.service - Virtual filesystem service - Media Transfer Protocol monitor.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped xdg-desktop-portal.service - Portal service.
Aug 16 12:57:57 ubuntu systemd[1]: colord.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped xdg-desktop-portal-gnome.service - Portal service (GNOME implementation).
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gvfs-metadata.service - Virtual filesystem metadata service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped xdg-document-portal.service - flatpak document portal service.
Aug 16 12:57:57 ubuntu systemd[1]: packagekit.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1]: packagekit.service: Consumed 8.855s CPU time, 170.6M memory peak, 0B memory swap peak.
Aug 16 12:57:57 ubuntu systemd[1]: upower.service: Deactivated successfully.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped gnome-session-monitor.service - Monitor Session leader for GNOME Session.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target graphical-session.target - Current graphical user session.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped update-notifier-crash.path - Path trigger for Apport crash notifications.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped update-notifier-release.path - Path trigger for new release of Ubuntu notifications.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session.target - GNOME Session.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session-wayland.target - GNOME Wayland Session.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session-x11-services-ready.target - GNOME session X11 services.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session@ubuntu.target - GNOME Session (session: ubuntu).
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.A11ySettings.target - GNOME accessibility target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Color.target - GNOME color management target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Datetime.target - GNOME date & time target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Housekeeping.target - GNOME maintenance of expirable data target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Keyboard.target - GNOME keyboard configuration target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.MediaKeys.target - GNOME keyboard shortcuts target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Power.target - GNOME power management target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.PrintNotifications.target - GNOME printer notifications target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Rfkill.target - GNOME RFKill support target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.ScreensaverProxy.target - GNOME FreeDesktop screensaver target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Sharing.target - GNOME file sharing target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Smartcard.target - GNOME smartcard target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Sound.target - GNOME sound sample caching target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.Wacom.target - GNOME Wacom tablet support target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.SettingsDaemon.XSettings.target - GNOME XSettings target.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.A11ySettings.service - GNOME accessibility service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Color.service - GNOME color management service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Datetime.service - GNOME date & time service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Housekeeping.service - GNOME maintenance of expirable data service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Keyboard.service - GNOME keyboard configuration service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.MediaKeys.service - GNOME keyboard shortcuts service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Power.service - GNOME power management service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.PrintNotifications.service - GNOME printer notifications service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Rfkill.service - GNOME RFKill support service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.ScreensaverProxy.service - GNOME FreeDesktop screensaver service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Sharing.service - GNOME file sharing service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Smartcard.service - GNOME smartcard service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Sound.service - GNOME sound sample caching service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.Wacom.service - GNOME Wacom tablet support service...
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.SettingsDaemon.XSettings.service - GNOME XSettings service...
Aug 16 12:57:57 ubuntu kernel: rfkill: input handler enabled
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Datetime.service - GNOME date & time service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Color.service - GNOME color management service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Housekeeping.service - GNOME maintenance of expirable data service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.A11ySettings.service - GNOME accessibility service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Keyboard.service - GNOME keyboard configuration service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Power.service - GNOME power management service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.PrintNotifications.service - GNOME printer notifications service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Rfkill.service - GNOME RFKill support service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Sharing.service - GNOME file sharing service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Smartcard.service - GNOME smartcard service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Sound.service - GNOME sound sample caching service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.MediaKeys.service - GNOME keyboard shortcuts service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.Wacom.service - GNOME Wacom tablet support service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.ScreensaverProxy.service - GNOME FreeDesktop screensaver service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped org.gnome.SettingsDaemon.XSettings.service - GNOME XSettings service.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session-x11-services.target - GNOME session X11 services.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target gnome-session-initialized.target - GNOME Session is initialized.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopped target org.gnome.Shell.target - GNOME Shell.
Aug 16 12:57:57 ubuntu systemd[1182]: Stopping org.gnome.Shell@wayland.service - GNOME Shell on Wayland...
Aug 16 12:57:57 ubuntu guake.desktop[12192]: System doesn't support transparency
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Connection to xwayland lost
Aug 16 12:57:57 ubuntu gnome-shell[11753]: Shutting down GNOME Shell

adombeck commented 2 months ago

I spent some more time investigating this issue. Here are some findings:

The issue can be reliably triggered by stopping authd and then purging or installing the authd-msentraid snap:

sudo sh -c "systemctl stop authd && snap remove --purge authd-msentraid"

or

sudo sh -c "systemctl stop authd && snap install authd-msentraid"

The snap remove / snap install command causes the authd service to be restarted, but authd hangs when it tries to authenticate to the system bus because the D-Bus daemon for the system bus doesn't respond.
When that happens, the D-Bus daemon doesn't respond to anything (like dbus-monitor --system or any calls made by d-feet) for 85 seconds.
After 55 seconds, the following message is printed to the journal (which is also printed when I run systemctl reload dbus so it indicates that the D-Bus daemon is reloaded):
```
dbus-daemon[817]: Unknown group "power" in message bus configuration file
```
30 seconds later (smells like a timeout), the following message is printed to the journal:
```
dbus-daemon[817]: [system] Reloaded configuration
```
Once that message is printed, D-Bus responds again and the authd service starts up

adombeck commented 2 months ago

Relevant messages from the journal (including debug output I added to authd and dbus-daemon) after I ran sudo sh -c "systemctl stop authd && snap install authd-msentraid":

Sep 16 22:46:42 ubuntu sudo[4882]:     user : TTY=pts/1 ; PWD=/home/user ; USER=root ; COMMAND=/usr/bin/sh -c 'systemctl stop authd && snap install authd-msentraid'
Sep 16 22:46:42 ubuntu sudo[4882]: pam_unix(sudo:session): session opened for user root(uid=0) by user(uid=1000)
Sep 16 22:46:42 ubuntu systemd[1]: Stopping authd.service - Authd daemon service...
Sep 16 22:46:42 ubuntu authd[962]: INFO Stopping daemon requested.
Sep 16 22:46:42 ubuntu authd[962]: INFO Wait for active requests to close.
Sep 16 22:46:42 ubuntu authd[962]: DEBUG All connections have now ended.
Sep 16 22:46:42 ubuntu authd[962]: XXX: Cleaning up broker manager
Sep 16 22:46:42 ubuntu authd[962]: INFO XXX: D-Bus connection closed
Sep 16 22:46:42 ubuntu systemd[1]: authd.service: Deactivated successfully.
Sep 16 22:46:42 ubuntu systemd[1]: Stopped authd.service - Authd daemon service.
Sep 16 22:46:42 ubuntu snapd[896]: api_snaps.go:427: Installing snap "authd-msentraid" revision unset
Sep 16 22:46:44 ubuntu systemd[1]: Reloading requested from client PID 4985 ('systemctl') (unit snapd.service)...
Sep 16 22:46:44 ubuntu systemd[1]: Reloading...
Sep 16 22:46:44 ubuntu systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
Sep 16 22:46:44 ubuntu systemd[1]: Reloading finished in 237 ms.
Sep 16 22:46:44 ubuntu systemd[1]: Cannot find unit for notify message of PID 4985, ignoring.
Sep 16 22:46:44 ubuntu systemd[1]: Mounting snap-authd\x2dmsentraid-44.mount - Mount unit for authd-msentraid, revision 44...
Sep 16 22:46:44 ubuntu kernel: loop0: detected capacity change from 0 to 34832
Sep 16 22:46:44 ubuntu systemd[1]: Mounted snap-authd\x2dmsentraid-44.mount - Mount unit for authd-msentraid, revision 44.
Sep 16 22:46:44 ubuntu systemd[1]: Starting authd.service - Authd daemon service...
Sep 16 22:46:45 ubuntu authd[5132]: INFO No configuration file: Config File "authd" Not Found in "[/ /etc/authd /usr/libexec]".
Sep 16 22:46:45 ubuntu authd[5132]: We will only use the defaults, env variables or flags.
Sep 16 22:46:45 ubuntu authd[5132]: DEBUG Debug mode is enabled
Sep 16 22:46:45 ubuntu authd[5132]: DEBUG Building authd object
Sep 16 22:46:45 ubuntu authd[5132]: DEBUG Building broker detection
Sep 16 22:46:45 ubuntu authd[5132]: DEBUG XXX: Connecting to system bus
Sep 16 22:46:45 ubuntu authd[5132]: DEBUG XXX: Authenticating to system bus
Sep 16 22:46:45 ubuntu authd[5132]: XXX: Sending null byte
Sep 16 22:46:45 ubuntu authd[5132]: XXX: Sending AUTH
Sep 16 22:46:45 ubuntu authd[5132]: XXX: Reading auth line
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.017:189): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.authd-msentraid" pid=5134 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.098:190): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.hook.install" pid=5136 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.102:191): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.authd-msentraid" pid=5135 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu systemd[1]: Reloading requested from client PID 5144 ('systemctl') (unit snapd.service)...
Sep 16 22:46:45 ubuntu systemd[1]: Reloading...
Sep 16 22:46:45 ubuntu systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
Sep 16 22:46:45 ubuntu systemd[1]: Reloading finished in 247 ms.
Sep 16 22:46:45 ubuntu systemd[1]: Cannot find unit for notify message of PID 5144, ignoring.
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.732:192): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/21759/usr/lib/snapd/snap-confine" pid=5282 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.732:193): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/snapd/21759/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=5282 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.826:194): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.authd-msentraid.authd-msentraid" pid=5284 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.831:195): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.authd-msentraid" pid=5286 comm="apparmor_parser"
Sep 16 22:46:45 ubuntu kernel: audit: type=1400 audit(1726519605.832:196): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.authd-msentraid.hook.install" pid=5287 comm="apparmor_parser"
Sep 16 22:47:39 ubuntu dbus-daemon[876]: Unknown group "power" in message bus configuration file
Sep 16 22:48:10 ubuntu dbus-daemon[876]: [system] Reloaded configuration
Sep 16 22:48:10 ubuntu cups-browsed[1236]: WARNING: Unhandled message: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=ActivatableServicesChanged
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In process_command: server command=AUTH
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In handle_server_state_waiting_for_auth: command=0, args=
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In handle_auth
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In process_command: server command=AUTH
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In handle_server_state_waiting_for_auth: command=0, args=
Sep 16 22:48:10 ubuntu dbus-daemon[876]: XXX: In handle_auth
Sep 16 22:48:10 ubuntu authd[5132]: XXX: Got auth line: [REJECTED EXTERNAL]

ubuntu / authd