[SSSD] Announcing SSSD 1.5.14

Jan Zelený jzeleny at redhat.com
Mon Oct 31 08:00:48 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=x
> xx,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.  :)


Try setting ldap_group_nesting_level=1


>   (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=Group
> OU,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:

Well, sort of. In order to speed up the operation, we only store partial 
information about groups at first, so we can return it ASAP. But right after 
that we need to complete this information (like all members of each group), 
that's what you see.

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

Frankly, I haven't noticed anything unusual in these logs. Perhaps someone 
else will.

One thought here:
could you install ldb-tools and try following?

ldbsearch -H /var/lib/sss/db/cache_<domain>.ldb | less

Look for a records of groups for which the groups command was unable to find 
names. Do these records have attribute called 'name'? If not, is the attribute 
'cn' set on the AD server for each group?

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

That's ok. It means that the particular user/group is not stored in the cache 
yet.


Jan
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 836 bytes
Desc: This is a digitally signed message part.
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20111031/434515e4/attachment.sig>


More information about the sssd-devel mailing list