[SSSD] Announcing SSSD 1.5.14

GOLLSCHEWSKY, Tim Tim.GOLLSCHEWSKY at suncorp.com.au
Fri Oct 28 05:14:59 UTC 2011


Hi Jakub.

> > > > Note using this round-robin DNS name "myadserver" works with the RHEL6 "stock" sssd we are running (sssd-1.5.1-34.el6_1.3.x86_64).
> > > >
> > > > So this has been introduced somewhere between that version and v1.5.14.
> > > >
> > > > BTW I tried setting "ldap_sasl_canonicalize" to true and false btw.  It didn't make any difference.
> > > >
> > > > Can I no longer use a round-robin DNS name for my ldap server?
> > > >
> > >
> > > Tim, what openldap and glibc versions are you running?  I think getting the
> > > "don't canonicalize" scenario to work involved fixes to several components
> > > including glibc and openldap.
> >
> > This is on RHEL6, so I think these are the current versions:
> >
> >   # rpm -q glibc openldap
> >   glibc-2.12-1.25.el6_1.3.x86_64
> >   glibc-2.12-1.25.el6_1.3.i686
> >   openldap-2.4.23-15.el6_1.3.x86_64
> >
> > > Does merely swapping the sssd version with the same openldap and glibc versions help?
> >
> > I'm not sure what I should swap.  I'm running the latest openldap and glibc, I could try the RHEL6 beta packages.
>
> Sorry, I phrased that poorly. My original question was whether stock
> RHEL6.1 SSSD worked with the same configuration and same version of
> glibc and openldap where 1.5.14 failed.

To answer your question yes it does.  It works, it's just slow hence why I'm trying out 1.5.14 to see how much of an improvement the initgroups enhancement (trac ticket #1006) has made.

<snip>

> >   3)  Now that I can login, I find the system can't resolves uids and gids to usernames and groupnames.  e.g.
> >
> >     > ssh myhost999
> >     Password:
> >     Last login: Thu Oct 27 10:14:24 2011 from anotherhost.xxx.xxx.xxx
> >     id: cannot find name for user ID 9999999
> >     id: cannot find name for user ID 9999999
> >     $ id
> 2,9323,9324,9325,9326,9328,9329,9337,9338,9339,9340,9341 context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
> >     $ groups
> >     localgroup1 groups: cannot find name for group ID 902
> >     902 localgroup2 groups: cannot find name for group ID 2131
> >     2131 groups: cannot find name for group ID 2132
> >     2132 groups: cannot find name for group ID 2135
> >     2135 groups: cannot find name for group ID 2202
> >     2202 groups: cannot find name for group ID 2203
> >     ..etc
> >     ..etc
> >
>
> This is worrying. Can you paste more complete logs of the initgroups
> operation? Are all the groups LDAP/AD groups or are some of them local
> groups?

Certainly.

The ones you can see (localgroup1 localgroup2) are local groups (with sanitised names). All the ones with just id's are from LDAP (active directory).

Logs below....

So when I try and log in, this is where it does an ldap search to see what groups I'm in, this seems to work:

  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_initgr_rfc2307bis_send] (6): Looking up parent groups for user [CN=U999999,OU=MyOU,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=U999999,OU=MyOU,OU=Users,OU=Accounts,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*))][ou=GroupOU,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [objectClass]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [cn]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [userPassword]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [gidNumber]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [msSFU30PosixMember]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [nsUniqueId]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [modifyTimestamp]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [uSNChanged]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 7
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfd9e50], ldap[0xfac610]
  (Thu Oct 27 10:17:13 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfd9e50], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_parse_entry] (9): OriginalDN: [CN=group1,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfd9e50], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_parse_entry] (9): OriginalDN: [CN=group2,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfd9e50], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_parse_entry] (9): OriginalDN: [CN=group3,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfd9e50], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_parse_entry] (9): OriginalDN: [CN=group4,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx].


Then it looks up what groups my groups are members of, I assume this is to resolve "groups within groups" which is cool but we purposely flattened all our groups (in an attempt) to make unix -> LDAP authentication faster.  So all these queries return nothing.

On a side note:  If there's a way to turn off this "Looking up parent groups for group" processing I'd love to know how.  :)


  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [rfc2307bis_nested_groups_step] (6): Looking up parent groups for group [CN=group5,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(&(msSFU30PosixMember=CN=group5,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx)(objectclass=group)(cn=*))][ou=GroupOU,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [objectClass]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [cn]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [userPassword]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [gidNumber]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [msSFU30PosixMember]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [nsUniqueId]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [modifyTimestamp]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [uSNChanged]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 106
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0x14fe6e0], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0x14fe6e0], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (7): Total count [0]


Then it starts updating the cache I think (I'm winging it here):


  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_get_direct_parents] (8): searching sysdb with filter [(&(objectClass=group)(member=name=idzrd,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1586190
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1588660
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x1588660 "ltdb_timeout"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x1586190 "ltdb_callback"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_get_direct_parents] (7): idzrd is a member of 0 sysdb groups
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_get_direct_parents] (8): searching sysdb with filter [(&(objectClass=group)(member=name=pc4rd,cn=groups,cn=XXX.XXX.XXX,cn=sysdb))]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1587dc0
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1588660
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x1588660 "ltdb_timeout"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x1587dc0 "ltdb_callback"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_get_direct_parents] (7): pc4rd is a member of 0 sysdb groups
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 1)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 2)


...now below here it says "initgroups done".  But it then does more searches, I assume it's enumerating the groups now:


  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x157cee0 "ltdb_timeout"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x1501710 "ltdb_callback"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x1581f10 "ltdb_timeout"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x15b3780 "ltdb_callback"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 3)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 1)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 0)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_initgr_done] (9): Initgroups done
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_id_op_connect_step] (9): reusing cached connection
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_id_op_destroy] (9): releasing operation connection
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_id_op_done] (9): releasing operation connection
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[(nil)], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
  (Thu Oct 27 10:17:14 2011) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (0, 0, Success) from Data Provider
  (Thu Oct 27 10:17:14 2011) [sssd[nss]] [nss_cmd_initgroups_search] (4): Requesting info for [user6 at XXX.XXX.XXX]
  (Thu Oct 27 10:17:14 2011) [sssd[nss]] [nss_cmd_initgroups_search] (6): Initgroups for [user6 at XXX.XXX.XXX] completed
  (Thu Oct 27 10:17:14 2011) [sssd[nss]] [nss_cmd_getgrgid_search] (4): Requesting info for [9008 at XXX.XXX.XXX]
  (Thu Oct 27 10:17:14 2011) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [XXX.XXX.XXX][4098][1][idnumber=9008]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sbus_dispatch] (9): dbus conn: FA6BA0
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sbus_dispatch] (9): Dispatching.
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [be_get_account_info] (4): Got request for [4098][1][idnumber=9008]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_id_op_connect_step] (9): reusing cached connection
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(&(gidNumber=9008)(objectclass=group)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][ou=GroupOU,ou=Right Groups,ou=Groups,dc=xxx,dc=xxx,dc=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [objectClass]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [cn]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [userPassword]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [gidNumber]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [msSFU30PosixMember]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [nsUniqueId]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [modifyTimestamp]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (7): Requesting attrs: [uSNChanged]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 160
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfaa950], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_parse_entry] (9): OriginalDN: [CN=group6,OU=GroupOU,OU=Right Groups,OU=Groups,DC=xxx,DC=xxx,DC=xxx].
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_process_result] (8): Trace: sh[0xfabf20], connected[1], ops[0xfaa950], ldap[0xfac610]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_generic_done] (7): Total count [0]
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_get_groups_process] (6): Search for groups, returned 1 results.
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Search users with filter: (&(objectclass=user)(originalDN=CN=user1,OU=Admin Accounts,OU=Accounts,DC=xxx,DC=xxx,DC=xxx))
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x14fe540
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x14ff240
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x14ff240 "ltdb_timeout"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x14fe540 "ltdb_callback"
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Search groups with filter: (&(objectclass=group)(originalDN=CN=user1,OU=Admin Accounts,OU=Accounts,DC=xxx,DC=xxx,DC=xxx))
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x14fe540
  (Thu Oct 27 10:17:14 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xfd9210

...and then the users:

  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_users] (9): User 73 processed!
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (9): Save user
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (7): Adding original DN [CN=user3,OU=Admin Accounts,OU=Accounts,DC=xxx,DC=xxx,DC=xxx] to attributes of [a319064].
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (7): Adding original memberOf attributes to [a319064].
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (7): User principal is not available for [a319064].
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (9): Adding [adAccountExpires]=[9223372036854775807] to user attributes.
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (9): Adding [adUserAccountControl]=[512] to user attributes.
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (6): Storing info for user a319064
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 1)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x16fc1f0
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x16fc2a0
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x16fc2a0 "ltdb_timeout"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x16fc1f0 "ltdb_callback"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x16fc1f0
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x16fc2a0
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x16fc2a0 "ltdb_timeout"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x16fc1f0 "ltdb_callback"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 3)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1706170
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1706290
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x1706290 "ltdb_timeout"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x1706170 "ltdb_callback"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 3)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): start ldb transaction (nesting: 3)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1708ad0
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1708b80
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Destroying timer event 0x1708b80 "ltdb_timeout"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): tevent: Ending timer event 0x1708ad0 "ltdb_callback"
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 3)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 2)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [ldb] (9): commit ldb transaction (nesting: 1)
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_users] (9): User 74 processed!
  (Thu Oct 27 10:17:15 2011) [sssd[be[XXX.XXX.XXX]]] [sdap_save_user] (9): Save user


It does a lot of user processing here. Many many sdap_fill_memberships, so it's definately accessing LDAP OK and populating the cache.

If there are more logs that would be of use please let me know.

One thing that's also concerning is I get "no such file or directory" errors a lot in the debug output:


  [root at jbsrd999586 ~]# grep 'such file or dir' /tmp/tim | tail -40
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:44 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_users] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_groups] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
  (Thu Oct 27 10:17:45 2011) [sssd[be[XXX.XXX.XXX]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)

Not sure what this means though.

If I can provide any more logs (or more specific parts) please let me know.

Best regards,

Tim.

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



More information about the sssd-devel mailing list