1694681 – Slow listing of files owned by 'nobody' on nfs share with SELinux and 'filter_users'

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1694681 - Slow listing of files owned by 'nobody' on nfs share with SELinux and 'filter_users'

Summary: Slow listing of files owned by 'nobody' on nfs share with SELinux and 'filter...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 8
Classification:	Red Hat
Component:	selinux-policy
Sub Component:
Version:	8.0
Hardware:	Unspecified
OS:	Linux
Priority:	medium
Severity:	high
Target Milestone:	rc
Target Release:	8.4
Assignee:	Zdenek Pytela
QA Contact:	Milos Malik
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	1945644 (view as bug list)
Depends On:
Blocks:	1894575 1947170 1947171
TreeView+	depends on / blocked

Reported:	2019-04-01 11:40 UTC by adam winberg
Modified:	2024-10-01 16:14 UTC (History)
CC List:	27 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:	Cause: The dbus communication was allowed from kernel to systemd, but dontaudited in the other way so the caller waited until the request timed out. Consequence: With systemd as user and group names resolver, the calling process did not get any response, being either positive or negative, which caused 25-second delay in listing NFS shares. Fix: An allow rule instead of the dontaudit one. Result: No delays as the communication is now allowed bidirectionally.
Clone Of:
Clones:	1947170 1947171 (view as bug list)
Environment:
Last Closed:	2021-05-18 14:57:35 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
ls strace file (53.28 KB, text/plain) 2019-09-12 12:47 UTC, adam winberg	no flags	Details
SSSD nss debug log (251.24 KB, text/plain) 2019-09-12 12:47 UTC, adam winberg	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Knowledge Base (Solution)	5071121	0	None	None	None	2020-05-13 21:51:30 UTC

Internal Links: 1945644

Description adam winberg 2019-04-01 11:40:11 UTC

Description of problem:

Listing files owned by a user/group filtered in SSSD (filter_users/filter_groups) on an NFS share takes a really long time with selinux enforcing. Testing in my environment shows that listing of a directory with a single file owned by a filtered user takes ~25s with selinux enforcing, while taking ~0.150s with selinux in permissive mode. 

SELinux logs shows no denials. I have disabled 'dontaudit' rules but still get no relevant denials, so it's really unclear what's happening. 

Version-Release number of selected component (if applicable):
selinux-policy-3.14.1-46.el8.noarch

How reproducible:
Always

Steps to Reproduce:
1. On machine A: configure SSSD to filter out an AD user (filter_users)
2. On machine B: Create an NFS directory with a single file owned by the filtered user from step 1. 
3. On machine A: make sure SELinux is enforcing. 
4. On machine A: List file:
$ nfsidmap -c # Clear cache
$ ls -l <file>

Repeat and adjust step 3 to compare with selinux in permissive mode. 

Actual results:
File listing takes a long time

Expected results:
File listing should be equally fast with or without selinux in enforcing mode. 


Additional info:
NFS Server: Netapp
NFS share mounted with vers=4.0. Tried with both 'sec=sys' and 'sec=krb5' with same result.

Comment 1 adam winberg 2019-04-02 08:01:35 UTC

So to be clear, the file listing works and returns the user/group ownership as 'nobody' which is expected, but it just takes a really long time. This is not the case in RHEL7. 

Since this seem to be affected by selinux somehow, is there any policy adjustments I can make to work it out?

Comment 2 adam winberg 2019-04-26 13:35:50 UTC

Since this is not targeted until 8.1, I'm still interested in any workarounds to make this work.

Comment 3 Lukas Vrabec 2019-09-12 11:31:05 UTC

sssd folks, 

Are you able to reproduce this issue? I'm not aware of any SELinux related change here. Could you please take a look? 

THanks,
Lukas.

Comment 4 Sumit Bose 2019-09-12 12:14:04 UTC

Hi,

can you run ls under strace like e.g.

    strace -f -w /tmp/ls.out -s 4096 -tt ls ....

while running SSSD with debug_level=9 at least in the [nss] section and send /tmp/ls.out and the SSSD log files?

bye,
Sumit

Comment 5 adam winberg 2019-09-12 12:46:54 UTC

My reproducer still works very well in my environment. File listing always takes 25s so it seems that there is some kind of timeout in play. 
(with selinux in permissive mode file listing takes ~0.032s. )

Attaching sssd nss debug log and strace.

Comment 6 adam winberg 2019-09-12 12:47:32 UTC

Created attachment 1614504 [details]
ls strace file

Comment 7 adam winberg 2019-09-12 12:47:56 UTC

Created attachment 1614505 [details]
SSSD nss debug log

Comment 8 Sumit Bose 2019-09-12 13:32:56 UTC

Hi,

thanks for the logs. So far I cannot see an indication the SSSD is involved in the delay.

How does your /etc/idmapd.conf looks like? Have you tried to increase the verbosity?

bye,
Sumit

Comment 9 adam winberg 2019-09-12 13:43:46 UTC

The only thing we changed in idmapd.conf is the Domain. 

Increasing verbosity does nothing, I only get:

Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31309]: libnfsidmap: using domain: example.com
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31309]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31309]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31310]: libnfsidmap: using domain: example.com
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31310]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31310]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31311]: libnfsidmap: using domain: example.com
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31311]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31311]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31312]: libnfsidmap: using domain: example.com
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31312]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31312]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31313]: libnfsidmap: using domain: example.com
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31313]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Sep 12 15:41:35 c21637.ad.example.com nfsidmap[31313]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch

Comment 10 adam winberg 2019-09-12 13:50:50 UTC

Hey, I actually found something here. We have the following lines in our /etc/nsswitch.conf:

passwd:     sss files systemd
group:      sss files systemd


This is default on RHEL 8 to my knowledge. I don't know really what the 'systemd' part does, but if I remove it file listing works as expected - nice and quick.

Comment 11 Jakub Hrozek 2019-09-12 14:10:00 UTC

(In reply to adam winberg from comment #10)
> Hey, I actually found something here. We have the following lines in our
> /etc/nsswitch.conf:
> 
> passwd:     sss files systemd
> group:      sss files systemd
> 
> 
> This is default on RHEL 8 to my knowledge. I don't know really what the
> 'systemd' part does, but if I remove it file listing works as expected -
> nice and quick.

See e.g. https://systemd.io/UIDS-GIDS.html#special-systemd-uid-ranges this is a module that is supposed to return users for a particular systemd service.

Comment 12 adam winberg 2019-09-13 05:39:06 UTC

Can you reproduce this now, with 'systemd' in nsswitch.conf?

Since we don't use those features the workaround for us is easy - remove 'systemd' from /etc/nsswitch.conf.

Comment 15 Jacob Shivers 2020-05-13 19:27:12 UTC

IHAC that ran into this issue.

I did some isolated testing and was able to reproduce this behavior in RHEL8. If I either set SELinux in permissive _or_ remove systemd from /etc/nsswitch.conf, I am not able to reproduce the behavior.
However, I can not reproduce this behavior in Fedora Rawhide even with systemd in /etc/nsswitch.conf and SELinux in enforcing mode:

### RHEL 8

 o RHEL 8.2 kernel, with SELinux in enforcing mode and values are not stripped in idmapd.conf.
   This is important in order to replicate the behavior as Windows NFS servers do not append
   the domain name to the uid/gid strings.
# getenforce ; uname -r ; egrep -v '#|^$' /etc/nsswitch.conf ; grep 'No-Strip =' /etc/idmapd.conf 
Enforcing
4.18.0-193.el8.x86_64
passwd:     sss files systemd
group:      sss files systemd
netgroup:   sss files
automount:  sss files
services:   sss files
shadow:     files sss
hosts:      files dns myhostname
aliases:    files
ethers:     files
gshadow:    files
networks:   files dns
protocols:  files
publickey:  files
rpc:        files
#No-Strip = none

# sestatus -b | head
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          enforcing
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Memory protection checking:     actual (secure)
Max kernel policy version:      31

 o Direct dbus monitor out to a file
# dbus-monitor --system | tee /tmp/dbus.out

# mount win2k16-dc.example.net:/home /mnt -o vers=4.1,sec=krb5
# date +%s ; time ls -l /mnt ; date +%s

 o We observe a 25 second delay in activity, where we take two
   seconds to complete the `# ls` transaction itself.
# date +%s ; time ls -l /mnt ; date +%s
1589396012
total 102401
-rw-r--r--. 1 nobody nobody         0 Mar 10 17:56 foo
-rw-r--r--. 1 nobody nobody        12 Mar 28  2019 test_dean
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_dean-2019-04-01
-rw-r--r--. 1 nobody nobody 104857600 Apr 10  2019 testfile.bin
-rw-r--r--. 1 nobody nobody         0 Mar 28  2019 test_jeff
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_jeff-2019-04-01
drwx------. 2 nobody nobody        64 Mar 10 19:38 troy

real    0m27.465s
user    0m0.001s
sys     0m0.006s
1589396039

# grep time /tmp/dbus.out | tail
signal time=1589396006.663926 sender=:1.0 -> destination=(null destination) serial=279 path=/org/freedesktop/systemd1/unit/dev_2dmapper_2dr8vg_5cx2droot_5flv_2edevice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
method call time=1589396014.840723 sender=:1.25 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1589396014.841437 sender=org.freedesktop.DBus -> destination=:1.25 serial=1 reply_serial=1
signal time=1589396014.841447 sender=org.freedesktop.DBus -> destination=(null destination) serial=54 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
signal time=1589396014.841456 sender=org.freedesktop.DBus -> destination=:1.25 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
method call time=1589396014.842344 sender=:1.25 -> destination=org.freedesktop.systemd1 serial=2 path=/org/freedesktop/systemd1; interface=org.freedesktop.systemd1.Manager; member=LookupDynamicUserByName
error time=1589396014.842883 sender=:1.0 -> destination=:1.25 error_name=org.freedesktop.systemd1.NoSuchDynamicUser reply_serial=2
error time=1589396014.842897 sender=org.freedesktop.DBus -> destination=:1.0 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=280
signal time=1589396039.851723 sender=org.freedesktop.DBus -> destination=:1.25 serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
signal time=1589396039.851805 sender=org.freedesktop.DBus -> destination=(null destination) serial=55 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged

# journalctl -xn
-- Logs begin at Wed 2020-05-13 19:51:23 BST, end at Wed 2020-05-13 19:54:34 BST. --
May 13 14:53:34 rhel-82.example.net nfsidmap[1482]: libnfsidmap: using (default) domain: example.net
May 13 14:53:34 rhel-82.example.net nfsidmap[1482]: libnfsidmap: Realms list: 'EXAMPLE.NET'
May 13 14:53:34 rhel-82.example.net nfsidmap[1482]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
May 13 14:53:34 rhel-82.example.net nfsidmap[1482]: nss_name_to_gid: name 'Domain Computers' not found in domain 'example.net'
May 13 14:53:34 rhel-82.example.net nfsidmap[1483]: libnfsidmap: res_querydomain() failed for _nfsv4idmapdomain.example.net: Unknown host
May 13 14:53:34 rhel-82.example.net nfsidmap[1483]: libnfsidmap: using (default) domain: example.net
May 13 14:53:34 rhel-82.example.net nfsidmap[1483]: libnfsidmap: Realms list: 'EXAMPLE.NET'
May 13 14:53:34 rhel-82.example.net nfsidmap[1483]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
May 13 14:53:59 rhel-82.example.net nfsidmap[1483]: nss_getpwnam: name 'jeff' not found in domain 'example.net'
May 13 14:54:34 rhel-82.example.net dbus-daemon[824]: [system] Monitoring connection :1.24 closed.

 o Rebooting and adjusting passwd to exclude _systemd_
# grep '^passwd' /etc/nsswitch.conf
passwd:     sss files

 o The `# ls` completes within the expected timeframe.
# date +%s ; time ls -l /mnt ; date +%s
1589396396
total 102401
-rw-r--r--. 1 nobody nobody         0 Mar 10 13:56 foo
-rw-r--r--. 1 nobody nobody        12 Mar 28  2019 test_dean
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_dean-2019-04-01
-rw-r--r--. 1 nobody nobody 104857600 Apr 10  2019 testfile.bin
-rw-r--r--. 1 nobody nobody         0 Mar 28  2019 test_jeff
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_jeff-2019-04-01
drwx------. 2 nobody nobody        64 Mar 10 15:38 troy

real    0m2.435s
user    0m0.002s
sys     0m0.004s
1589396398

# journalctl -xn
-- Logs begin at Wed 2020-05-13 14:58:46 EDT, end at Wed 2020-05-13 14:59:58 EDT. --
May 13 14:59:58 rhel-82.example.net nfsidmap[1475]: libnfsidmap: res_querydomain() failed for _nfsv4idmapdomain.example.net: Unknown host
May 13 14:59:58 rhel-82.example.net nfsidmap[1475]: libnfsidmap: using (default) domain: example.net
May 13 14:59:58 rhel-82.example.net nfsidmap[1475]: libnfsidmap: Realms list: 'EXAMPLE.NET'
May 13 14:59:58 rhel-82.example.net nfsidmap[1475]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
May 13 14:59:58 rhel-82.example.net nfsidmap[1475]: nss_name_to_gid: name 'Domain Computers' not found in domain 'example.net'
May 13 14:59:58 rhel-82.example.net nfsidmap[1476]: libnfsidmap: res_querydomain() failed for _nfsv4idmapdomain.example.net: Unknown host
May 13 14:59:58 rhel-82.example.net nfsidmap[1476]: libnfsidmap: using (default) domain: example.net
May 13 14:59:58 rhel-82.example.net nfsidmap[1476]: libnfsidmap: Realms list: 'EXAMPLE.NET'
May 13 14:59:58 rhel-82.example.net nfsidmap[1476]: libnfsidmap: loaded plugin /usr/lib64/libnfsidmap/nsswitch.so for method nsswitch
May 13 14:59:58 rhel-82.example.net nfsidmap[1476]: nss_getpwnam: name 'jeff' not found in domain 'example.net'

### Fedora Rawhide

 o systemd is included in passwd database resolution:
# getenforce ; uname -r ; egrep -v '#|^$' /etc/nsswitch.conf ; grep 'No-Strip =' /etc/idmapd.conf
Enforcing
5.6.0-0.rc6.git0.1.fc33.x86_64
passwd:     sss files systemd
group:      sss files systemd
netgroup:   sss files
automount:  files
services:   sss files
shadow:     files sss
hosts:      files dns myhostname
bootparams: nisplus [NOTFOUND=return] files
ethers:     files
netmasks:   files
networks:   files
protocols:  files
rpc:        files
publickey:  nisplus
aliases:    files nisplus
#No-Strip = both

 o The kernel policy version is newer.
# sestatus -b | head
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          enforcing
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Memory protection checking:     actual (secure)
Max kernel policy version:      32

 o Even with systemd as a resolvable database in Fedora Rawhide, we do not observe
   the same delays.
# mount win2k16-dc.example.net:/home /mnt -o vers=4.1,sec=krb5

# date +%s ; time ls -l /mnt ; date +%s
1589396686
total 102401
-rw-r--r--. 1 nobody nobody         0 Mar 10 13:56 foo
-rw-r--r--. 1 nobody nobody        12 Mar 28  2019 test_dean
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_dean-2019-04-01
-rw-r--r--. 1 nobody nobody 104857600 Apr 10  2019 testfile.bin
-rw-r--r--. 1 nobody nobody         0 Mar 28  2019 test_jeff
-rw-r--r--. 1 nobody nobody         0 Apr  1  2019 test_jeff-2019-04-01
drwx------. 2 nobody nobody        64 Mar 10 15:38 troy

real    0m2.415s
user    0m0.001s
sys     0m0.004s
1589396688

From previous testing, this looks may be an issue with SELinux policy given the returned errors:

# grep time /tmp/dbus.out  | tail
signal time=1589223995.749222 sender=:1.0 -> destination=(null destination) serial=208 path=/org/freedesktop/systemd1/unit/dev_2dmapper_2dr8vg_5cx2droot_5flv_2edevice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
method call time=1589224004.254239 sender=:1.29 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1589224004.254277 sender=org.freedesktop.DBus -> destination=:1.29 serial=1 reply_serial=1
signal time=1589224004.254289 sender=org.freedesktop.DBus -> destination=(null destination) serial=64 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
signal time=1589224004.254297 sender=org.freedesktop.DBus -> destination=:1.29 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
method call time=1589224004.255533 sender=:1.29 -> destination=org.freedesktop.systemd1 serial=2 path=/org/freedesktop/systemd1; interface=org.freedesktop.systemd1.Manager; member=LookupDynamicUserByName
error time=1589224004.256013 sender=:1.0 -> destination=:1.29 error_name=org.freedesktop.systemd1.NoSuchDynamicUser reply_serial=2
error time=1589224004.256026 sender=org.freedesktop.DBus -> destination=:1.0 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=209
signal time=1589224029.259489 sender=org.freedesktop.DBus -> destination=:1.29 serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
signal time=1589224029.259515 sender=org.freedesktop.DBus -> destination=(null destination) serial=65 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged

# sed '/1589224004/,$ !d' /tmp/dbus.out
method call time=1589224004.254239 sender=:1.29 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1589224004.254277 sender=org.freedesktop.DBus -> destination=:1.29 serial=1 reply_serial=1
   string ":1.29"
signal time=1589224004.254289 sender=org.freedesktop.DBus -> destination=(null destination) serial=64 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.29"
   string ""
   string ":1.29"
signal time=1589224004.254297 sender=org.freedesktop.DBus -> destination=:1.29 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.29"
method call time=1589224004.255533 sender=:1.29 -> destination=org.freedesktop.systemd1 serial=2 path=/org/freedesktop/systemd1; interface=org.freedesktop.systemd1.Manager; member=LookupDynamicUserByName
   string "jeff"
error time=1589224004.256013 sender=:1.0 -> destination=:1.29 error_name=org.freedesktop.systemd1.NoSuchDynamicUser reply_serial=2
   string "Dynamic user jeff does not exist."
error time=1589224004.256026 sender=org.freedesktop.DBus -> destination=:1.0 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=209
   string "An SELinux policy prevents this sender from sending this message to this recipient, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1 comm="/usr/lib/systemd/systemd --switched-root --system " label="system_u:system_r:init_t:s0") interface="(unset)" member="(unset)" error name="org.freedesktop.systemd1.NoSuchDynamicUser" requested_reply="0" destination=":1.29" (uid=0 pid=1656 comm="nfsidmap 95064561 uid:jeff " label="system_u:system_r:kernel_t:s0")"
signal time=1589224029.259489 sender=org.freedesktop.DBus -> destination=:1.29 serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.29"
signal time=1589224029.259515 sender=org.freedesktop.DBus -> destination=(null destination) serial=65 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.29"
   string ":1.29"
   string ""

Comment 16 Alexey Tikhonov 2020-05-13 20:13:56 UTC

Why is the component == sssd in this bz?

Comment 17 Frank Sorenson 2020-05-13 21:16:44 UTC

The issue occurs when 'systemd' is specified in nsswitch.conf for passwd/group, selinux is enforcing, and the user/group owning the files is NOT found in any of the name service switch databases.


on the nfs server:

# mkdir /export
# for i in {1100..1300} ; do touch /export/user_$i ; chown $i:$i /export/user_$i

cat /etc/exports
/export   *(rw,sync,no_root_squash,security_label,fsid=0,sec=sys)

# exportfs -av


on the nfs client:

# egrep '^(passwd|group)' /etc/nsswitch.conf
passwd:     sss files systemd
group:      sss files systemd


# mount server:/ /mnt/tmp -overs=4

# time ls -al /mnt/tmp >/dev/null

real	0m50.706s
user	0m0.007s
sys	0m0.032s


I get the following audit message, which I saved to /var/tmp/dbus_send_error

type=USER_AVC msg=audit(1589400931.223:5344): pid=993 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=error error_name=org.freedesktop.systemd1.NoSuchDynamicUser dest=:1.4536 spid=1 tpid=2770 scontext=system_u:system_r:init_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"


# audit2allow -w </var/tmp/dbus_send_error
type=USER_AVC msg=audit(1589400931.223:5344): pid=993 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=error error_name=org.freedesktop.systemd1.NoSuchDynamicUser dest=:1.4536 spid=1 tpid=2770 scontext=system_u:system_r:init_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=0  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"

	Was caused by:
		Missing type enforcement (TE) allow rule.

		You can use audit2allow to generate a loadable module to allow this access.


# audit2allow -m dbus_send_error -i /var/tmp/dbus_send_error >/var/tmp/dbus_send_error.te
# cat /var/tmp/dbus_send_error.te

module dbus_send_error 1.0;

require {
	type init_t;
	type kernel_t;
	class dbus send_msg;
}

#============= init_t ==============
allow init_t kernel_t:dbus send_msg;


# checkmodule -M -m -o /var/tmp/dbus_send_error.mod /var/tmp/dbus_send_error.te
# semodule_package -o /var/tmp/dbus_send_error.pp -m /var/tmp/dbus_send_error.mod


# nfsidmap -c
# time ls -l /mnt/tmp >/dev/null

real	0m55.688s
user	0m0.007s
sys	0m0.031s


# semodule -i /var/tmp/dbus_send_error.pp


# nfsidmap -c
# time ls -l /mnt/vm1 >/dev/null

real	0m0.670s
user	0m0.007s
sys	0m0.025s


*** remove again and re-test
# semodule -r dbus_send_error
libsemanage.semanage_direct_remove_key: Removing last dbus_send_error module (no other dbus_send_error module exists at another priority).

# nfsidmap -c
# time ls -l /mnt/vm1 >/dev/null

real	0m50.785s
user	0m0.003s
sys	0m0.026s


# semodule -i /var/tmp/dbus_send_error.pp
# nfsidmap -c
# time ls -l /mnt/vm1 >/dev/null

real	0m0.565s
user	0m0.003s
sys	0m0.009s


I realize this is a workaround.  I hope it's helpful in finding a permanent resolution.

Comment 18 adam winberg 2020-05-14 05:25:41 UTC

wow, I had forgotten about this one. Nice to see it gaining some traction. 

The bug is registered on the sssd component because the problem only manifested itself for users/groups listed in the sssd configuration parameters 'filter_users/fiter_groups'. So a listing of a NFS directory without those users was fast, while a listing of a directory where the filtered users/groups were owners was slow. That was the case in my original report at least.

Comment 19 Alexey Tikhonov 2020-05-14 07:43:37 UTC

Changing component to "systemd" based  on the comment 17

Comment 23 David Tardon 2020-08-11 06:55:05 UTC

From comment 15:

method call time=1589224004.255533 sender=:1.29 -> destination=org.freedesktop.systemd1 serial=2 path=/org/freedesktop/systemd1; interface=org.freedesktop.systemd1.Manager; member=LookupDynamicUserByName
   string "jeff"
error time=1589224004.256013 sender=:1.0 -> destination=:1.29 error_name=org.freedesktop.systemd1.NoSuchDynamicUser reply_serial=2
   string "Dynamic user jeff does not exist."
error time=1589224004.256026 sender=org.freedesktop.DBus -> destination=:1.0 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=209
   string "An SELinux policy prevents this sender from sending this message to this recipient, 0 matched rules; type="error", sender=":1.0" (uid=0 pid=1 comm="/usr/lib/systemd/systemd --switched-root --system " label="system_u:system_r:init_t:s0") interface="(unset)" member="(unset)" error name="org.freedesktop.systemd1.NoSuchDynamicUser" requested_reply="0" destination=":1.29" (uid=0 pid=1656 comm="nfsidmap 95064561 uid:jeff " label="system_u:system_r:kernel_t:s0")"

-> moving to selinux-policy.

Comment 24 Zdenek Pytela 2020-08-11 08:32:23 UTC

David,

I read through the bug history, but still seem not to have the complete picture.
What is the systemd background for the reproducer described in c#17?


The reason for dbus timing out supposedly is that SELinux dontaudits the communication:

  # sesearch --dontaudit -s init_t -t kernel_t -c dbus -p send_msg
dontaudit init_t kernel_t:dbus send_msg;

Is it necessary to allow it in order to have something working?


Note:
This is the Fedora commit, introduced to resolve https://bugzilla.redhat.com/show_bug.cgi?id=1669095:
commit f4b4b99846308b75fd9bb2f50d6e9897459f87a5
Author: Lukas Vrabec <lvrabec>
Date:   Fri Jul 12 09:48:27 2019 +0200

    Dontaudit dbus chat between kernel_t and init_t

diff --git a/policy/modules/kernel/kernel.te b/policy/modules/kernel/kernel.te
index ddd7fc555..c32bb728a 100644
--- a/policy/modules/kernel/kernel.te
+++ b/policy/modules/kernel/kernel.te
@@ -394,6 +394,7 @@ optional_policy(`
 optional_policy(`
        init_sigchld(kernel_t)
        init_dyntrans(kernel_t)
+    init_dontaudit_dbus_chat(kernel_t)
 ')

Comment 28 Zdenek Pytela 2020-10-13 13:15:56 UTC

I've submitted a Fedora PR to address the issue:
https://github.com/fedora-selinux/selinux-policy/pull/455

Comment 39 Zdenek Pytela 2021-04-08 07:08:02 UTC

*** Bug 1945644 has been marked as a duplicate of this bug. ***

Comment 51 errata-xmlrpc 2021-05-18 14:57:35 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (selinux-policy bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:1639

Comment 52 Red Hat Bugzilla 2024-01-06 04:26:14 UTC

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 120 days

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

atikhono
cpassare
dtardon
fkrska
fsorenso
grajaiya
jhrozek
jshivers
lslebodn
ltitov
lvrabec
mmalik
msekleta
mzidek
pbrezina
plautrba
pwallend
rbergant
sbose
ssekidde
sysadmin5
systemd-maint-list
tim.denholm
tjaros
tquinlan
tscherf
zpytela