1679173 – filter_users option is not applied to sub-domains if SSSD starts offline

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 1679173 - filter_users option is not applied to sub-domains if SSSD starts offline

Summary: filter_users option is not applied to sub-domains if SSSD starts offline

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	sssd
Sub Component:
Version:	7.6
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	SSSD Maintainers
QA Contact:	ipa-qe
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2019-02-20 14:17 UTC by Thorsten Scherf
Modified:	2020-05-02 19:08 UTC (History)
CC List:	10 users (show)
Fixed In Version:	sssd-1.16.4-1.el7
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2019-08-06 13:02:47 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	SSSD sssd issues 4955	0	None	closed	filter_users option is not applied to sub-domains if SSSD starts offline	2021-01-05 06:17:36 UTC
Red Hat Product Errata	RHSA-2019:2177	0	None	None	None	2019-08-06 13:03:05 UTC

Description Thorsten Scherf 2019-02-20 14:17:58 UTC

Description of problem:
IPA/AD trust setup with 'domain_resolution_order' set to prefer AD over IdM domain. In such a setup we see initgroup calls for root triggering LDAP backend lookups.

Version-Release number of selected component (if applicable):
sssd-1.16.0-19.el7

How reproducible:
always

Steps to Reproduce:
1.Setup IdM/AD trust
2.Change domain resolution order to prefer the AD domain: 'ipa config-mod --domain-resolution-order=ad.domain:ipa.domain'
3.Call 'id root'

Actual results:
LDAP lookups for 'root'

Expected results:
No LDAP lookups root 'root'

Additional info:
Adding 'root' to 'filter_users' in sssd.conf 'nss' section mitigates the issue.

The issue is related to this (already closed) BZ:

id root triggers an LDAP lookup
https://bugzilla.redhat.com/show_bug.cgi?id=1479983

Comment 5 Sumit Bose 2019-03-12 17:26:40 UTC

Upstream ticket:
https://pagure.io/SSSD/sssd/issue/3983

Comment 7 Jakub Hrozek 2019-03-14 21:19:42 UTC

* master:
 * 640edac4287ccbd373fb0b5711b49cfb076bf6e0
 * 6b93ee699cef2f24a5d96a187fcd9ece5f2e29f4
 * 2f5aca39b5b473259cd43e6b93246ff218a2b177
* sssd-1-16:
 * faede6d273576cfdd1db29ca7d03a1944d120601
 * 720907dd7ba465007bcafe6b7a00f131322d945a
 * 6bb46a67165ace1b62f4e92f91aab59875548ee8

Comment 9 Sergey Orlov 2019-06-07 10:09:38 UTC

Hello Jakub
I have problem verifying this BZ because I can not reproduce the original bug with old version of sssd:

# rpm -q sssd-common
sssd-common-1.16.2-17.el7.x86_64

# ipa config-show | grep resolution
  Domain resolution order: ad.test:testrelm.test

filter_users and get_domains_timeout are not defined in sssd.conf, so should be using default values root and 60 respectively.

In /etc/sssd/sssd.conf I have "debug_level = 9" in all sections.

I tried the steps from upstream ticket https://pagure.io/SSSD/sssd/issue/3983:

systemctl stop sssd 
rm -f /var/lib/sss/{db,mc}/* /var/log/sssd/* 
systemctl start sssd
sleep 10
echo Secret123 | ipa trust-add --type ad ad.test --password --admin Administrator
id root

In this case root is searched only in cache:

(Fri Jun  7 11:33:25 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: root
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #2: Setting "Initgroups by name" plugin
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #2: New request 'Initgroups by name'
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #2: Parsing input name [root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'root' matched without domain, user is root
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #2: Setting name [root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #2: Performing a multi-domain search
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #2: Search will check the cache and check the data provider
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain ad.test type POSIX is valid
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #2: Using domain [ad.test]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [ad.test] rules
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #2: Looking up root
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/ad.test/root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: [root] does not exist (negative cache)
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain testrelm.test type POSIX is valid
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #2: Using domain [testrelm.test]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [testrelm.test] rules
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #2: Looking up root
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/testrelm.test/root]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: [root] does not exist (negative cache)
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain child.ad.test type POSIX is valid
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #2: Using domain [child.ad.test]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [child.ad.test] rules
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #2: Looking up root.test
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [root.test]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/child.ad.test/root.test]
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #2: [root.test] does not exist (negative cache)
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #2: Finished: Not found
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain ad.test is Active
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain child.ad.test is Active
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
(Fri Jun  7 11:33:25 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected!

I also tried the steps from https://bugzilla.redhat.com/show_bug.cgi?id=1679173#c6:

systemctl stop sssd
rm -f /var/lib/sss/{db,mc}/* /var/log/sssd/*
systemctl start sssd
sleep 10
echo Secret123 | ipa trust-add --type ad ad.test --password --admin Administrator
ipactl stop 
systemctl restart sssd
sleep 10
ipactl start
sleep 65
id root

And got same result:

(Fri Jun  7 11:54:50 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: root
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #21: Setting "Initgroups by name" plugin
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #21: New request 'Initgroups by name'
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #21: Parsing input name [root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'root' matched without domain, user is root
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #21: Setting name [root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #21: Performing a multi-domain search
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #21: Search will check the cache and check the data provider
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain ad.test type POSIX is valid
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [ad.test]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [ad.test] rules
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up root
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/ad.test/root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [root] does not exist (negative cache)
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain testrelm.test type POSIX is valid
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [testrelm.test]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [testrelm.test] rules
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up root
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/testrelm.test/root]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [root] does not exist (negative cache)
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain child.ad.test type POSIX is valid
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [child.ad.test]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [child.ad.test] rules
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up root.test
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [root.test]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/child.ad.test/root.test]
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [root.test] does not exist (negative cache)
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #21: Finished: Not found
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain ad.test is Active
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain child.ad.test is Active
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
(Fri Jun  7 11:54:50 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected!

I also tried to clear sssd cache while ipactl is offline:
echo Secret123 | ipa trust-add --type ad ad.test --password --admin Administrator
ipactl stop 
systemctl stop sssd
rm -f /var/lib/sss/{db,mc}/* /var/log/sssd/*
systemctl start sssd
sleep 10
ipactl start
sleep 65
id root

In this case there are no requests for root at all:
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: root
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #21: Setting "Initgroups by name" plugin
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #21: New request 'Initgroups by name'
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #21: Parsing input name [root]
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'root' matched without domain, user is root
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #21: Setting name [root]
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #21: Performing a multi-domain search
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #21: Search will check the cache and check the data provider
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain testrelm.test type POSIX is valid
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [testrelm.test]
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [testrelm.test] rules
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up root
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [root]
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/testrelm.test/root]
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [root] does not exist (negative cache)
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #21: Finished: Not found
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
(Fri Jun  7 12:00:42 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected!


I have seen requests to data provider few times but can not reliably reproduce this behavior

Comment 10 Jakub Hrozek 2019-06-07 11:09:59 UTC

Would you mind trying without removing the cache? I think it might make a difference in the sense that with your test sssd starts not just offline, but also with clean cache and I guess when the domain is created, it might populate the negative cache, whereas when the domain exists, we take a different route. Alternatively, please try with another user present in filter_users, but not root.

But I'm only guessing here, if that doesn't help, feel free to send me credentials to your environment or even just ask, I can also revert the fixes locally and try the reproducer.

Comment 11 Sergey Orlov 2019-06-07 11:52:35 UTC

I tried to request witjout cleaning cache and re-establishing trust -- no changes.
I also added line "filter_users = abcde" to /etc/sssd/sssd.conf and executed following script (user abcde does not exist anywhere):

(use existing trust, do not re-establish)

ipactl stop 
rm -f /var/log/sssd/* 
systemctl restart sssd 
sleep 10 
ipactl start
sleep 65 
id abcde

Still no requests to provider

(Fri Jun  7 13:38:38 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: abcde
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #21: Setting "User by name" plugin
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #21: New request 'User by name'
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #21: Parsing input name [abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'abcde' matched without domain, user is abcde
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #21: Setting name [abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #21: Performing a multi-domain search
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #21: Search will check the cache and check the data provider
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain ad.test type POSIX is valid
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [ad.test]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [ad.test] rules
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up abcde
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/ad.test/abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [abcde] does not exist (negative cache)
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain testrelm.test type POSIX is valid
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [testrelm.test]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [testrelm.test] rules
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up abcde
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/testrelm.test/abcde]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [abcde] does not exist (negative cache)
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain child.ad.test type POSIX is valid
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using domain [child.ad.test]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #21: Preparing input data for domain [child.ad.test] rules
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking up abcde.test
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: Checking negative cache for [abcde.test]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/child.ad.test/abcde.test]
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21: [abcde.test] does not exist (negative cache)
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #21: Finished: Not found
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain ad.test is Active
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain child.ad.test is Active
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Fri Jun  7 13:38:38 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client [0x559b50438760][36]

I checked, that when requesting user not from filter_users ("id abcdef") provider is queried:
(Fri Jun  7 13:40:48 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #22: Looking up [abcdef] in data provider
(Fri Jun  7 13:40:48 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x559b4f39d5d0:1:abcdef@ad.test]


I also rechecked that I have old version of sssd:
# rpm -qa | grep sssd
python-sssdconfig-1.16.2-17.el7.noarch
sssd-common-pac-1.16.2-17.el7.x86_64
sssd-ldap-1.16.2-17.el7.x86_64
sssd-dbus-1.16.2-17.el7.x86_64
sssd-krb5-common-1.16.2-17.el7.x86_64
sssd-ad-1.16.2-17.el7.x86_64
sssd-krb5-1.16.2-17.el7.x86_64
sssd-proxy-1.16.2-17.el7.x86_64
sssd-client-1.16.2-17.el7.x86_64
sssd-common-1.16.2-17.el7.x86_64
sssd-ipa-1.16.2-17.el7.x86_64
sssd-1.16.2-17.el7.x86_64

Comment 12 Sergey Orlov 2019-06-07 11:53:53 UTC

I am testing in local vagrant so can not share the environment.

Comment 13 Pavel Březina 2019-06-07 12:02:18 UTC

Actually there is vagrant-share plugin that might help with sharing the machine, see:
https://www.vagrantup.com/docs/share/

I did not tried it yet myself though, but perhaps you can give it a try.

Comment 14 Jakub Hrozek 2019-06-07 12:05:26 UTC

I can also just revert the patch locally, I'm just not sure I'll have the time today, I'd like to finish libuser and mod_auth_mellon builds for 8.1..

Comment 15 anuja 2019-06-24 06:06:26 UTC

Steps performed :
 - Setup trust
 - Change domain resolution order to prefer the AD domain
 - Added aduser in sssd.conf in filter_users
 - ipactl stop
 - rm -f sssd logs and cache
 - sssd start
 - ipactl start
 - sssctl domain-list should not show the AD domain
 - keep calling sssctl domain-list until you do see the AD domain
 - then run id user
 - check that there are no calls to [cache_req_search_dp] for user in sssd_nss.log
======================================================================================================================================================
older version :
======================================================================================================================================================
[root@oldenv1 ~]# rpm -qa sssd
sssd-1.16.2-13.el7.x86_64
[root@oldenv1 ~]# 
[root@oldenv1 ~]# grep -B 3 "filter_users" /etc/sssd/sssd.conf
[nss]
memcache_timeout = 600
homedir_substring = /home
filter_users = aduser1

[root@oldenv1 ~]# ipa config-show | grep resolution
  Domain resolution order: ipaad2k16cin.test:apq3h.test
[root@oldenv1 ~]# 
[root@oldenv1 ~]# ipactl stop
Stopping ipa-dnskeysyncd Service
Stopping ipa-otpd Service
Stopping winbind Service
Stopping smb Service
Stopping pki-tomcatd Service
Stopping ntpd Service
Stopping ipa-custodia Service
Stopping httpd Service
Stopping named Service
Stopping kadmin Service
Stopping krb5kdc Service
Stopping Directory Service
ipa: INFO: The ipactl command was successful
[root@oldenv1 ~]# service sssd stop; rm -rf /var/lib/sss/{db,mc}/*; service sssd start
Redirecting to /bin/systemctl stop sssd.service
Redirecting to /bin/systemctl start sssd.service
[root@oldenv1 ~]# sssd start
SSSD is already running
[root@oldenv1 ~]# ipactl start
Starting Directory Service
Starting krb5kdc Service
Starting kadmin Service
Starting named Service
Starting httpd Service
Starting ipa-custodia Service
Starting ntpd Service
Starting pki-tomcatd Service
Starting smb Service
Starting winbind Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@oldenv1 ~]# sssctl domain-list
apq3h.test
[root@oldenv1 ~]# sssctl domain-list
apq3h.test
[root@oldenv1 ~]# sleep 60 ; sssctl domain-list
apq3h.test
ipaad2k16cin.test
ipasubad2k16cin.ipaad2k16cin.test
[root@oldenv1 ~]# 
[root@oldenv1 ~]# id aduser1
uid=879001109(aduser1) gid=879001109(aduser1) groups=879001109(aduser1),879001115(adunigroup1),879001114(adgroup2),879000513(domain users),879001113(adgroup1)
[root@oldenv1 ~]# date
Thu Jun 20 08:46:32 EDT 2019

[root@oldenv1 ~]# grep -F "Looking up [aduser1] in data provider" /var/log/sssd/sssd_nss.log 
(Thu Jun 20 08:46:28 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #21: Looking up [aduser1] in data provider
(Thu Jun 20 08:46:28 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #23: Looking up [aduser1] in data provider
[root@oldenv1 ~]# 


======================================================================================================================================================
latest version :
======================================================================================================================================================
[root@latest771 ~]# rpm -qa sssd
sssd-1.16.4-21.el7.x86_64
[root@latest771 ~]# grep -B 3 "filter_users" /etc/sssd/sssd.conf
[nss]
memcache_timeout = 600
homedir_substring = /home
filter_users = aduser1

[root@latest771 ~]# ipa config-show | grep resolution
  Domain resolution order: ipaad2k16cin.test:agkfl.test

[root@latest771 ~]# ipactl stop
Stopping ipa-dnskeysyncd Service
Stopping ipa-otpd Service
Stopping winbind Service
Stopping smb Service
Stopping pki-tomcatd Service
Stopping ntpd Service
Stopping ipa-custodia Service
Stopping httpd Service
Stopping named Service
Stopping kadmin Service
Stopping krb5kdc Service
Stopping Directory Service
ipa: INFO: The ipactl command was successful
[root@latest771 ~]# service sssd stop; rm -rf /var/lib/sss/{db,mc}/*; service sssd start
Redirecting to /bin/systemctl stop sssd.service
Redirecting to /bin/systemctl start sssd.service
[root@latest771 ~]# sssd start
SSSD is already running
[root@latest771 ~]# ipactl start
Starting Directory Service
Starting krb5kdc Service
Starting kadmin Service
Starting named Service
Starting httpd Service
Starting ipa-custodia Service
Starting ntpd Service
Starting pki-tomcatd Service
Starting smb Service
Starting winbind Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@latest771 ~]# sssctl domain-listagkfl.test
[root@latest771 ~]# sleep 60 
[root@latest771 ~]# sssctl domain-list
agkfl.test
ipaad2k16cin.test
ipasubad2k16cin.ipaad2k16cin.test
[root@latest771 ~]#  id aduser1
uid=879001109(aduser1) gid=879001109(aduser1) groups=879001109(aduser1),879001115(adunigroup1),879001114(adgroup2),879000513(domain users),879001113(adgroup1)
[root@latest771 ~]# date
Thu Jun 20 09:22:42 EDT 2019
[root@latest771 ~]# grep -F "Looking up [aduser1] in data provider" /var/log/sssd/sssd_nss.log
(Thu Jun 20 09:14:10 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #23: Looking up [aduser1] in data provider
(Thu Jun 20 09:14:10 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #25: Looking up [aduser1] in data provider
(Thu Jun 20 09:19:32 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #21: Looking up [aduser1] in data provider
(Thu Jun 20 09:19:33 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #23: Looking up [aduser1] in data provider
(Thu Jun 20 09:22:35 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #21: Looking up [aduser1] in data provider
(Thu Jun 20 09:22:35 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #23: Looking up [aduser1] in data provider
[root@latest771 ~]# 

Based on this moving into assigned state.

Comment 16 Sumit Bose 2019-06-25 10:12:00 UTC

Hi,

here are some more specific steps to verify this issue.

First, you need an environment with sub-domains, so either join to an AD domain which is part of a forest with other domains or join to IPA where there is a trust to AD as above.

Now, as above for the IPA case, stop the IPA server components and start SSSD with an empty cache so that it is running in offline mode.

If you now call

    grep 'sss_ncache_set_str.*aduser1' /var/log/sssd/sssd_nss.log

you should only see:

    [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/your.ipa.domain/@aduser1] to negative cache permanently


(Please note, on RHEL8 you might also see the 'implicit_files' domain:

    [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/implicit_files/@aduser1] to negative cache permanently

If you start the IPA server components SSSD should go online eventually and the grep should return entries for the AD domains as well:

    [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/ipaad2k16cin.test/@aduser1] to negative cache permanently
    [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/some.other.ad.domain.if.any/@aduser1] to negative cache permanently


In older version the negative cache was not refreshed when new domains were found and the log entries for the AD domains will not show up.

HTH

bye,
Sumit

Comment 17 anuja 2019-06-25 10:17:19 UTC

As per comment #16 moving back to ON_QA

Comment 18 anuja 2019-06-26 08:13:27 UTC

======================================================================================================================================================
Older Version :
sssd-1.16.2-13.el7.x86_64
======================================================================================================================================================

[root@old1 ~]# ipactl stop
Stopping ipa-dnskeysyncd Service
Stopping ipa-otpd Service
Stopping winbind Service
Stopping smb Service
Stopping pki-tomcatd Service
Stopping ntpd Service
Stopping ipa-custodia Service
Stopping httpd Service
Stopping named Service
Stopping kadmin Service
Stopping krb5kdc Service
Stopping Directory Service
ipa: INFO: The ipactl command was successful
[root@old1 ~]# service sssd stop; rm -rf /var/lib/sss/{db,mc}/*; service sssd start
Redirecting to /bin/systemctl stop sssd.service
Redirecting to /bin/systemctl start sssd.service
[root@old1 ~]# sssd start
SSSD is already running
[root@old1 ~]# grep 'sss_ncache_set_str.*aduser1' /var/log/sssd/sssd_nss.log
[root@old1 ~]# echo $?
1
[root@old1 ~]# 
[root@old1 ~]# 
[root@old1 ~]# 
[root@old1 ~]# ipactl start
Starting Directory Service
Starting krb5kdc Service
Starting kadmin Service
Starting named Service
Starting httpd Service
Starting ipa-custodia Service
Starting ntpd Service
Starting pki-tomcatd Service
Starting smb Service
Starting winbind Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@old1 ~]# date
Wed Jun 26 04:03:33 EDT 2019
[root@old1 ~]#  grep 'sss_ncache_set_str.*aduser1' /var/log/sssd/sssd_nss.log
[root@old1 ~]# echo $?
1
[root@old1 ~]# 


======================================================================================================================================================
latest version:
sssd-1.16.4-21.el7.x86_64
======================================================================================================================================================
[root@latest1 ~]# grep -B 3 "filter_users" /etc/sssd/sssd.conf
[nss]
memcache_timeout = 600
homedir_substring = /home
filter_users = aduser1
[root@latest1 ~]# ipa config-show | grep resolution
  Domain resolution order: ipaad2k16cin.test:akpep.test
[root@latest1 ~]# 

[root@latest1 ~]# ipactl stop
Stopping ipa-dnskeysyncd Service
Stopping ipa-otpd Service
Stopping winbind Service
Stopping smb Service
Stopping pki-tomcatd Service
Stopping ntpd Service
Stopping ipa-custodia Service
Stopping httpd Service
Stopping named Service
Stopping kadmin Service
Stopping krb5kdc Service
Stopping Directory Service
ipa: INFO: The ipactl command was successful
[root@latest1 ~]# service sssd stop; rm -rf /var/lib/sss/{db,mc}/*; service sssd start
Redirecting to /bin/systemctl stop sssd.service
Redirecting to /bin/systemctl start sssd.service
[root@latest1 ~]# sssd start
SSSD is already running
[root@latest1 ~]# grep 'sss_ncache_set_str.*aduser1' /var/log/sssd/sssd_nss.log
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
[root@latest1 ~]# 
[root@latest1 ~]# 
[root@latest1 ~]# 
[root@latest1 ~]# 
[root@latest1 ~]# 
[root@latest1 ~]# 
[root@latest1 ~]# ipactl start
Starting Directory Service
Starting krb5kdc Service
Starting kadmin Service
Starting named Service
Starting httpd Service
Starting ipa-custodia Service
Starting ntpd Service
Starting pki-tomcatd Service
Starting smb Service
Starting winbind Service
Starting ipa-otpd Service
Starting ipa-dnskeysyncd Service
ipa: INFO: The ipactl command was successful
[root@latest1 ~]# grep 'sss_ncache_set_str.*aduser1' /var/log/sssd/sssd_nss.log
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
(Wed Jun 26 03:52:16 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/akpep.test/@aduser1] to negative cache permanently
(Wed Jun 26 03:57:55 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/ipaad2k16cin.test/aduser1] to negative cache permanently
[root@latest1 ~]# date
Wed Jun 26 03:58:23 EDT 2019
[root@latest1 ~]# 

As per comment #16 
In older version the negative cache was not refreshed when new domains were found and the log entries for the AD domains is not shown.
And in latest version expected logs are shown.
As per this moving bz to verified.

Comment 20 errata-xmlrpc 2019-08-06 13:02:47 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, 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/RHSA-2019:2177

Comment 21 James Hartsock 2019-08-08 19:22:14 UTC

Bugzilla not allowing solution link, so doing as comment:
https://bugzilla.redhat.com/show_bug.cgi?id=1724088

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