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.htm...). 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@example.corp (Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x0400): Processing group PUB_R@example.corp (Thu Apr 16 15:51:08 2015) [sssd[be[unix.example.corp]]] [sdap_save_group] (0x4000): AD group [PUB_R@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@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@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@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@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@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@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