Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
adombeck opened this issue Aug 16, 2024 · 2 comments
Open

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

adombeck opened this issue Aug 16, 2024 · 2 comments
Labels
bug Something isn't working jira

Comments

@adombeck
Copy link
Contributor

adombeck commented Aug 16, 2024 •
edited
Loading

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

  1. Install authd and authd-mesentraid: 
    sudo apt install -y authd
sudo snap install authd-msentraid --edge
  2. 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"
  3. Observe how the installation of authd-msentraid hangs in the Run install hook of "authd-msentraid" snap if present step.
  4. Open another terminal and try to run command with sudo: 
    sudo journalctl
  5. Wait ~20 seconds
  6. 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
  7. 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 [email protected] - 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 [email protected] - 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 [email protected] - 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 adombeck added bug Something isn't working jira labels Aug 16, 2024
@adombeck adombeck changed the title Reinstall of authd and broker sometimes leads to gnome-shell crash Reinstall of broker sometimes leads to gnome-shell crash Aug 26, 2024
@adombeck adombeck changed the title Reinstall of broker sometimes leads to gnome-shell crash Installing/purging authd-msentraid snap sometimes causes D-Bus to hang Sep 16, 2024
@adombeck adombeck changed the title Installing/purging authd-msentraid snap sometimes causes D-Bus to hang Installing/purging authd-msentraid snap sometimes causes D-Bus daemon to hang Sep 16, 2024
@adombeck
Copy link
Contributor Author

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
Copy link
Contributor Author

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]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working jira
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@adombeck