aad-auth
aad-auth copied to clipboard
ubuntu
Login succeeds but dbus crashes on openSUSE
I've built aad-auth on openSUSE, and I'm encountering an issue (posting here to see if you guys have any ideas). The authentication is successful and nss is working fine, but I'm seeing the following error from dbus:
May 04 13:22:03 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[8186]: dbus[8186]: Could not get password database information for UID of current process: User "???" unknown or no memory to allocate password entry
After which I'm dumped back to the login shell. The message is coming from dbus: dbus-1.14.6/dbus/dbus-sysdeps-unix.c:fill_user_info which has apparently been passed a NULL username.
Any thoughts?
I was able to determine a call to getpwuid_r with the correct UID is failing. I'm not sure why. getent passwd with the UID succeeds.
If I su as the user, I can successfully auth, and then I see similar behavior:
su - '[email protected]'
Password:
I have no name!@localhost:~> getent passwd 100763296
I have no name!@localhost:~>
It appears that the nss calls all fail if the request comes from a process owned by that user (but succeeds for all other users, including non-root local users).
Hey @dmulder, thanks for reporting the issue! Would you mind following the steps listed in our Troubleshoot and provide us with more information? It does look like a NSS problem, but we need more logs to narrow down the point of failure.
I've added NSS_AAD_DEBUG=1 to /etc/bash.bashrc (openSUSE doesn't have the file /etc/environment), but I'm not getting any any debug from NSS.
The debug I am getting:
May 16 01:12:52 localhost.localdomain gdm-password][1806]: gkr-pam: unable to locate daemon control file
May 16 01:12:52 localhost.localdomain gdm-password][1806]: gkr-pam: stashed password to try later in open session
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_unix(gdm-password:auth): authentication failure; logname= uid=0 euid=0 tty=/dev/tty7 ruser= rhost= [email protected]
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): aad auth debug enabled
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): PAM AAD DEBUG enabled
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Loading configuration from /etc/aad.conf
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Could not open /etc/adduser.conf, using defaults for homedir and shell: open /etc/adduser.conf: no such file or directory
May 16 01:12:52 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Connecting to "https://login.microsoftonline.com/XXXXXX", with clientID "XXXXXX" for user "[email protected]"
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Authentication successful with user/password
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Cache initialization
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Opening cache in /var/lib/aad/cache
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): check file permissions on /var/lib/aad/cache/passwd.db
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): check file permissions on /var/lib/aad/cache/shadow.db
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Shadow db mode: 2
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Cleaning up db. Removing entries that last authenticated online more than 180 days ago
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): getting user information from cache for "[email protected]"
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): encrypt password for user "[email protected]"
May 16 01:12:53 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): updating from last online login information for user "[email protected]"
May 16 01:12:54 localhost.localdomain gdm-password][1806]: pam_aad(gdm-password:auth): Close database request
May 16 01:12:54 localhost.localdomain accounts-daemon[784]: request by system-bus-name::1.52 [gdm-session-worker [pam/gdm-password] pid:1806 uid:0]: cache user '[email protected]'
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: client fd 36 accepted
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: read credentials byte
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: Credentials: pid 1806 uid 0
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: getsockopt failed with Protocol not available, len now 1024
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: Failed to getsockopt(SO_PEERSEC): Protocol not available
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: Got uid of 0 in _dbus_user_database_get_uid
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: uid is now 0 in _dbus_user_database_lookup
May 16 01:12:54 localhost.localdomain dbus-daemon[631]: Using cache for UID 0 information
May 16 01:12:54 localhost.localdomain gdm-password][1806]: pam_systemd(gdm-password:session): Failed to create session: No such process
May 16 01:12:55 localhost.localdomain gdm-password][1806]: pam_unix(gdm-password:session): session opened for user [email protected](uid=100763296) by [email protected](uid=0)
May 16 01:12:55 localhost.localdomain gdm-password][1806]: gkr-pam: unable to locate daemon control file
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: client fd 36 accepted
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: read credentials byte
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: Credentials: pid 1818 uid 100763296
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: getsockopt failed with Protocol not available, len now 1024
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: Failed to getsockopt(SO_PEERSEC): Protocol not available
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: Got uid of 100763296 in _dbus_user_database_get_uid
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: uid is now 100763296 in _dbus_user_database_lookup
May 16 01:12:55 localhost.localdomain dbus-daemon[631]: Using cache for UID 100763296 information
May 16 01:12:55 localhost.localdomain gdm-password][1806]: gkr-pam: gnome-keyring-daemon started properly and unlocked keyring
May 16 01:12:55 localhost.localdomain kernel: rfkill: input handler enabled
May 16 01:12:55 localhost.localdomain gsd-media-keys[1260]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
May 16 01:12:55 localhost.localdomain gsd-media-keys[1260]: Unable to get default source
May 16 01:12:55 localhost.localdomain gsd-media-keys[1260]: Unable to get default sink
May 16 01:12:55 localhost.localdomain gnome-shell[1082]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: getuid for proc returns: 100763296
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: Got uid of 100763296 in _dbus_user_database_get_uid
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: uid is now 100763296 in _dbus_user_database_lookup
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: No cache for UID 100763296
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: Cache not found, doing a fill info uid
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: Trying to fill user info
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: getpwuid_r with uid: 100763296
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: User ??? unknown
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: Could not get password database information for UID of current process: User "???" unknown or no memory to allocate password entry
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1836]: dbus[1836]: Failed to start message bus: Memory allocation failure in message bus
May 16 01:12:55 localhost.localdomain /usr/libexec/gdm/gdm-wayland-session[1831]: Unable to run session message bus
May 16 01:12:55 localhost.localdomain gdm-password][1806]: pam_unix(gdm-password:session): session closed for user [email protected]
May 16 01:12:56 localhost.localdomain gdm[778]: Gdm: GdmDisplay: Session never registered, failing
May 16 01:12:56 localhost.localdomain wireplumber[1207]: dbus[1207]: connecting to unix socket /run/dbus/system_bus_socket abstract=0
May 16 01:12:56 localhost.localdomain wireplumber[1207]: dbus[1207]: socket fd 23 opened
May 16 01:12:56 localhost.localdomain wireplumber[1207]: dbus[1207]: wrote credentials byte
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: client fd 27 accepted
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: read credentials byte
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: Credentials: pid 1207 uid 458
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: getsockopt failed with Protocol not available, len now 1024
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: Failed to getsockopt(SO_PEERSEC): Protocol not available
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: Got uid of 458 in _dbus_user_database_get_uid
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: uid is now 458 in _dbus_user_database_lookup
May 16 01:12:56 localhost.localdomain dbus-daemon[631]: Using cache for UID 458 information
May 16 01:12:56 localhost.localdomain kernel: rfkill: input handler disabled
May 16 01:12:56 localhost.localdomain wireplumber[1207]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NameHasNoOwner
May 16 01:12:56 localhost.localdomain gsd-media-keys[1260]: Unable to get default sink
May 16 01:12:56 localhost.localdomain gsd-media-keys[1260]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
May 16 01:12:56 localhost.localdomain gsd-media-keys[1260]: gvc_mixer_card_get_index: assertion 'GVC_IS_MIXER_CARD (card)' failed
May 16 01:12:56 localhost.localdomain org.gnome.Shell.desktop[1868]: The XKEYBOARD keymap compiler (xkbcomp) reports:
May 16 01:12:56 localhost.localdomain org.gnome.Shell.desktop[1868]: > Warning: Unsupported maximum keycode 708, clipping.
May 16 01:12:56 localhost.localdomain org.gnome.Shell.desktop[1868]: > X11 cannot support keycodes above 255.
May 16 01:12:56 localhost.localdomain org.gnome.Shell.desktop[1868]: Errors from xkbcomp are not fatal to the X server
I've obfuscated some of the info in the log.
Hmm, not having NSS logs is weird. Can you double check to see if the NSS module is installed and linked in the nsswitch.conf file? There should be something like:
# nsswitch.conf
passwd: files systemd aad
Recall that getent passwd is working (though only as non-aad users). I'm not at my machine, but will double check nss config later.