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