[SSSD] slow logins via ssh

GOLLSCHEWSKY, Tim Tim.GOLLSCHEWSKY at suncorp.com.au
Fri Sep 23 02:20:36 UTC 2011


Hi Dmitri, thanks for your response.

>> The bit I don't understand is:  It does this even when I have "Enumerate" set to False.  Isn't Enumerate = False supposed to stop it from downloading all the group memberships?
>>
>> http://docs.redhat.com/docs/en-US/Red_Hat_Enterprise_Linux/6/html/Deployment_Guide/chap-SSSD_User_Guide-Configuring_Domains.html
>>
>> Note I'm using an "ldap_filter" on just one group to control access to the box.  So really for the initial login process it only needs to see the users that exist in one group.  The only time I would expect it to look at other groups is when somebody types the "groups" command for example or does an "ls" in a directory.
>>
>
>This is not how it works. It does the resolution of the user and all his
>membership once user logs in. We do it once at the login as we do not
>know what  applications and user would do. You know that you never call
>"groups" and want to offload the performance hit to it but we do not.
>This is why we can't have partial information. There were some
>performance issue like that that we noticed and tried to address
>recently. What version are you running and on what OS? Some of the
>recent 1.6 fixes might help.

I'm running RHEL6:

$ rpm -q sssd
sssd-1.5.1-34.el6_1.3.x86_64

>Also you might extend the cache timeouts significantly but then the
>changes made centrally would also be propagated with significant latency.
>I also wonder if winbind would be faster... Have you ever tried winbind?

Not for many years, but if this is preferable for large organisations
I could give it a shot.

>It will be interesting to compare its performance and sssd in your setup
>as we are bringing it as a back end to sssd soon.
>
>If you can provide sanitized logs and info about how your data is
>structured (how many groups, nesting, etc) we would be able to see if
>this problem is something we already know about or something different.

At this point in time we have 145 groups in the "ldap_group_search_base", although this
is growing all the time.  Each group has about 10-200 members.

So it doesn't sound like a lot, but it takes around 30 seconds to enumerate all this information
at login time.

Here's an example of the sanitised debug logs while it's doing the enumeration (heavily grep -v'd)

  ...
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=oggap,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [oggap]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=oggap,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [oggap] is not a direct member of any groups
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=rmbad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=rmbad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [rmbad]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=rmbad,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [rmbad] is not a direct member of any groups
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=iswad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=iswad,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Processing group [iswad]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(member=name=iswad,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_update_sysdb] (6): Group [iswad] is not a direct member of any groups
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Saving incomplete group [voirp] to the sysdb
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=voirp,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
  (Fri Sep 23 08:58:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=voirp,OU=xxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  ...

And timings from the start of the ssh connection until the password prompt is rendered:

  (Fri Sep 23 12:03:36 2011) [sssd[be[XXX.XXX.XXX]]] [be_get_account_info] (4): Got request for [4097][1][name=xxxuser]
  (Fri Sep 23 12:04:06 2011) [sssd[be[XXX.XXX.XXX]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success

Best regards,

Tim Gollschewsky.

This e-mail is sent by Suncorp Group Limited ABN 66 145 290 124 or one of its related entities "Suncorp".
Suncorp may be contacted at Level 18, 36 Wickham Terrace, Brisbane or on 13 11 55 or at suncorp.com.au.
The content of this e-mail is the view of the sender or stated author and does not necessarily reflect the view of Suncorp. The content, including attachments, is a confidential communication between Suncorp and the intended recipient. If you are not the intended recipient, any use, interference with, disclosure or copying of this e-mail, including attachments, is unauthorised and expressly prohibited. If you have received this e-mail in error please contact the sender immediately and delete the e-mail and any attachments from your system.



More information about the sssd-devel mailing list