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(a)XXX.XXX.XXX]
(Thu Oct 27 10:17:14 2011) [sssd[nss]] [nss_cmd_initgroups_search] (6):
Initgroups for [user6(a)XXX.XXX.XXX] completed (Thu Oct 27 10:17:14 2011)
[sssd[nss]] [nss_cmd_getgrgid_search] (4): Requesting info for
[9008(a)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