Description of problem: "systemd --user" launched NOT for NIS user Cannot run "systemctl --user" - kernel booted with "systemd.unified_cgroup_hierarchy=1" EDIT - resolved, identified 2 bugs: - slow login for NIS user: nis package missing dropin for systemd-userdbd.service to unset IPAddressDeny (see https://bugzilla.redhat.com/show_bug.cgi?id=1831141#c4) - NIS user login does not start "systemd --user" without nscd running Version-Release number of selected component (if applicable): F32 systemd 245 (v245.4-1.fc32) How reproducible: Everytime Steps to Reproduce: 1. install and setup nis client/slave on localhost, sync with remote NIS server 2. login via ssh or on console 3. run "systemctl --user status" Actual results: -- NIS setup # authselect current Profile ID: nis Enabled features: - with-pamaccess -- NIS user, served from local nis slave $ systemctl --user status Failed to connect to bus: No such file or directory -- locally added user $ systemctl --user status ● Unknown-00-0c-29-e0-2b-3f State: running Jobs: 0 queued Failed: 0 units Since: Mon 2020-05-04 18:10:31 BST; 11s ago CGroup: /user.slice/user-1001.slice/user └─init.scope ├─890 /usr/lib/systemd/systemd --user └─891 (sd-pam) Expected results: "systemd --user" launched for NIS user and thus able to run "systemd-run --user " Additional info: Login via console and shell. Seen in "journalctl -f" for sessions that do not have "systemd --user" started. Session login are slow (45sec) in this situation login[1061]: pam_systemd(login:session): Failed to get user record: Connection timed out On local user, XDG_* env variables exist - not available for NIS user session, in particular XDG_RUNTIME_DIR=/run/user/1001 (localuser) - there is no /run/user/500 for NIS user# On F30, starting "nscd" solved this problem - running "nscd" on F32 does NOT fix for NIS user and has impact on local user: .. prevents "systemd --user" from starting .. has slow login like NIS user
# /etc/nsswitch.conf --- aliases: files nis automount: files nis ethers: files nis group: files nis systemd hosts: files nis dns myhostname initgroups: files nis netgroup: files nis networks: files nis passwd: files nis systemd protocols: files nis publickey: files nis rpc: files nis services: files nis shadow: files nis gshadow: files --- Login on console, with NIS account (served from localhost), nscd not running/running is the same --- May 05 11:50:19 Unknown-00-0c-29-e0-2b-3f audit[787]: USER_AUTH pid=787 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:50:19 Unknown-00-0c-29-e0-2b-3f audit[787]: USER_ACCT pid=787 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix acct="ray" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:50:19 Unknown-00-0c-29-e0-2b-3f audit[787]: CRED_ACQ pid=787 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:50:19 Unknown-00-0c-29-e0-2b-3f systemd-userdbd[832]: yp_bind_client_create_v3: RPC: Unable to send May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f login[787]: pam_systemd(login:session): Failed to get user record: Connection timed out May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f login[787]: pam_unix(login:session): session opened for user ray by LOGIN(uid=0) May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f audit[787]: USER_START pid=787 uid=0 auid=500 ses=6 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_unix,pam_umask,pam_lastlog acct="ray" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f audit[787]: CRED_REFR pid=787 uid=0 auid=500 ses=6 msg='op=PAM:setcred grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f audit[787]: USER_LOGIN pid=787 uid=0 auid=500 ses=6 msg='op=login id=500 exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:51:04 Unknown-00-0c-29-e0-2b-3f login[787]: LOGIN ON tty1 BY ray --- Login on console, with local account, nscd running - 45s delay --- May 05 11:57:06 Unknown-00-0c-29-e0-2b-3f audit[1025]: USER_AUTH pid=1025 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_unix acct="dummy" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:57:06 Unknown-00-0c-29-e0-2b-3f audit[1025]: USER_ACCT pid=1025 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix acct="dummy" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:57:06 Unknown-00-0c-29-e0-2b-3f audit[1025]: CRED_ACQ pid=1025 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix acct="dummy" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f login[1025]: pam_systemd(login:session): Failed to get user record: Connection timed out May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f login[1025]: pam_unix(login:session): session opened for user dummy by LOGIN(uid=0) May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f login[1025]: LOGIN ON tty1 BY dummy May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f audit[1025]: USER_START pid=1025 uid=0 auid=1001 ses=8 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_unix,pam_umask,pam_lastlog acct="dummy" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f audit[1025]: CRED_REFR pid=1025 uid=0 auid=1001 ses=8 msg='op=PAM:setcred grantors=pam_unix acct="dummy" exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' May 05 11:57:51 Unknown-00-0c-29-e0-2b-3f audit[1025]: USER_LOGIN pid=1025 uid=0 auid=1001 ses=8 msg='op=login id=1001 exe="/usr/bin/login" hostname=Unknown-00-0c-29-e0-2b-3f addr=? terminal=tty1 res=success' ---
The `userdbd` appears to be where this is struggling - `strace` output for `userdbctl user ray` (where `ray` is the NIS user - `ypbind` is up and running. Notice the `13:48:52.557734 epoll_wait()` ``` 13:48:52.551590 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3 13:48:52.551819 connect(3, {sa_family=AF_UNIX, sun_path="/run/systemd/userdb/io.systemd.Multiplexer"}, 45) = 0 13:48:52.552054 epoll_create1(EPOLL_CLOEXEC) = 4 13:48:52.552274 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 5 13:48:52.552484 epoll_ctl(4, EPOLL_CTL_ADD, 5, {EPOLLIN, {u32=2920673360, u64=94831503601744}}) = 0 13:48:52.553107 epoll_ctl(4, EPOLL_CTL_ADD, 3, {0, {u32=2920675504, u64=94831503603888}}) = 0 13:48:52.553411 gettid() = 1515 13:48:52.553613 getrandom("\x43\xf7\x95\x26\xb5\xff\x0e\x86\xe2\x17\x8d\x7f\x67\xe6\xcd\x77", 16, GRND_NONBLOCK) = 16 13:48:52.553842 epoll_ctl(4, EPOLL_CTL_MOD, 3, {EPOLLIN|EPOLLOUT, {u32=2920675504, u64=94831503603888}}) = 0 13:48:52.554068 openat(AT_FDCWD, "/proc/sys/kernel/random/boot_id", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 6 13:48:52.554520 read(6, "c4fffdc7-350a-4d3b-b441-6f573423"..., 38) = 37 13:48:52.554853 read(6, "", 1) = 0 13:48:52.555059 close(6) = 0 13:48:52.555266 timerfd_settime(5, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=6227, tv_nsec=722096000}}, NULL) = 0 13:48:52.555480 epoll_wait(4, [{EPOLLOUT, {u32=2920675504, u64=94831503603888}}], 4, 0) = 1 13:48:52.555689 timerfd_create(CLOCK_BOOTTIME, TFD_CLOEXEC|TFD_NONBLOCK) = 6 13:48:52.555926 close(6) = 0 13:48:52.556166 sendto(3, "{\"method\":\"io.systemd.UserDataba"..., 118, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 118 13:48:52.556435 epoll_ctl(4, EPOLL_CTL_MOD, 3, {EPOLLIN, {u32=2920675504, u64=94831503603888}}) = 0 13:48:52.556700 epoll_wait(4, [], 4, 0) = 0 13:48:52.556916 mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f10e1fd8000 13:48:52.557145 mremap(0x7f10e1fd8000, 135168, 139264, MREMAP_MAYMOVE) = 0x7f10e1fb6000 13:48:52.557432 recvfrom(3, 0x7f10e1fb6010, 135152, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 13:48:52.557734 epoll_wait(4, [{EPOLLIN, {u32=2920673360, u64=94831503601744}}], 4, -1) = 1 13:49:37.640118 read(5, "\x01\x00\x00\x00\x00\x00\x00\x00", 8) = 8 13:49:37.640472 recvfrom(3, 0x7f10e1fb6010, 135152, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) 13:49:37.640902 epoll_ctl(4, EPOLL_CTL_MOD, 3, {0, {u32=2920675504, u64=94831503603888}}) = 0 13:49:37.641192 epoll_wait(4, [], 4, 0) = 0 13:49:37.641540 epoll_ctl(4, EPOLL_CTL_DEL, 3, NULL) = 0 13:49:37.641849 close(3) = 0 13:49:37.642189 munmap(0x7f10e1fb6000, 139264) = 0 13:49:37.642590 close(4) = 0 13:49:37.642991 close(5) = 0 13:49:37.643299 writev(2, [{iov_base="\x1b\x5b\x30\x3b\x31\x3b\x33\x31\x6d", iov_len=9}, {iov_base="Failed to find user ray: Connect"..., iov_len=45}, {iov_base="\x1b\x5b\x30\x6d", iov_len=4}, {iov_base="\n", iov_len=1}], 4Failed to find user ray: Connection timed out ) = 59 13:49:37.644087 exit_group(1) = ? 13:49:37.645216 +++ exited with 1 +++ ``` Services appear to be running: ``` # userdbctl services SERVICE LISTENING io.systemd.DynamicUser yes io.systemd.Home yes io.systemd.Multiplexer yes io.systemd.NameServiceSwitch yes ```
systemd-userdbd.service is running but reports: systemd-userdbd.service - User Database Manager Loaded: loaded (/usr/lib/systemd/system/systemd-userdbd.service; static; vendor preset: disabled) Active: active (running) since Tue 2020-05-05 12:06:05 BST; 1h 51min ago TriggeredBy: ● systemd-userdbd.socket Docs: man:systemd-userdbd.service(8) Main PID: 795 (systemd-userdbd) Status: "Processing requests..." Tasks: 4 (limit: 4645) Memory: 152.3M CPU: 1.515s CGroup: /system.slice/systemd-userdbd.service ├─ 795 /usr/lib/systemd/systemd-userdbd ├─1188 systemd-userwork ├─1201 systemd-userwork └─1202 systemd-userwork May 05 12:06:05 Unknown-00-0c-29-e0-2b-3f systemd[1]: Starting User Database Manager... May 05 12:06:05 Unknown-00-0c-29-e0-2b-3f systemd[1]: Started User Database Manager. May 05 13:40:40 Unknown-00-0c-29-e0-2b-3f systemd-userdbd[1188]: yp_bind_client_create_v3: RPC: Unable to send May 05 13:43:09 Unknown-00-0c-29-e0-2b-3f systemd-userdbd[1202]: yp_bind_client_create_v3: RPC: Unable to send May 05 13:44:49 Unknown-00-0c-29-e0-2b-3f systemd-userdbd[1201]: yp_bind_client_create_v3: RPC: Unable to send nss-nis is installed (3.1-4.fc32)
https://github.com/systemd/systemd/issues/15705#issuecomment-624125354 from Lennart Pottering --- adding a drop-in to systemd-userdbd.service, that unsets IPAddressDeny=any so that the daemon is wide open again. Consider asking your distro packagers to just package a drop-in like that for systemd-userdbd.service as part of the NIS package, they must be shipping one just like that for systemd-logind.service already --- Removing "IPAddressDeny" from /lib/systemd/system/systemd-userdbd.service resolves the issue of slow login for NIS user. NIS user on login still have no "systemd --user" started
XDG_* envs available on login, but no "systemd --user" spawned --- May 05 17:49:20 fedora32 audit[1096]: USER_AUTH pid=1096 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 audit[1096]: USER_ACCT pid=1096 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix acct="ray" exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 audit[1096]: CRED_ACQ pid=1096 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 systemd[1]: Created slice User Slice of UID 500. May 05 17:49:20 fedora32 systemd[1]: Starting User Runtime Directory /run/user/500... May 05 17:49:20 fedora32 systemd-logind[797]: New session 13 of user ray. May 05 17:49:20 fedora32 systemd[1]: Finished User Runtime Directory /run/user/500. May 05 17:49:20 fedora32 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user-runtime-dir@500 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' May 05 17:49:20 fedora32 systemd[1]: Starting User Manager for UID 500... May 05 17:49:20 fedora32 systemd[1431]: user: Failed to determine user credentials: No such process May 05 17:49:20 fedora32 systemd[1431]: user: Failed at step USER spawning /usr/lib/systemd/systemd: No such process May 05 17:49:20 fedora32 systemd[1]: user: Main process exited, code=exited, status=217/USER May 05 17:49:20 fedora32 systemd[1]: user: Failed with result 'exit-code'. May 05 17:49:20 fedora32 systemd[1]: Failed to start User Manager for UID 500. May 05 17:49:20 fedora32 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user@500 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' May 05 17:49:20 fedora32 systemd[1]: Started Session 13 of user ray. May 05 17:49:20 fedora32 login[1096]: pam_unix(login:session): session opened for user ray by LOGIN(uid=0) May 05 17:49:20 fedora32 audit[1096]: USER_START pid=1096 uid=0 auid=500 ses=13 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="ray" exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 audit[1096]: CRED_REFR pid=1096 uid=0 auid=500 ses=13 msg='op=PAM:setcred grantors=pam_unix acct="ray" exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 audit[1096]: USER_LOGIN pid=1096 uid=0 auid=500 ses=13 msg='op=login id=500 exe="/usr/bin/login" hostname=fedora32 addr=? terminal=tty1 res=success' May 05 17:49:20 fedora32 login[1096]: LOGIN ON tty1 BY ray
starting nscd resolves the issue! Same problem as https://bugzilla.redhat.com/show_bug.cgi?id=1823907
identified 2 bugs: - slow login for NIS user: nis package missing dropin for systemd-userdbd.service to unset IPAddressDeny (see https://bugzilla.redhat.com/show_bug.cgi?id=1831141#c4) - NIS user login does not start "systemd --user" without nscd running
*** This bug has been marked as a duplicate of bug 1823907 ***
*** Bug 2082843 has been marked as a duplicate of this bug. ***