Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

SSSD fails nss_getby_name for IPA user with SID if the user has user private group #5607

Closed
sumit-bose opened this issue Apr 27, 2021 · 1 comment
Closed

SSSD fails nss_getby_name for IPA user with SID if the user has user private group #5607

sumit-bose opened this issue Apr 27, 2021 · 1 comment
Assignees
@sumit-bose
Labels
Bugzilla Closed: Fixed Issue was closed as fixed.

Comments

@sumit-bose
Copy link
Contributor

Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 8): Bug 1837090

In IPA domain, with trust support enabled, SSSD fails to retrieve IPA user's
SID if there is a user private group associated with the user (default IPA
setup):

[root@master ~]# ipa user-add some-user
First name: Some
Last name: User
----------------------
Added user "some-user"
----------------------
  User login: some-user
  First name: Some
  Last name: User
  Full name: Some User
  Display name: Some User
  Initials: SU
  Home directory: /home/some-user
  GECOS: Some User
  Login shell: /bin/sh
  Principal name: some-user@IPA.TEST
  Principal alias: some-user@IPA.TEST
  Email address: some-user@ipa.test
  UID: 1908200011
  GID: 1908200011
  Password: False
  Member of groups: ipausers
  Kerberos keys available: False
[root@master ~]# id IPA\\some-user
uid=1908200011(some-user) gid=1908200011(some-user)
groups=1908200011(some-user)

The use case here is that an application performs a getsidbyname lookup against
SSSD API:

[root@master ~]# python
Python 3.8.2 (default, Feb 28 2020, 00:00:00)
[GCC 10.0.1 20200216 (Red Hat 10.0.1-0.8)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import pysss_nss_idmap
>>> pysss_nss_idmap.getsidbyname('IPA\\admin')
{'IPA\\admin': {'sid': 'S-1-5-21-3787809381-104084847-3373960542-500', 'type':
1}}
>>> pysss_nss_idmap.getsidbyname('IPA\\some-user')
{}
>>> pysss_nss_idmap.getsidbyname('IPA\\some-user')
{}
>>>

We can see in the sssd_nss.log that it stumbled upon a UPG without SID:

(Mon May 18 19:18:47 2020) [sssd[nss]] [get_client_cred] (0x4000): Client
[0x55bd9dc69480][27] creds: euid[0] egid[0] pid[274415] cmd_line['python'].
(Mon May 18 19:18:47 2020) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle
timer re-set for client [0x55bd9dc69480][27]
(Mon May 18 19:18:47 2020) [sssd[nss]] [accept_fd_handler] (0x0400): Client
[0x55bd9dc69480][27] connected!
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received
client version [1].
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered
version [1].
(Mon May 18 19:18:47 2020) [sssd[nss]] [nss_getby_name] (0x0400): Input name:
IPA\some-user
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR
#122: Setting "Object by name" plugin
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_send] (0x0400): CR #122: New
request 'Object by name'
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_process_input] (0x0400): CR
#122: Parsing input name [IPA\some-user]
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain
ipa.test is Active
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_parse_name_for_domains] (0x0200):
name 'IPA\some-user' matched expression for domain 'ipa.test', user is
some-user
(Mon May 18 19:18:47 2020) [sssd[nss]] [nss_get_object_send] (0x0400): Client
[0x55bd9dc69480][27]: sent cache request #122
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_set_name] (0x0400): CR #122:
Setting name [some-user]
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_select_domains] (0x0400): CR
#122: Performing a single domain search
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain
implicit_files is Active
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain
ipa.test is Active
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_domains] (0x0400): CR
#122: Search will check the cache and check the data provider
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_validate_domain_type]
(0x2000): Request type POSIX-only for domain ipa.test type POSIX is valid
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_set_domain] (0x0400): CR
#122: Using domain [ipa.test]
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_prepare_domain_data]
(0x0400): CR #122: Preparing input data for domain [ipa.test] rules
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_send] (0x0400): CR
#122: Looking up some-user@ipa.test
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR
#122: Checking negative cache for [some-user@ipa.test]
(Mon May 18 19:18:47 2020) [sssd[nss]] [sss_ncache_check_str] (0x2000):
Checking negative cache for [NCE/USER/ipa.test/some-user@ipa.test]
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR
#122: [some-user@ipa.test] is not present in negative cache
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_cache] (0x0400): CR
#122: Looking up [some-user@ipa.test] in cache
(Mon May 18 19:18:47 2020) [sssd[nss]] [ldb] (0x4000): Added timed event
"ldb_kv_callback": 0x55bd9dc6c280

(Mon May 18 19:18:47 2020) [sssd[nss]] [ldb] (0x4000): Added timed event
"ldb_kv_timeout": 0x55bd9dc59ea0

(Mon May 18 19:18:47 2020) [sssd[nss]] [ldb] (0x4000): Running timer event
0x55bd9dc6c280 "ldb_kv_callback"

(Mon May 18 19:18:47 2020) [sssd[nss]] [ldb] (0x4000): Destroying timer event
0x55bd9dc59ea0 "ldb_kv_timeout"

(Mon May 18 19:18:47 2020) [sssd[nss]] [ldb] (0x4000): Destroying timer event
0x55bd9dc6c280 "ldb_kv_callback"

(Mon May 18 19:18:47 2020) [sssd[nss]] [sysdb_search_object_attr] (0x0020):
Search with filter [(&(|(objectCategory=user)(objectCategory=group))(|(nameAlia
s=some-user@ipa.test)(name=some-user@ipa.test)))] returned more than one
object.
(Mon May 18 19:18:47 2020) [sssd[nss]] [sysdb_search_object_attr] (0x0040):
Error: 22 (Invalid argument)
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_search_cache] (0x0020): CR
#122: Unable to lookup [some-user@ipa.test] in cache [22]: Invalid argument
(Mon May 18 19:18:47 2020) [sssd[nss]] [cache_req_process_result] (0x0400): CR
#122: Finished: Error 22: Invalid argument
(Mon May 18 19:18:47 2020) [sssd[nss]] [nss_protocol_done] (0x4000): Sending
reply: error [22]: Invalid argument
(Mon May 18 19:18:47 2020) [sssd[nss]] [client_recv] (0x0200): Client
disconnected!
(Mon May 18 19:18:47 2020) [sssd[nss]] [client_close_fn] (0x2000): Terminated
client [0x55bd9dc69480][27]

There is nothing in the domain log for that specific request because
information was cached by the 'id' call few seconds before:

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_initgr_user]
(0x4000): Process user's groups
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_primary_name]
(0x0400): Processing object some-user
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_has_deref_support_ex]
(0x0400): The server supports deref method OpenLDAP
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_print_server] (0x2000):
Searching 10.0.106.211:389
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup)(objectCl
ass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test].
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [objectClass]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [posixGroup]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [cn]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [userPassword]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [gidNumber]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [member]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [ipaUniqueID]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [ipaNTSecurityIdentifier]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [modifyTimestamp]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [entryUSN]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [ipaExternalMember]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x2000): ldap_search_ext called, msgid = 14
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_op_add] (0x2000): New
operation 14 timeout 6
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: sh[0x561a95868ae0], connected[1], ops[0x561a95837be0],
ldap[0x561a95776890]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: sh[0x561a95868ae0], connected[1], ops[0x561a95837be0],
ldap[0x561a95776890]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_entry] (0x1000):
OriginalDN: [cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test].
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectClass]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [cn]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [member]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [ipaUniqueID]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [modifyTimestamp]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_parse_range] (0x2000): No
sub-attributes for [entryUSN]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: sh[0x561a95868ae0], connected[1], ops[0x561a95837be0],
ldap[0x561a95776890]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_op_destructor] (0x2000):
Operation 14 finished
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_search_by_name]
(0x0400): No such entry
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_add_incomplete_groups]
(0x1000): Group #0 [ipausers@ipa.test][ipausers@ipa.test] is not cached, need
to add a fake entry
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_primary_name]
(0x0400): Processing object ipausers
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_attrs_get_sid_str]
(0x1000): No [objectSIDString] attribute. [0][Success]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_add_incomplete_groups]
(0x1000): The group ipausers@ipa.test gid was missing
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_add_incomplete_groups]
(0x0400): Marking group ipausers@ipa.test as non-POSIX and setting GID=0!
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_add_incomplete_groups]
(0x2000): Adding fake group ipausers@ipa.test to sysdb
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_ldb_msg_difference]
(0x2000): Added attr [lastUpdate] to entry
[name=ipausers@ipa.test,cn=groups,cn=ipa.test,cn=sysdb]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95848bb0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95848bb0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95848bb0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_set_entry_attr]
(0x0200): Entry [name=ipausers@ipa.test,cn=groups,cn=ipa.test,cn=sysdb] has set
[cache, ts_cache] attrs.
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_primary_name]
(0x0400): Processing object ipausers
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_get_direct_parents]
(0x2000): searching sysdb with filter [(&(objectCategory=group)(member=name=ipa
users@ipa.test,cn=groups,cn=ipa.test,cn=sysdb))]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_get_direct_parents]
(0x1000): ipausers@ipa.test is a member of 0 sysdb groups
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[sdap_initgr_nested_get_direct_parents] (0x4000): Looking up direct parents for
group [cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[sdap_initgr_nested_get_direct_parents] (0x4000): The group
[cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=test] has 0 direct parents
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[sdap_initgr_nested_get_membership_diff] (0x1000): The group ipausers@ipa.test
is a direct member of 0 LDAP groups
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[sdap_initgr_store_user_memberships] (0x1000): The user some-user@ipa.test is a
direct member of 1 LDAP groups
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_get_direct_parents]
(0x2000): searching sysdb with filter [(&(objectCategory=group)(member=name=som
e-user@ipa.test,cn=users,cn=ipa.test,cn=sysdb))]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a95841a70

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a95841a70 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sysdb_get_direct_parents]
(0x1000): some-user@ipa.test is a member of 0 sysdb groups
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[sdap_initgr_store_user_memberships] (0x2000): Updating memberships for
some-user@ipa.test
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sss_domain_get_state]
(0x1000): Domain ipa.test is Active
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): start ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9583cf10

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9583cf10 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9582f1d0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9687c0f0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_timeout"
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583cf10 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9582f1d0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a968824f0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9687f410

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687c0f0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9582f1d0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a968824f0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687c0f0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a96886550

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687f410 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a968824f0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687c0f0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687f410

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a96881d30

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a96886550 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687c0f0 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687f410 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a96881d30 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687f410 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 3)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 2)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 1)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): commit ldb
transaction (nesting: 0)
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_initgr_done]
(0x4000): Initgroups done
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_initgr_done]
(0x0400): Primary group already cached, nothing to do.
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_initgr_done]
(0x4000): No need to check for domain local group memberships.
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_id_op_done] (0x4000):
releasing operation connection
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_callback": 0x561a9687ea00

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Added timed
event "ldb_kv_timeout": 0x561a9583eab0

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Running timer
event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9583eab0 "ldb_kv_timeout"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ldb] (0x4000): Destroying
timer event 0x561a9687ea00 "ldb_kv_callback"

(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_id_op_connect_step]
(0x4000): reusing cached connection
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]]
[ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view
[Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUU
ID=:IPA:ipa.test:571fa34c-993c-11ea-b112-fa163efaafc4))].
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_print_server] (0x2000):
Searching 10.0.106.211:389
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAn
chorUUID=:IPA:ipa.test:571fa34c-993c-11ea-b112-fa163efaafc4))][cn=Default Trust
View,cn=views,cn=accounts,dc=ipa,dc=test].
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_ext_step]
(0x2000): ldap_search_ext called, msgid = 15
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_op_add] (0x2000): New
operation 15 timeout 6
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: sh[0x561a95868ae0], connected[1], ops[0x561a96882230],
ldap[0x561a95776890]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_result] (0x2000):
Trace: sh[0x561a95868ae0], connected[1], ops[0x561a96882230],
ldap[0x561a95776890]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_op_destructor] (0x2000):
Operation 15 finished
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [ipa_get_ad_override_done]
(0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaA
nchorUUID=:IPA:ipa.test:571fa34c-993c-11ea-b112-fa163efaafc4))].
(Mon May 18 19:18:44 2020) [sssd[be[ipa.test]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
sumit-bose added a commit to sumit-bose/sssd that referenced this issue Apr 27, 2021
@sumit-bose
nss: fix getsidbyname for IPA user-private-groups
0adfd78 
Currently the getsidbyname request does not work properly for IPA users
due to the way IPA user-private-groups are handled by SSSD. With this
patch two different cases, the default automatic user-private-groups
where the group is a managed object and manual creation of a user and a
groups with UID and GIDs so that the group is a user-private group, are
covered.

Resolves: SSSD#5607

:fixes: Fix getsidbyname issues with IPA users with a user-private-group
@sumit-bose sumit-bose mentioned this issue Apr 27, 2021
Closed
sumit-bose added a commit to sumit-bose/sssd that referenced this issue May 19, 2021
@sumit-bose
nss: fix getsidbyname for IPA user-private-groups
f968767 
Currently the getsidbyname request does not work properly for IPA users
due to the way IPA user-private-groups are handled by SSSD. With this
patch two different cases are handled.

The first is about the default automatic user-private-groups
where the group is a managed object. In this case there will be a user
and a group object with the same name in the cache which will both be
found by the lookup by name. Since only the user object will have a SID
we can return this SID for the request.

The second case is the manual creation of a user and a groups with UID
and GIDs so that the group is a user-private group. Here the user and
the group object will both get a different SID assigned since they are
independent objects. In this case, both objects have a SID and the UID
and GID of the user and the GID of the group all have the same numerical
value, the SID of the user is returned.

Resolves: SSSD#5607

:fixes: Fix getsidbyname issues with IPA users with a user-private-group
@pbrezina
Copy link
Member

Pushed PR: #5608

  • master
    • 9cb8966 - nss: fix getsidbyname for IPA user-private-groups

@pbrezina pbrezina added the Closed: Fixed Issue was closed as fixed. label May 25, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sumit-bose sumit-bose

Labels
Bugzilla Closed: Fixed Issue was closed as fixed.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

nss: fix getsidbyname for IPA user-private-groups sumit-bose/sssd
3 participants
@sumit-bose @pbrezina @alexey-tikhonov