Bug 1831141 - "systemd --user" NOT launched for NIS user
Summary: "systemd --user" NOT launched for NIS user
Keywords:
Status: CLOSED DUPLICATE of bug 1823907
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 32
Hardware: Unspecified
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 2082843 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-05-04 17:30 UTC by whatdoineed2do
Modified: 2022-08-26 08:21 UTC (History)
10 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2020-08-01 13:23:55 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description whatdoineed2do 2020-05-04 17:30:43 UTC
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

Comment 1 whatdoineed2do 2020-05-05 11:02:50 UTC
# /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'
---

Comment 2 whatdoineed2do 2020-05-05 12:55:16 UTC
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  
```

Comment 3 whatdoineed2do 2020-05-05 13:10:59 UTC
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)

Comment 4 whatdoineed2do 2020-05-05 16:31:38 UTC
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

Comment 5 whatdoineed2do 2020-05-05 16:50:54 UTC
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

Comment 6 whatdoineed2do 2020-05-05 17:03:43 UTC
starting nscd resolves the issue!

Same problem as https://bugzilla.redhat.com/show_bug.cgi?id=1823907

Comment 7 whatdoineed2do 2020-05-05 17:11:32 UTC
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

Comment 8 Zbigniew Jędrzejewski-Szmek 2020-08-01 13:23:55 UTC

*** This bug has been marked as a duplicate of bug 1823907 ***

Comment 9 David Tardon 2022-08-26 08:21:20 UTC
*** Bug 2082843 has been marked as a duplicate of this bug. ***


Note You need to log in before you can comment on or make changes to this bug.