Hi,

Not sure this could help. Testing Samba4 as AD with lot of objects I was facing slow logins until I index memberOf attribute on Samba side.
I haven't took time yet to rebuild such a test platform and to redo this test. So really sure that could help ;)

2015-09-28 15:02 GMT+02:00 <l@avc.su>:
Hello.
I've set up SSSD v.1.12.4 with 'ad' provider, enrolled PC into domain with adcli, and everything seems to be working. I've got bothered with two problems which I think are linked.
First one, is slow logins. It takes up to 1-2 minutes sometimes to get access to machine, and commands like 'id user' and 'sudo' works slowly. From 30 seconds to two minutes approx. After record goes to cache, however, if works almost instantly.
Second is that SSSD does not resolve nested groups by default and some users that are should be allowed, are not able to login.  Possible workaround is use of explict noting of 'memberOf:1.2.840.113556.1.4.1941:' rule, but it looks like a workaround to me. Maybe I'm wrong, though.
But when I'm enabling 'ldap_groups_use_matching_rule_in_chain' and 'ldap_initgroups_use_matching_rule_in_chain', login process and commands like 'id user' and 'sudo' takes up to 2-5 minutes to finish.
It shouldn't be the network issue, all servers are on the same virtual host.

We've got rather big environment: one domain, several locations, many services and groups. Therefore, I can't enable enumeration on the machine.
As far as I understand, slow logins occuring because ad_filter needs to know if the user in the valid group or not.

So, the main question is slow logins. Here's my sssd.conf:
[domain/domain.local]
debug_level = 2

id_provider    = ad
auth_provider  = ad
chpass_provider = ad
access_provider = ad

case_sensitive       = false
cache_credentials    = true
krb5_auth_timeout    = 30
dns_resolver_timeout = 30

ad_domain   = domain.local
ad_hostname = ServerTwo.domain.local
ad_server   = loc01dc01.domain.local, _srv_, loc02dc02.domain.local
ad_backup_server      = 192.168.0.1
ad_gpo_access_control = disabled

ad_access_filter    = DOM:domain.local:(|(memberOf=CN=group1, OU=something, DC=domain, DC=local)(memberOf:1.2.840.113556.1.4.1941:=CN=grour2, OU=something, DC=domain, DC=local))

ldap_search_timeout = 15
ldap_opt_timeout    = 15
ldap_sasl_minssf    = 56

[sssd]
debug_level = 2
domains     = domain.local
services    = nss,pam,ssh,pac
config_file_version = 2

[nss]
debug_level = 2
filter_users  = root
filter_groups = root

[pam]
debug_level = 2
pam_id_timeout                 = 15

[ssh]
debug_level=2

[pac]


And here's what happens when I'm trying to log in with Kerberos (tried also password and rsa auth):

[sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [UserOne] from [<ALL>]
[sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[be[domain.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(waiting 1 sec.)
[sssd[be[domain.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD_GC'
[sssd[be[domain.local]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://loc01dc01.domain.local'
[sssd[be[domain.local]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://loc01dc01.domain.local:3268'
[sssd[be[domain.local]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [6]
[sssd[be[domain.local]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'AD'
[sssd[be[domain.local]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://loc01dc01.domain.local'
[sssd[be[domain.local]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://loc01dc01.domain.local'
[[sssd[ldap_child[18547]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [LOC01DC01$@DOMAIN.LOCAL]
[[sssd[ldap_child[18547]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab]
[sssd[be[domain.local]]] [child_sig_handler] (0x0100): child [18547] finished successfully.
[sssd[be[domain.local]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
[sssd[be[domain.local]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: LOC01DC01$
(waiting 1 sec.)
[sssd[be[domain.local]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'loc01dc01.domain.local' as 'working'
[sssd[be[domain.local]]] [set_server_common_status] (0x0100): Marking server 'loc01dc01.domain.local' as 'working'
[sssd[be[domain.local]]] [sdap_fill_memberships] (0x0080): Member [CN=group1,CN=something,DC=domain,DC=local] was not found in cache. Is it out of scope?
[sssd[be[domain.local]]] [sdap_fill_memberships] (0x0080): Member [CN=group2,OU=something,OU=something,OU=something,DC=domain,DC=local] was not found in cache. Is it out of scope?
[sssd[be[domain.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
[sssd[be[domain.local]]] [sdap_fill_memberships] (0x0080): Member [CN=group3,OU=something,OU=something,OU=something,DC=domain,DC=local] was not found in cache. Is it out of scope?
... (many many many more 'success' with few errors 'out of scope')
[sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [UserOne] from [<ALL>]
[sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [userone@domain.local]
(repeated twice)
[sssd[pam]] [pam_cmd_acct_mgmt] (0x0100): entering pam_cmd_acct_mgmt
[sssd[pam]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
[sssd[pam]] [pam_print_data] (0x0100): domain: not set
[sssd[pam]] [pam_print_data] (0x0100): user: UserOne
[sssd[pam]] [pam_print_data] (0x0100): service: sshd
[sssd[pam]] [pam_print_data] (0x0100): tty: ssh
[sssd[pam]] [pam_print_data] (0x0100): ruser: not set
[sssd[pam]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): priv: 1
[sssd[pam]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[pam]] [pam_print_data] (0x0100): logon name: UserOne
[sssd[be[domain.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
[sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
[sssd[pam]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
[sssd[pam]] [pam_print_data] (0x0100): domain: domain.local
[sssd[pam]] [pam_print_data] (0x0100): user: UserOne
[sssd[pam]] [pam_print_data] (0x0100): service: sshd
[sssd[pam]] [pam_print_data] (0x0100): tty: ssh
[sssd[pam]] [pam_print_data] (0x0100): ruser: not set
[sssd[pam]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): priv: 1
[sssd[pam]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[pam]] [pam_print_data] (0x0100): logon name: UserOne
[sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
[sssd[be[domain.local]]] [be_pam_handler] (0x0100): Got request with the following data
[sssd[be[domain.local]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
[sssd[be[domain.local]]] [pam_print_data] (0x0100): domain: domain.local
[sssd[be[domain.local]]] [pam_print_data] (0x0100): user: UserOne
[sssd[be[domain.local]]] [pam_print_data] (0x0100): service: sshd
[sssd[be[domain.local]]] [pam_print_data] (0x0100): tty: ssh
[sssd[be[domain.local]]] [pam_print_data] (0x0100): ruser:
[sssd[be[domain.local]]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[be[domain.local]]] [pam_print_data] (0x0100): authtok type: 0
[sssd[be[domain.local]]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[be[domain.local]]] [pam_print_data] (0x0100): priv: 1
[sssd[be[domain.local]]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[be[domain.local]]] [pam_print_data] (0x0100): logon name: not set
[sssd[be[domain.local]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success]
[sssd[be[domain.local]]] [be_pam_handler_callback] (0x0100): Sending result [0][domain.local]
[sssd[pam]] [pam_dp_process_reply] (0x0100): received: [0][domain.local]
[sssd[be[domain.local]]] [be_pam_handler_callback] (0x0100): Sent result [0][domain.local]
[sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [userone] from [<ALL>]
[sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for [userone@domain.local]
(repeated 6 times)
[sssd[pam]] [pam_cmd_open_session] (0x0100): entering pam_cmd_open_session
[sssd[pam]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
[sssd[pam]] [pam_print_data] (0x0100): domain: not set
[sssd[pam]] [pam_print_data] (0x0100): user: UserOne
[sssd[pam]] [pam_print_data] (0x0100): service: sshd
[sssd[pam]] [pam_print_data] (0x0100): tty: ssh
[sssd[pam]] [pam_print_data] (0x0100): ruser: not set
[sssd[pam]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): priv: 1
[sssd[pam]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[pam]] [pam_print_data] (0x0100): logon name: UserOne
[sssd[pam]] [pam_check_user_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:
[sssd[pam]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
[sssd[pam]] [pam_print_data] (0x0100): domain: domain.local
[sssd[pam]] [pam_print_data] (0x0100): user: UserOne
[sssd[pam]] [pam_print_data] (0x0100): service: sshd
[sssd[pam]] [pam_print_data] (0x0100): tty: ssh
[sssd[pam]] [pam_print_data] (0x0100): ruser: not set
[sssd[pam]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[pam]] [pam_print_data] (0x0100): authtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[pam]] [pam_print_data] (0x0100): priv: 1
[sssd[pam]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[pam]] [pam_print_data] (0x0100): logon name: UserOne
[sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
[sssd[be[domain.local]]] [be_pam_handler] (0x0100): Got request with the following data
[sssd[be[domain.local]]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION
[sssd[be[domain.local]]] [pam_print_data] (0x0100): domain: domain.local
[sssd[be[domain.local]]] [pam_print_data] (0x0100): user: UserOne
[sssd[be[domain.local]]] [pam_print_data] (0x0100): service: sshd
[sssd[be[domain.local]]] [pam_print_data] (0x0100): tty: ssh
[sssd[be[domain.local]]] [pam_print_data] (0x0100): ruser:
[sssd[be[domain.local]]] [pam_print_data] (0x0100): rhost: ServerOne.domain.local
[sssd[be[domain.local]]] [pam_print_data] (0x0100): authtok type: 0
[sssd[be[domain.local]]] [pam_print_data] (0x0100): newauthtok type: 0
[sssd[be[domain.local]]] [pam_print_data] (0x0100): priv: 1
[sssd[be[domain.local]]] [pam_print_data] (0x0100): cli_pid: 18545
[sssd[be[domain.local]]] [pam_print_data] (0x0100): logon name: not set
[sssd[be[domain.local]]] [be_pam_handler] (0x0100): Sending result [0][domain.local]
[sssd[pam]] [pam_dp_process_reply] (0x0100): received: [0][domain.local]
[sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [userone] from [<ALL>]
[sssd[nss]] [nss_cmd_initgroups_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [userone] from [<ALL>]
[sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [userone@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [704943713@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [704943713]

It takes from about 30 secs to 2 minutes lo login.


Here what I see in logs when setting options 'ldap_groups_use_matching_rule_in_chain' and 'ldap_initgroups_use_matching_rule_in_chain' and running 'id user':

[sssd[be[domain.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [704754393@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [704754393]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [704754393@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [704754393]
... (many of these messages, about 1-3/sec)
And then I see these messages:
[sssd[be[domain.local]]] [sysdb_store_group] (0x0080): A group with the same GID [704543591] was removed from the cache
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [704543591@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [704543591]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0100): Requesting info for [704432243@domain.local]
[sssd[nss]] [nss_cmd_getgrgid_search] (0x0080): No matching domain found for [704432243]
[sssd[be[domain.local]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
[sssd[be[domain.local]]] [sysdb_store_group] (0x0080): A group with the same GID [704432243] was removed from the cache
... (not so many, but still a lot.)

In the output of 'id user' I see these strange groups:
704195244(groupname {fcc357ea-83ef-4645-17e9-1967bfe8a77f})


Is there anything I can do to speed up my login? Is there anything I've messed up in my sssd.conf?

Any help appreciated. Thank you in advance.



_______________________________________________
sssd-users mailing list
sssd-users@lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users