[SSSD-users] Faulty ldap query?

[Davor Vusir]

Hello!

I'm finetuning sssd and going through the logs. We're using AD as 
authentication source. SSSD is version 1.12.2 and seems to send a faulty 
query to the DC:

My sAMAccountName is myLogonID but some queries passes the value of 
givenName. It searches the two defined ldap_search_base twice before it 
returns "No such entry". Followed by a query for "(unknown)". This
query 
is only once per search base. See log below.

Regards
Davor Vusir

---

(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[sysdb_gpo_get_gpo_result_setting] (0x0400): key 
[SeRemoteInteractiveLogonRight] value [*S-1-5-21-XXX-YYY-ZZZ-287220]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[sysdb_gpo_get_gpo_result_setting] (0x0400): key 
[SeDenyRemoteInteractiveLogonRight] value [(null)]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[parse_policy_setting_value] (0x0400): No value for key 
[SeDenyRemoteInteractiveLogonRight] found in gpo result
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): RESULTANT POLICY:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): gpo_map_type: Remote Interactive
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): allowed_size = 1
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): allowed_sids[0] = 
S-1-5-21-XXX-YYY-ZZZ-287220
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): denied_size = 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): CURRENT USER:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400):        user_sid = 
S-1-5-21-XXX-YYY-ZZZ-174590
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400):   group_sids[0] = S-1-5-21-XXX-YYY-ZZZ-50989
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400):   group_sids[1] = S-1-5-11
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): POLICY DECISION:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400):  access_granted = 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400):   access_denied = 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_check] (0x0400): access denied: permissive mode
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[ad_gpo_access_done] (0x0400): GPO-based access control successful.
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) 
[Success]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_pam_handler_callback] (0x0400): SELinux provider doesn't exist, not 
sending the request to it.
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_pam_handler_callback] (0x0100): Sending result [0][ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_pam_handler_callback] (0x0100): Sent result [0][ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_req_set_domain] (0x0400): Changing request domain from 
[ad.example.org] to [ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Got request with the following data
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): command: PAM_SETCRED
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): domain: ad.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): user: myLogonID
~~~~~~~~~~~~~~~ ^ ~~

(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): service: sshd
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): tty: ssh
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): ruser:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): rhost: client-1.subdomain.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): authtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): newauthtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): priv: 1
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): cli_pid: 4460
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): logon name: not set
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Sending result [0][ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_req_set_domain] (0x0400): Changing request domain from 
[ad.example.org] to [ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Got request with the following data
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): command: PAM_OPEN_SESSION
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): domain: ad.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): user: myLogonID
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): service: sshd
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): tty: ssh
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): ruser:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): rhost: client-1.subdomain.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): authtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): newauthtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): priv: 1
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): cli_pid: 4460
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): logon name: not set
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Sending result [0][ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] 
[be_req_set_domain] (0x0400): Changing request domain from 
[ad.example.org] to [ad.example.org]
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Got request with the following data
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): command: PAM_SETCRED
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): domain: ad.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): user: myLogonID
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): service: sshd
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): tty: ssh
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): ruser:
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): rhost: client-1.subdomain.example.org
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): authtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): newauthtok type: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): priv: 0
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): cli_pid: 4468
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [pam_print_data] 
(0x0100): logon name: not set
(Fri Aug 14 10:29:03 2015) [sssd[be[ad.example.org]]] [be_pam_handler] 
(0x0100): Sending result [0][ad.example.org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[be_get_account_info] (0x0200): Got request for [0x1003][1][name=davor]
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[be_req_set_domain] (0x0400): Changing request domain from 
[ad.example.org] to [ad.example.org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_initgr_next_base] (0x0400): Searching for users with base 
[ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=davor)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_initgr_next_base] (0x0400): Searching for users with base 
[ou=CT,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=davor)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][ou=CT,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_initgr_next_base] (0x0400): Searching for users with base 
[ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=davor)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_initgr_next_base] (0x0400): Searching for users with base 
[ou=CT,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=davor)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][ou=CT,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sysdb_search_by_name] (0x0400): No such entry
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sysdb_delete_user] (0x0400): Error: 2 (No such file or directory)

(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[be_get_account_info] (0x0200): Got request for [0x1001][1][name=(unknown)]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[be_req_set_domain] (0x0400): Changing request domain from 
[ad.example.org] to [ad.example.org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_search_user_next_base] (0x0400): Searching for users with base 
[ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=\28unknown\29)(objectclass=user)(sAMAccountName=*)(&(uidNumber=*)(!(uidNumber=0))))][ou=Users,ou=Employee,ou=CompanyIDs,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_search_user_process] (0x0400): Search for users, returned 0 results.
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_search_user_next_base] (0x0400): Searching for users with base 
[ou=CT,dc=ad,dc=example,dc=org]
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with 
[(&(sAMAccountName=\28unknown\29)(objectclass=user)(sAMAccountName=*)(&(uidNumber=*)(!(uidNumber=0))))][ou=CT,dc=ad,dc=example,dc=org].
~~~~~~~~~~~~~~~ ^ ~~
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no 
errmsg set
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_search_user_process] (0x0400): Search for users, returned 0 results.
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sdap_get_users_done] (0x0040): Failed to retrieve users
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sysdb_search_by_name] (0x0400): No such entry
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[sysdb_delete_user] (0x0400): Error: 2 (No such file or directory)
(Fri Aug 14 10:29:04 2015) [sssd[be[ad.example.org]]] 
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success