SSO login and username case sensitivity

[GOLLSCHEWSKY, Tim]

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.

[Jakub Hrozek]

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

[GOLLSCHEWSKY, Tim]

> 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.

slow logins via ssh

[GOLLSCHEWSKY, Tim]

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.

slow logins via ssh

[Dmitri Pal]

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
> [e-mail]
> https://fedorahosted.org/mailman/listinfo/sssd-devel

slow logins via ssh

[Simo Sorce]

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.

slow logins via ssh

[GOLLSCHEWSKY, Tim]

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.

slow logins via ssh

[GOLLSCHEWSKY, Tim]

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.

slow logins via ssh

[Dmitri Pal]

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.

slow logins via ssh

[GOLLSCHEWSKY, Tim]

> 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/[e-mail]]
  (Fri Sep 23 14:55:48 2011) [sssd[be[XXX.XXX.XXX]]] [sasl_bind_send] (4): Executing sasl bind mech: gssapi, user: host/[e-mail]
  (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/[e-mail]

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.

slow logins via ssh

[Stephen Gallagher]

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.

slow logins via ssh

[John Hodrien]

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

slow logins via ssh

[GOLLSCHEWSKY, Tim]

> > 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.

slow logins via ssh

[GOLLSCHEWSKY, Tim]

> 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.

slow logins via ssh

[Stephen Gallagher]

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.