Red Hat Bugzilla – Bug 1474899
GDM user logins failing because of systemd1 service failing
Last modified: 2017-08-14 04:56:52 EDT
Description of problem:
I recently upgraded a host from Fedora 24 to Fedora 26. The upgrade appeared to have completed with no issue. When attempting a terminal (VT) login, I see normal successful behavior. When I attempt a graphical (GDM) login with the same account the login iteslf succeeds, the screen flashes black, and the GDM prompt appears again. In troubleshooting this problem it appears to boil down to an issue launching the D-Bus service "org.freedesktop.systemd1.
The problem also appears if I attempt to run "systemctl --user" mode after a shell login, for example:
$ eval `dbus-launch --sh-syntax`
$ systemctl --user
Failed to list units: Process org.freedesktop.systemd1 exited with status 1
Version-Release number of selected component (if applicable):
Consistently; I thought it might be a single host problem but I see the same thing on a second host which also was stock Fedora 24 upgraded to Fedora 26.
Steps to Reproduce:
1. Have a working Fedora 24 host enrolled in an IPA domain.
2. Upgrade to Fedora 26 with default options (all packages upgraded and successful).
3. Attempt graphical logins with GDM under Fedora 26.
User is unable to consistently login to GDM.
Valid user should be able to login properly.
This error usually means that the systemd process is non-functional. In this case systemd@<uid>.service for your <uid>. Please attach the full logs from the boot, including a failed login attempt (journalctl -b).
Created attachment 1304785 [details]
boot and login log
This is the result of "journalctl -b" on one of the failing hosts.
After trying out logins some more on these hosts, it appears that after some time after boot (which seems to be inconsistent) I am able to get a graphical login on the host. Even after I do, the use of "systemctl --user" fails as described above. If I then log-out and attempt another login it will then fail when starting a gnome session (for the original reason above).
So there is some amount of non-repeatability that I'm seeing.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: Created slice User Slice of bsipos.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: Starting User Manager for UID 1364400003...
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd-logind: New session 2 of user bsipos.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: Started Session 2 of user bsipos.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: pam_sss(systemd-user:account): Access denied for user bsipos: 6 (Permission denied)
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com audit: USER_ACCT pid=1705 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=? acct="bsipos" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: firstname.lastname@example.org: Failed at step PAM spawning /usr/lib/systemd/systemd: Operation not permitted
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: Failed to start User Manager for UID 1364400003.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=user@1364400003 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: email@example.com: Unit entered failed state.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com systemd: firstname.lastname@example.org: Failed with result 'protocol'.
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com gdm-password]: pam_systemd(gdm-password:session): Failed to create session: Start job for unit email@example.com failed with 'failed'
Jul 26 08:48:18 dev-travel-t440.ipa.rkf-engineering.com gdm-password]: pam_unix(gdm-password:session): session opened for user bsipos by (uid=0)
Jul 26 08:48:19 dev-travel-t440.ipa.rkf-engineering.com audit: USER_START pid=1692 uid=0 auid=1364400003 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_keyinit,pam_namespace,pam_keyinit,pam_limits,pam_unix,pam_sss,pam_gnome_keyring acct="bsipos" exe="/usr/libexec/gdm-session-worker" hostname=dev-travel-t440.ipa.rkf-engineering.com addr=? terminal=/dev/tty2 res=success'
Jul 26 08:48:19 dev-travel-t440.ipa.rkf-engineering.com audit: USER_LOGIN pid=1692 uid=0 auid=1364400003 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='uid=1364400003 exe="/usr/libexec/gdm-session-worker" hostname=? addr=? terminal=? res=success'
It seems like pam_sss is denying the creation of the pam session. It'll reassing,
since this seems to be sssd specific.
Can you also paste your /etc/pam.d/systemd-user file?
It would be also good to provide sssd log files
BTW is user "bsipos" in local files /etc/passwd or from freeIPA?
This user is an IPA user, I do have a local account on a different host I can attach a log for. The thing about the GDM login is that it has the same failing behavior for the local user as the IPA user.
I am able to successufully get a non-graphical shell login from one of the VTs on the same host and I am able to enable SSH and get a remote shell login, which both work consistently. It's just the GDM login which has trouble.
Related to SSSd, I've also tried un-enrolling and re-enrolling the host with IPA. This has had no effect on the login trouble, seeing same behavior after as before the re-enrollment.
Created attachment 1304918 [details]
Copy of /etc/pam.d/systemd-user from failing host
Since it was mentioned above that the root cause seemed to be the "systemd-user" PAM service being disallowed, I checked my IPA HBAC configuration and found that my normal allow-user-login policy did not include the "systemd-user" service. I added that service to the allowed list in my IPA policy and now GDM logins (and "systemctl --user" from SSH logins) appear to work correctly.
We are mostly still on Fedora 24 here, and have just begun to migrate up to Fedora 26. I don't know when (either in FC25 or 26) that the behavior in either SSSD, PAM, or systemd may have changed but there may be a benefit in listing this issue on the upgrade bugs page <https://fedoraproject.org/wiki/Common_F26_bugs>. Only a suggestion, since this issue appears to be solved for me but this may help others figure out the same problem.
I can see /etc/pam.d/systemd-user also on fedora24 and fedora25
with the same content as you attached in Comment 7.
SSSD is the same on f24+.
Are you sure that it works for you on f24? Maybe HBAC rules were configured differently for different hosts.
If it works on f24/f25 and does not work after upgrade to f26 then something had to change in systemd.
Created attachment 1305363 [details]
journalctl log from succesful fedora 24 use
I've logged and attached a sequence from SSH login an "systemctl --user status" run. From what I can tell, it appears that systemd is using PAM differently between the two Fedora versions; in F24 it is using "pam_unix(systemd-user:session)" while in F26 it's using also "pam_sss(systemd-user:account)" to authorize access. F24 systemd never seems to use the PAM account validation.
I don't think systemd pam code or config changed.
Is /etc/pam.d/systemd-user and /etc/pam.d/system-auth identical between F24 and F26? (It is here...)
We added pam_loginuid in an update in F24 for #1328947. I believe that was the last significant change to the system pam stack.
Then /etc/pam.d/system-auth had to change after upgrade from f24 -> f26
Which might be related to BZ1449106. And some package called "authconfig --updateall" in rpm scriptlet. Because authconfig does not do it itself.
I was not able to see fixed version of authconfig for f24 in koji.
You might try to upgrade from f24 -> f25 and execute "authconfig --updateall" on your own. Then it might fail as well.
Or you can copy /etc/pam.d/system-auth from f26 to f24. And IMHO it will fail as well
Is *your* /etc/pam.d/system-auth different between f24 and f26? Please paste the diff.
Created attachment 1305617 [details]
differences from base fedora-24 to upgraded 24-to-26 file
I've attached a difference (from my other host running Fedora-24 enrolled on IPA domain) in the /etc/pam.d/system-auth file on my newly upgraded Fedora 26 host. This is after both an upgrade and an IPA unenroll-and-re-enroll to attempt to deal with my original problem.
As an interesting observation, I noticed that a freshly installed-and-enrolled Fedora 26 host has a fully identical /etc/pam.d/system-auth file from my installed-and-enrolled Fedora 24 host.
This difference is in auth and password phases of pam authentication so it does not affect session and account phase which validates the account. But to be sure, does it work if you use system-auth file from f24 on f26?
(In reply to Pavel Březina from comment #16)
> This difference is in auth and password phases of pam authentication so it
> does not affect session and account phase which validates the account. But
> to be sure, does it work if you use system-auth file from f24 on f26?
To clarify my original issue, the problem was never the PAM configuration on the Fedora log-in-able host. My problem was that in F24, systemd never requested the PAM service:method of "systemd-user:account" so I never needed to enable IPA HBAC rule for "systemd-user" to allow normal GDM logins.
In F26 (and maybe in F25, but I've not tested) there is now a use of PAM "systemd-user:account" so there needed to be a new IPA HBAC condition to allow this new use. I just didn't realize, until digging through logs and asking for your advice, that this PAM service was used/needed.
So to answer your question, the PAM configurations 'work' in both cases in that they are sending out proper requests to proper handlers.
We have had the same issue. In our case, the systemd-user is failing in F24 but that isn't
preventing login, whereas the failure in F26 does prevent login. It's my opinion that the
behaviour of gdm has changed. (I reported bug 1473806 but ultimately it's the same as
the bug here.)
*** Bug 1473806 has been marked as a duplicate of this bug. ***