Hi guys,
We've been experimenting with putty v0.61 and windows SSO authentication. e.g. You log into windows with username "tim" and when then load up putty and try and connect to a RHEL6 machine, it passes along my Windows GSSAPI credentials and automatically logs me in to the RHEL6 box.
SSSD has been configured to talk to Active Directory like so:
[domain/KRB5DOMAIN] enumerate = True ldap_id_use_start_tls = False cache_credentials = True id_provider = ldap auth_provider = krb5 chpass_provider = krb5 debug_level = 1
ldap_schema = rfc2307bis ldap_force_upper_case_realm = True ldap_user_object_class = user ldap_group_object_class = group ldap_user_home_directory = unixHomeDirectory ldap_user_name = msSFU30Name ldap_user_member_of = msSFU30PosixMemberOf ldap_group_member = msSFU30PosixMember
access_provider = ldap ldap_uri = ldap://xxxx/ ldap_search_base = xxx ldap_user_search_base = xxx ldap_group_search_base = xxx ldap_sasl_mech = gssapi ldap_sasl_authid = xxx ldap_krb5_keytab = xxx ldap_krb5_init_creds = true ldap_tls_cacertdir = /etc/openldap/cacerts krb5_realm = xxx krb5_kpasswd = xxx krb5_server = xxx
What we're finding is Windows for some reason stores the username in UPPERCASE and passes the uppercase value in the GSSAPI credentials. However the username attribute in AD (msSFU30Name) stores the username in lowercase, which is the standard for Unix usernames and something we are very comfortable with.
Because the username comparison is case-sensitive, the user is denied access. If we hard-code the login name in putty to be lowercase it works, so I'm pretty sure the GSSAPI auth is working.
So, my question is: Is there a way to make the username comparison to LDAP case-insensitive? Or do we need to update our AD/LDAP to uppercase all the msSFU30Name attributes? Or is there another option?
I understand usernames should be compared case-sensitive to be POSIX compliant. I've just been asked to see if I can get this to work.
BTW I've been browsing trac and it looks like you were considering a "force_lowercase_names" config option at one point. Is this still under consideration? https://fedorahosted.org/sssd/ticket/246
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.
On Wed, Aug 31, 2011 at 04:43:28PM +1000, GOLLSCHEWSKY, Tim wrote:
BTW I've been browsing trac and it looks like you were considering a "force_lowercase_names" config option at one point. Is this still under consideration? https://fedorahosted.org/sssd/ticket/246
Hi, I think you might find https://fedorahosted.org/sssd/ticket/890 interesting..currently scheduled for 1.8
On Wed, Aug 31, 2011 at 04:43:28PM +1000, GOLLSCHEWSKY, Tim wrote:
BTW I've been browsing trac and it looks like you were considering a "force_lowercase_names" config > option at one point. Is this still under consideration? https://fedorahosted.org/sssd/ticket/246
Hi, I think you might find https://fedorahosted.org/sssd/ticket/890 interesting..currently scheduled for 1.8
Hi Jakub, yes this comment by simo:
| User and Group names are case insensitive on most LDAP servers. So we should have an option to mark a | sssd domain as case insensitive do all our string comparisons in a case-insensitive way and return | all user and group names lowercased to the OS.
Hits the nail right on the head.
Can I +1 this enhancement ticket please? :)
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.
Hi all.
I work in an organisation with a relatively large LDAP (active) directory.
When we ssh into a server running SSSD it seems to enumerate all the groups in the "ldap_group_search_base" which takes a very long time. Sometimes it can take up to 30 seconds for the Password: prompt to appear to the ssh client, which feels like ages when you are logging into Linux machines all day.
I've been running debug on the sssd process and I can see it searching and populating all the groups when a person tries to log in. It calls "ldap_search_ext" over and over again until all the groups (and users inside those groups) have been discovered. Once it's done this and has all the info in the cache, logging back in again is quick. But if I don't login for a day or so and try to login again, it downloads all the group information once again and I have the 30 second wait.
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...
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.
access_provider = ldap ldap_access_filter = memberOf=cn=jbsrd,ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx
I'm just wondering if anybody else is using sssd in a large company or university with a large LDAP directory and wondered how they got around this issue.
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.
On 09/22/2011 08:02 PM, GOLLSCHEWSKY, Tim wrote:
Hi all.
I work in an organisation with a relatively large LDAP (active) directory.
When we ssh into a server running SSSD it seems to enumerate all the groups in the "ldap_group_search_base" which takes a very long time. Sometimes it can take up to 30 seconds for the Password: prompt to appear to the ssh client, which feels like ages when you are logging into Linux machines all day.
I've been running debug on the sssd process and I can see it searching and populating all the groups when a person tries to log in. It calls "ldap_search_ext" over and over again until all the groups (and users inside those groups) have been discovered. Once it's done this and has all the info in the cache, logging back in again is quick. But if I don't login for a day or so and try to login again, it downloads all the group information once again and I have the 30 second wait.
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...
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.
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? 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.
access_provider = ldap ldap_access_filter = memberOf=cn=jbsrd,ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx
I'm just wondering if anybody else is using sssd in a large company or university with a large LDAP directory and wondered how they got around this issue.
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. _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://fedorahosted.org/mailman/listinfo/sssd-devel
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...
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.
On Fri, 2011-09-23 at 12:20 +1000, GOLLSCHEWSKY, Tim wrote:
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...
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]. ...
This isn't enough information to say where the latency is occurring. Is the 30s passing while it's still iterating through "Looking up parent groups for group", or are you seeing it happen while the SSSD is saving the results to the cache? I'm guessing that the problem is likely happening during the latter. We're doing a lot of work right now for 1.6.2 with improving the cache performance, but I'd like to try and track this down to make sure our current enhancement plans will aid you.
On Fri, 23 Sep 2011, Stephen Gallagher wrote:
This isn't enough information to say where the latency is occurring. Is the 30s passing while it's still iterating through "Looking up parent groups for group", or are you seeing it happen while the SSSD is saving the results to the cache? I'm guessing that the problem is likely happening during the latter. We're doing a lot of work right now for 1.6.2 with improving the cache performance, but I'd like to try and track this down to make sure our current enhancement plans will aid you.
This was definitely one of the cases with 1.6.1 that I found was cache performance limited (as you suggest). In my case symlinking cache_default.ldb to /dev/shm made this clear by entirely resolving the performance issue (reducing a near 60 second op to around 3).
jh
On Fri, 23 Sep 2011, Stephen Gallagher wrote:
This isn't enough information to say where the latency is occurring. Is the 30s passing while it's still iterating through "Looking up parent groups for group", or are you seeing it happen while the SSSD is saving the results to the cache? I'm guessing that the problem is likely happening during the latter. We're doing a lot of work right now for 1.6.2 with improving the cache performance, but I'd like to try and track this down to make sure our current enhancement plans will aid you.
This was definitely one of the cases with 1.6.1 that I found was cache performance limited (as you suggest). In my case symlinking cache_default.ldb to /dev/shm made this clear by entirely resolving the performance issue (reducing a near 60 second op to around 3).
I just tried symlinking my cache file to /dev/shm and it went from 28 secs to 16 secs... so some improvement:
(Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxange (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxlemr (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group edcrd (Mon Sep 26 10:29:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxb2 (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx002 (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx001 (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group cifrp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:26 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:27 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxra (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxu (Mon Sep 26 10:29:28 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxu (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxi (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx002 (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:29 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx003 (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxdef (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 10:29:30 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 10:29:31 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd
Note this is still with 1.5.1 (RHEL package), I haven't got 1.6.1 working yet. :)
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.
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]. ...
This isn't enough information to say where the latency is occurring. Is the 30s passing while it's still iterating through "Looking up parent groups for group", or are you seeing it happen while the SSSD is saving the results to the cache? I'm guessing that the problem is likely happening during the latter. We're doing a lot of work right now for 1.6.2 with improving the cache performance, but I'd like to try and track this down to make sure our current enhancement plans will aid you.
Hi Stephen,
I believe you are right.
This is the "Looking up parent groups for group" section, it only lasts about a second:
(Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [be_get_account_info] (4): Got request for [4097][1][name=u999999] (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30Name=u999999)(objectclass=user))][ou=Accounts,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (7): Adding original DN [CN=U999999,OU=Suncorp,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx] to attributes of [u999999]. (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (6): Storing info for user u999999 (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30Name=u999999)(objectclass=user))][ou=Accounts,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_initgr_rfc2307bis_send] (6): Looking up parent groups for user [CN=U999999,OU=xxxxxx,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:57 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=U999999,OU=Suncorp,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=xxxxt,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=xxxxt,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=xxxxp,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=xxxxp,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=xxxxdm,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=xxxxdm,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=xxxxlemr,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=xxxxlemr,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. <snip> (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=xxxxp,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=xxxxp,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
But then it goes into these loops where it fills the group memberships:
(Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=9167] (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(&(gidNumber=9167)(objectclass=group)(cn=*)(gidNumber=*))][ou=xxxxxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx]. (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null) (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_groups_process] (6): Search for groups, returned 1 results. (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Search users with filter: (&(objectclass=user)(originalDN=CN=A555555,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)) (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_nested_group_process_step] (6): Cached values are still valid. Skipping (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Search users with filter: (&(objectclass=user)(originalDN=CN=A666666,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)) (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_nested_group_process_step] (6): Cached values are still valid. Skipping (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Search users with filter: (&(objectclass=user)(originalDN=CN=A777777,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)) <snip user searches> (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Search users with filter: (&(objectclass=user)(originalDN=CN=U888888,OU=Users,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)) (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_nested_group_process_step] (6): Cached values are still valid. Skipping (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_group] (7): Adding original DN [CN=xxxxp,OU=xxxxxx,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx] to attributes of [iswap]. (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_group] (6): Storing info for group xxxxp (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (7): Adding member users to group [xxxxp] (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_fill_memberships] (7): member #0 (CN=A555555,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx): [name=a345314,cn=users,cn=INT.CORP.SUN,cn=sysdb] (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_fill_memberships] (7): member #1 (CN=A666666,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx): [name=a343849,cn=users,cn=INT.CORP.SUN,cn=sysdb] (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_fill_memberships] (7): member #2 (CN=A777777,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx): [name=a344654,cn=users,cn=INT.CORP.SUN,cn=sysdb] <snip fill members> (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
And there are many of these loops and they go on for about 30 seconds:
(Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:22:58 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxange (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxlemr (Mon Sep 26 09:22:59 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:00 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:00 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:00 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:00 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:00 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:01 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:01 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:01 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:01 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:02 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:02 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:02 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:04 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:04 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:04 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:05 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:05 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:05 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:05 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:05 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxb2 (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx002 (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:06 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:07 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:08 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx001 (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:09 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:10 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:11 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:12 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:12 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:12 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:16 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:17 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:18 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxra (Mon Sep 26 09:23:19 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxu (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:20 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxu (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group rmbad (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxi (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:21 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx002 (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxt (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxx003 (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:22 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxdef (Mon Sep 26 09:23:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:23 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxp (Mon Sep 26 09:23:24 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd (Mon Sep 26 09:23:25 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_grpmem] (6): Storing members for group xxxxd
Do you think version 1.6.2 will speed up this part of the process?
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.
On Mon, 2011-09-26 at 10:10 +1000, GOLLSCHEWSKY, Tim wrote:
Hi Stephen,
I believe you are right.
This is the "Looking up parent groups for group" section, it only lasts about a second:
<snip>
Do you think version 1.6.2 will speed up this part of the process?
While working on an unrelated enhancement this weekend, I think I stumbled across the source of this issue. We're doing too many writes to the disk due to poorly thought-out transaction logic.
I opened bug https://fedorahosted.org/sssd/ticket/1006 to track the issue. I'm not sure yet whether this will be fixed in 1.6.2 or if it will be pushed to a later release. It will be discussed at a triage meeting later this week.
On Fri, 2011-09-23 at 10:02 +1000, GOLLSCHEWSKY, Tim wrote:
Hi all.
I work in an organisation with a relatively large LDAP (active) directory.
When we ssh into a server running SSSD it seems to enumerate all the groups in the "ldap_group_search_base" which takes a very long time. Sometimes it can take up to 30 seconds for the Password: prompt to appear to the ssh client, which feels like ages when you are logging into Linux machines all day.
I've been running debug on the sssd process and I can see it searching and populating all the groups when a person tries to log in. It calls "ldap_search_ext" over and over again until all the groups (and users inside those groups) have been discovered. Once it's done this and has all the info in the cache, logging back in again is quick. But if I don't login for a day or so and try to login again, it downloads all the group information once again and I have the 30 second wait.
Can you please tell what version of SSSD you are using ? We noticed a few issues with the initgroups code in older version and have fixes that should increase performance of initgroups by avoiding many of the lookups you see.
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?
Yes, but see above.
http://docs.redhat.com/docs/en-US/Red_Hat_Enterprise_Linux/6/html/Deployment...
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.
Groups need to be set at login time in the shell as they are inherited by all your processes. So we cannot delay a full group resolution, but we can improve its speed.
access_provider = ldap ldap_access_filter = memberOf=cn=jbsrd,ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx
I'm just wondering if anybody else is using sssd in a large company or university with a large LDAP directory and wondered how they got around this issue.
Yes, we've seen this problem and we think we addressed the slowest paths recently.
Please provide what version you are using so we can tell you if improvements are available.
Simo.
Hi Simo, thanks for your assistance.
Can you please tell what version of SSSD you are using ? We noticed a few issues with the initgroups code in older version and have fixes that should increase performance of initgroups by avoiding ma
ny of the lookups you see.
I'm running the latest RHEL6: sssd-1.5.1-34.el6_1.3.x86_64
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?
Yes, but see above.
http://docs.redhat.com/docs/en-US/Red_Hat_Enterprise_Linux/6/html/Depl oyment_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.
Groups need to be set at login time in the shell as they are inherited by all your processes. So we cannot delay a full group resolution, but
we can improve its speed.
I see, that makes sense.
access_provider = ldap ldap_access_filter = memberOf=cn=jbsrd,ou=xxx,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx
I'm just wondering if anybody else is using sssd in a large company or university with a large LDAP directory and wondered how they got around this issue.
Yes, we've seen this problem and we think we addressed the slowest paths recently.
Please provide what version you are using so we can tell you if improvements are available.
I'm using the latest RHEL6 package. Should I try compiling v1.6.1 from source?
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.
On 09/22/2011 10:16 PM, GOLLSCHEWSKY, Tim wrote:
I'm using the latest RHEL6 package. Should I try compiling v1.6.1 from source?
If you do not mind trying yes please.
On 09/22/2011 10:16 PM, GOLLSCHEWSKY, Tim wrote:
I'm using the latest RHEL6 package. Should I try compiling v1.6.1 from source?
If you do not mind trying yes please.
I have compiled 1.6.1 OK but I seem to be having trouble with the SASL bind:
(Fri Sep 23 14:55:47 2011) [[sssd[ldap_child[28025]]]] [ldap_child_get_tgt_sync] (4): Principal name is: [host/hostname.fq.dn@XXX.XXX.XXX] (Fri Sep 23 14:55:48 2011) [sssd[be[XXX.XXX.XXX]]] [sasl_bind_send] (4): Executing sasl bind mech: gssapi, user: host/hostname.fq.dn@XXX.XXX.XXX (Fri Sep 23 14:55:48 2011) [sssd[be[XXX.XXX.XXX]]] [sasl_bind_send] (1): ldap_sasl_bind failed (-2)[Local error] (Fri Sep 23 14:55:48 2011) [sssd[be[XXX.XXX.XXX]]] [child_sig_handler] (4): child [28025] finished successfully. (Fri Sep 23 14:55:48 2011) [sssd[be[XXX.XXX.XXX]]] [fo_set_port_status] (4): Marking port 389 of server 'ldapserver.fq.dn' as 'not working'
In /var/log/messages I get:
Sep 23 15:00:40 hostname sssd_be: GSSAPI Error: An invalid name was supplied (Unknown error)
I'm using the same principle name though that I was before:
host/hostname.fq.dn@XXX.XXX.XXX
Any idea what I'm doing wrong?
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.
sssd-devel@lists.fedorahosted.org
-
Dmitri Pal -
GOLLSCHEWSKY, Tim -
Jakub Hrozek -
John Hodrien -
Simo Sorce -
Stephen Gallagher