Bug 1540703

Summary: FreeIPA/SSSD implicit_file sssd_nss error: The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Fatal]
Product: [Fedora] Fedora Reporter: Anthony Messina <amessina>
Component: sssdAssignee: Jakub Hrozek <jhrozek>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 27CC: abokovoy, asn, e.lania, fidencio, jhrozek, lslebodn, nalin, pbrezina, rharwood, sbose, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: sssd-1.16.1-3.fc28 sssd-1.16.1-3.fc26 sssd-1.16.1-3.fc27 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-05-01 07:42:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Anthony Messina 2018-01-31 19:50:36 UTC 
In a Fedora 27 FreeIPA-4.6 domain with the following sssd.conf, I regularly
get the followin error:

sssd_nss[2603]: The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Fatal]

Increasing the sssd debug level reveals that the fatal error seems to be raised
by the lookup in the implicit_files domain which doesn't contain this GID.

While this happens on all my FreeIPA clients, this particular host is a mailserver
postfix and cyrus-imap with saslsuthd/pam authentication so the number of user
lookups is far higher and the error occurs with considerable frequency.

Do I have a misconfiguration here or is there a problem with implicit_domain
and GID lookups?  It doesn't seem like this should be a fatal error when the
GID exists in the example.com FreeIPA/SSSD domain.

# /etc/nsswitch.conf (snippet)
passwd:     sss files mymachines systemd
shadow:     files sss
group:      sss files mymachines systemd

# /etc/sssd/sssd.conf
[domain/example.com]
cache_credentials = True
krb5_store_password_if_offline = True
ipa_domain = example.com
id_provider = ipa
auth_provider = ipa
access_provider = ipa
ipa_hostname = host.example.com
chpass_provider = ipa
ipa_server = _srv_, ipa-master.ipa.example.com
ldap_tls_cacert = /etc/ipa/ca.crt
[sssd]
services = nss, sudo, pam, ssh, ifp

domains = example.com
[nss]
homedir_substring = /home

[pam]

[sudo]

[autofs]

[ssh]

[pac]

[ifp]
allowed_uids = apache, root

[secrets]

# Relevant sssd_nss debug logs
Jan 30 18:22:48 sssd_nss[2603]: Input ID: 1111100001
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: New request 'Group by ID'
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Performing a multi-domain search
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Search will check the cache and check the data provider
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Using domain [implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up GID:1111100001@implicit_files
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Checking negative cache for [GID:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: [GID:1111100001@implicit_files] is not present in negative cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up [GID:1111100001@implicit_files] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Object [GID:1111100001@implicit_files] was not found in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up [GID:1111100001@implicit_files] in data provider
Jan 30 18:22:48 sssd_nss[2603]: Issuing request for [0x56200cc04250:2:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: Creating request for [implicit_files][0x2][BE_REQ_GROUP][idnumber=1111100001:-]
Jan 30 18:22:48 sssd_nss[2603]: Entering request [0x56200cc04250:2:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: Input ID: 1111100001
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: New request 'Group by ID'
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Performing a multi-domain search
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Search will check the cache and check the data provider
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Using domain [implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up GID:1111100001@implicit_files
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Checking negative cache for [GID:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: [GID:1111100001@implicit_files] is not present in negative cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up [GID:1111100001@implicit_files] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Object [GID:1111100001@implicit_files] was not found in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up [GID:1111100001@implicit_files] in data provider
Jan 30 18:22:48 sssd_nss[2603]: Issuing request for [0x56200cc04250:2:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: Identical request in progress: [0x56200cc04250:2:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Fatal]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Data Provider Error: 3, 5, Failed to get reply from Data Provider
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Due to an error we will return cached data
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up [GID:1111100001@implicit_files] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Object [GID:1111100001@implicit_files] was not found in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Using domain [example.com]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up GID:1111100001
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Checking negative cache for [GID:1111100001]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: [GID:1111100001] is not present in negative cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Looking up [GID:1111100001] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Returning [GID:1111100001] from cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Filtering out results by negative cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Data Provider Error: 3, 5, Failed to get reply from Data Provider
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Due to an error we will return cached data
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up [GID:1111100001@implicit_files] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Object [GID:1111100001@implicit_files] was not found in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Using domain [example.com]
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up GID:1111100001
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Checking negative cache for [GID:1111100001]
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: [GID:1111100001] is not present in negative cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Looking up [GID:1111100001] in cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Returning [GID:1111100001] from cache
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Filtering out results by negative cache
Jan 30 18:22:48 sssd_nss[2603]: Deleting request: [0x56200cc04250:2:1111100001@implicit_files]
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Found 1 entries in domain example.com
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Found 1 entries in domain example.com
Jan 30 18:22:48 sssd_nss[2603]: CR #134773: Finished: Success
Jan 30 18:22:48 sssd_nss[2603]: Domain example.com is Active
Jan 30 18:22:48 sssd_nss[2603]: Domain implicit_files is Active
Jan 30 18:22:48 sssd_nss[2603]: Domain example.com is Active
Jan 30 18:22:48 sssd_nss[2603]: CR #134774: Finished: Success
Comment 1 Jakub Hrozek 2018-01-31 20:16:21 UTC 
Upstream ticket:
https://pagure.io/SSSD/sssd/issue/3520
Comment 2 Fabiano Fidêncio 2018-04-27 12:04:33 UTC 
master:
 d69e1da
 1f8bfb6
 81f1699
 c1bce7d
 77d63f5
Comment 3 Fedora Update System 2018-04-27 21:02:36 UTC 
sssd-1.16.1-3.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-e0662375ce
Comment 4 Fedora Update System 2018-04-27 21:03:27 UTC 
sssd-1.16.1-3.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2018-33ce52aa2d
Comment 5 Fedora Update System 2018-04-27 21:09:00 UTC 
sssd-1.16.1-3.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-2f11593fb0
Comment 6 Fedora Update System 2018-04-29 09:41:25 UTC 
sssd-1.16.1-3.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-e0662375ce
Comment 7 Fedora Update System 2018-04-29 14:29:25 UTC 
sssd-1.16.1-3.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-2f11593fb0
Comment 8 Fedora Update System 2018-05-01 07:42:53 UTC 
sssd-1.16.1-3.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.
Comment 9 Fedora Update System 2018-05-01 13:18:20 UTC 
sssd-1.16.1-3.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.
Comment 10 Fedora Update System 2018-05-01 13:41:26 UTC 
sssd-1.16.1-3.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.