Hi there,
I thought I’d revive this thread since I’m more or less having the same issues as the
initial poster
(
https://lists.fedorahosted.org/pipermail/sssd-users/2015-February/002667....). I was not
able to test the patch supplied by Sumit, but I can provide some additional logging.
On Fri, Mar 06, 2015 at 03:16:52PM +0000, Aviolat Romain wrote:
> Hi Sumit,
>
> I tried your patch, it seems that it still fails to download always the same groups
as before.
>
> Here's the part where sysdb_set_entry_attr fails:
>
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_group] (0x0400):
Processing group my group1 at
ad.domain2.net
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_group] (0x0400):
Filtering AD group [my group1 at
ad.domain2.net].
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_process_ghost_members]
(0x0400): The group has 1 members
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_process_ghost_members]
(0x0400): Group has 1 members
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_group] (0x0400):
Storing info for group my group1 at
ad.domain2.net
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sysdb_set_entry_attr]
(0x0080): ldb_modify failed: [Attribute or value exists]
> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sysdb_set_entry_attr]
(0x0040): Error: 17 (File exists)
Can you set debug_level to 9? Then there should be a dump of the
attributes in the logs.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_connect_step]
(0x4000): reusing cached connection
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_connect_step]
(0x4000): reusing cached connection
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_groups_next_base]
(0x0400): Searching for groups with base [dc=example,dc=corp]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_print_server] (0x2000):
Searching 192.168.141.5
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x0400): calling ldap_search_ext with
[(&(objectSID=S-1-5-21-1848557837-2917031290-480500741-7748)(objectClass=group)(name=*))][dc=example,dc=corp].
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [objectClass]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [name]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [gidNumber]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [member]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [objectGUID]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [objectSID]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [whenChanged]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [uSNChanged]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x1000): Requesting attrs: [groupType]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_ext_step]
(0x2000): ldap_search_ext called, msgid = 161
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56ac750], connected[1], ops[(nil)], ldap[0x7f24f56c42d0]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: ldap_result found nothing!
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56e0be0], connected[1], ops[0x7f24f5776ce0], ldap[0x7f24f56e0830]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_ENTRY]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_entry] (0x1000):
OriginalDN: [CN=PUB_R,OU=Groups,DC=example,DC=corp].
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectClass]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [member]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [whenChanged]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [uSNChanged]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [name]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectGUID]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [objectSid]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_parse_range] (0x2000): No
sub-attributes for [groupType]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56e0be0], connected[1], ops[0x7f24f5776ce0], ldap[0x7f24f56e0830]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_REFERENCE]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56e0be0], connected[1], ops[0x7f24f5776ce0], ldap[0x7f24f56e0830]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_REFERENCE]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56e0be0], connected[1], ops[0x7f24f5776ce0], ldap[0x7f24f56e0830]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_REFERENCE]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f24f56e0be0], connected[1], ops[0x7f24f5776ce0], ldap[0x7f24f56e0830]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_message] (0x4000):
Message type: [LDAP_RES_SEARCH_RESULT]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_generic_op_finished]
(0x0400): Search result: Success(0), no errmsg set
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_groups_process]
(0x0400): Search for groups, returned 1 results.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_has_deref_support]
(0x0400): The server supports deref method ASQ
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_hash_group]
(0x4000): AD group has type flags 0x80000004.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_hash_group]
(0x0400): Filtering AD group.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_hash_group]
(0x4000): The group's gid was zero
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_hash_group]
(0x2000): Marking group as non-posix and setting GID=0!
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_hash_entry]
(0x4000): Inserting [CN=PUB_R,OU=Groups,DC=example,DC=corp] into hash table [groups]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_process_send]
(0x2000): About to process group [CN=PUB_R,OU=Groups,DC=example,DC=corp]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_search_users] (0x2000):
Search users with filter:
(&(objectclass=user)(originalDN=CN=Users_All,OU=Resources,OU=Groups,DC=example,DC=corp))
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7f24f579c230
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7f24f585b670
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer
event 0x7f24f579c230 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer
event 0x7f24f585b670 "ltdb_timeout"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer
event 0x7f24f579c230 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_search_users] (0x2000): No
such entry
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_search_groups] (0x2000):
Search groups with filter:
(&(objectclass=group)(originalDN=CN=Users_All,OU=Resources,OU=Groups,DC=example,DC=corp))
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7f24f5820910
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7f24f5767620
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer
event 0x7f24f5820910 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer
event 0x7f24f5767620 "ltdb_timeout"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer
event 0x7f24f5820910 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_split_members]
(0x4000): [CN=Users_All,OU=Resources,OU=Groups,DC=example,DC=corp] found in cache,
skipping
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_process_send]
(0x2000): Looking up 0/1 members of group [CN=PUB_R,OU=Groups,DC=example,DC=corp]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_recv]
(0x0400): 0 users found in the hash table
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_nested_group_recv]
(0x0400): 1 groups found in the hash table
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): start ldb
transaction (nesting: 0)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): start ldb
transaction (nesting: 1)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_get_primary_name] (0x0400):
Processing object PUB_R(a)example.corp
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0400):
Processing group PUB_R(a)example.corp
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x4000): AD
group [PUB_R(a)example.corp] has type flags 0x80000004.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0400):
Filtering AD group [PUB_R(a)example.corp].
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding original DN [CN=PUB_R,OU=Groups,DC=example,DC=corp] to attributes of
[PUB_R(a)example.corp].
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_attrs_add_ldap_attr]
(0x2000): Adding original mod-Timestamp [20130427135353.0Z] to attributes of
[PUB_R(a)example.corp].
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_ghost_members]
(0x0400): The group has 1 members
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_process_ghost_members]
(0x0400): Group has 1 members
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_attrs_get_aliases]
(0x2000): Domain is case-insensitive; will add lowercased aliases
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0400):
Storing info for group PUB_R(a)example.corp
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7f24f5741710
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7f24f5741840
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer
event 0x7f24f5741710 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer
event 0x7f24f5741840 "ltdb_timeout"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer
event 0x7f24f5741710 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): start ldb
transaction (nesting: 2)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7f24f5712a30
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7f24f5712af0
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer
event 0x7f24f5712a30 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_callback": 0x7f24f5714950
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Added timed event
"ltdb_timeout": 0x7f24f584cd20
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer
event 0x7f24f5712af0 "ltdb_timeout"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer
event 0x7f24f5712a30 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Running timer
event 0x7f24f5714950 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Destroying timer
event 0x7f24f584cd20 "ltdb_timeout"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): Ending timer
event 0x7f24f5714950 "ltdb_callback"
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): cancel ldb
transaction (nesting: 2)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_set_entry_attr] (0x0080):
ldb_modify failed: [Attribute or value exists]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_set_entry_attr] (0x0040):
Error: 17 (File exists)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_store_group] (0x1000):
sysdb_set_group_attr failed.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sysdb_store_group] (0x0400):
Error: 17 (File exists)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_store_group_with_gid]
(0x0040): Could not store group PUB_R(a)example.corp
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0080): Could
not store group with GID: [File exists]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0080):
Failed to save group [PUB_R(a)example.corp]: [File exists]
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_groups] (0x0040):
Failed to store group 0. Ignoring.
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): commit ldb
transaction (nesting: 1)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [ldb] (0x4000): commit ldb
transaction (nesting: 0)
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_destroy] (0x4000):
releasing operation connection
(Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_id_op_done] (0x4000):
releasing operation connection
>
>> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sysdb_store_group]
(0x0400): Error: 17 (File exists)
>> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]]
[sdap_store_group_with_gid] (0x0040): Could not store group my group1 at
ad.domain2.net
>> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_group]
(0x0080): Could not store group with GID: [File exists]
>> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_group]
(0x0080): Failed to save group [my group1 at
ad.domain2.net]: [File exists]
>> (Fri Mar 6 16:02:17 2015) [sssd[be[ipa.domain1.com]]] [sdap_save_groups]
(0x0040): Failed to store group 14. Ignoring.
>>
>> Every time it still tries to download the same groups.
>>
>> About the pam systemd thing, I don't have such option set in my sssd conf
file.
>
>This is not configured in sssd.conf. In a default Fedora installation
>you can find it in /etc/pam.d/password-auth. But if you do not see any
>pam_systemd(sshd:session) timeout messages in the journal or
>/var/log/secure you do not need to change anything here.
>
>bye,
>Sumit