On 14 Aug 2015, at 11:44, Davor Vusir <davortvusir(a)gmail.com>
wrote:
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:
What distribution is that?
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]
~~~~~~~~~~~~~~~ ^ ~~
Can you also enable debugging in the responders so that we know which client sent this
query? The backend receives queries from responders and acts upon those...
(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].
~~~~~~~~~~~~~~~ ^ ~~
Same here, we need to find out where the queries are coming from..
(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
_______________________________________________
sssd-users mailing list
sssd-users(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users