Univention Bugzilla – Bug 47636
Traceback with cross-school users after being removed from a school
Last modified: 2018-08-30 22:11:20 CEST
+++ This bug was initially created as a clone of Bug #46682 +++ A school customer could now observe several times that the S4-Connector reproducibly throws tracebacks. It occurs in the following scenario: A teacher is *only* at school1 and is temporarily set up as a cross-school user account for school "school1" and "school2". For this purpose, "school1" and "school2" are correctly entered in the user's LDAP attribute "ucsschoolSchool" and the user is additionally included in the groups "lehrer-school2" and "domain users school2". The teacher is then correctly replicated to the school2 slave and transferred to the AD via the S4 connector. 2 days later the user was removed from "school2" and the corresponding groups "lehrer-school2" and "domain users school2". This is said to have worked and the user has been correctly removed from LDAP and AD from the groups and the user object itself. During the night the group "Domain Users school1" was modified. Since all groups "Domain User $SCHOOL" and "lehrer-$SCHOOL" are replicated to all schools, this change also arrived at the school DC dcschool2. The S4 connector has thrown the following traceback: 22.02.2018 07:15:16,924 LDAP (WARNING): group_members_sync_from_ucs: failed to sync members: (cn=domain users school1,cn=groups,ou=school1,DC=schule,DC=customer,DC=de,[(2, 'member', ['cn=someteacher,cn=lehrer,cn=users,ou=school1,dc=schule,dc=customer,dc=de'])]) 22.02.2018 07:15:16,930 LDAP (WARNING): sync failed, saved as rejected /var/lib/univention-connector/s4/1519280106.726590 22.02.2018 07:15:16,967 LDAP (WARNING): Traceback (most recent call last): File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 897, in __sync_file_from_ucs if ((old_dn and not self.sync_from_ucs(key, object, premapped_ucs_dn, unicode(old_dn, 'utf8'), old, new)) or (not old_dn and not self.sync_from_ucs(key, object, premapped_ucs_dn, old_dn, old, new))): File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/__init__.py", line 2720, in sync_from_ucs f(self, property_type, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/__init__.py", line 79, in group_members_sync_from_ucs return s4connector.group_members_sync_from_ucs(key, object) File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/__init__.py", line 1812, in group_members_sync_from_ucs self.lo_s4.lo.modify_s(compatible_modstring(object['dn']), [(ldap.MOD_REPLACE, 'member', modlist_members)]) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 364, in modify_s return self.result(msgid,all=1,timeout=self.timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 465, in result resp_type, resp_data, resp_msgid = self.result2(msgid,all,timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 469, in result2 resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all,timeout) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 476, in result3 resp_ctrl_classes=resp_ctrl_classes File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 483, in result4 ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop) File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 106, in _ldap_call result = func(*args,**kwargs) NO_SUCH_OBJECT: {'info': '00002030: Unable to find GUID for DN cn=someteacher,cn=lehrer,cn=users,ou=school1,dc=schule,dc=customer,dc=de\n', 'desc': 'No such object'}
The original patch removes the dn from the group cache only for the add or rename modtype. But there is also the case, that the connector gets a modify but then renames the object, at this point the old dn has to be removed from the group cache too user add uid=test1,ou=AAA,dc=test user modify uid=test1,ou=BBB,dc=test -> test1 has been renamed at this point group_members_sync_from_ucs: Traceback NO_SUCH_OBJECT: {'info': '00002030: Unable to find GUID for DN uid=test1... (1) del old dn from groupcache in sync_from_ucs (2) use ud.PROCESS for move debug message in sync_from_ucs !!
univention-s4-connector: 2c8943e0cf6cf42a5a135140223b8220b0b28921 c7dfea793dbd5c5bc0253003f1e5c45fddf7ba1f yaml: 9c98dee3a2b6293b64aead14d5f03f134fa627dc a5fbc844ecaeaa15d7ec920f5ad4045c7e2964e9
You adjusted the code to statically log 'move' as action and you duplicated the cache invalidation code. Instead I think you could just apply the patch attached to Bug 46470 Comment 7, which fixes the object['modtype'] in ucs.__sync_file_from_ucs before calling s4.sync_from_ucs. Then we also would have both bugs fixed.
Note: Bug 46470 was also listed in the "See Also" field of Bug 46682, which you cloned here.
(In reply to Arvid Requate from comment #3) > You adjusted the code to statically log 'move' as action > and you duplicated a slight difference is that we don't want to delete the dn here, but the old_dn > the cache invalidation code. Instead I think you could just apply the patch > attached to Bug 46470 Comment 7, which fixes the object['modtype'] in > ucs.__sync_file_from_ucs before calling s4.sync_from_ucs. Then we also would > have both bugs fixed. At the moment sync_from_ucs decides if the operation is a move (looks for old_dn and renames the object if existing). And i think this is the correct way to go. How can we be sure this is a move without this search operation? We could set object['modtype'] = modify in sync_from_ucs after the rename and use the "univention/s4connector/s4/__init__.py" part of the patch to get rid of some code? so in doubt reopen and revert ...
as discussed * set object['modtype'] = move after rename * removed "move" log (move is now logged with corrected modtype) * added _remove_dn_from_group_cache(), called after rename and delete * modified if statements for add and modify (as in the 46470 patch)
Created attachment 9644 [details] reproduce_bug47636.sh The attached script reproduced the Bug on a standard UCS 4.3-1 Samba/AD DC Master, but I had to work on the timing (no sleep between create and move) to trigger it. After updating the package the behavior seems to have improved, becasue it doesn't trigger for the first create/move of a user. But the script still triggers the issue again when I repeat the create/move with a new user: root@master10:~# ./reproduce_bug47636.sh Setting connector/debug/level [ ok ] Restarting univention-s4-connector (via systemctl): univention-s4-connector.service. Object created: uid=user2011,cn=groups,dc=ar41i1,dc=qa Object modified: uid=user2011,cn=groups,dc=ar41i1,dc=qa Object created: uid=user2012,cn=users,dc=ar41i1,dc=qa Sleeping a bit And trying it again wth two new users Object created: uid=user2013,cn=groups,dc=ar41i1,dc=qa Object modified: uid=user2013,cn=groups,dc=ar41i1,dc=qa Object created: uid=user2014,cn=users,dc=ar41i1,dc=qa ERROR: Rejects for cn=Domain Users after moving user2013 I'll attach the connector-s4.log. Code review: Ok Advisory: Ok I think we should release the updated package but clone the bug to fix the actual issue? I'm not sure, what do you think?
Created attachment 9645 [details] connector-s4.log of reproducer script at debug level 4
Summary of the move as found in connector-s4.log plus some additional info from my debugging session: ============================================================================ 21.08.2018 ... LDAP (INFO ): sync_from_ucs: MORE DEBUG: Removing CN=user2013,cn=groups,DC=ar41i1,DC=qa from S4 group member mapping cache ## But the key is not in the cache 21.08.2018 ... LDAP (INFO ): sync_from_ucs: MORE DEBUG: Removing uid=user2013,cn=groups,dc=ar41i1,dc=qa from UCS group member mapping cache ## But the key is not in the cache 21.08.2018 18:29:11,553 LDAP (PROCESS): sync from ucs: [ user] [ move] CN=user2013,cn=users,DC=ar41i1,DC=qa [...] 21.08.2018 18:29:11,606 LDAP (PROCESS): sync from ucs: [ user] [ modify] cn=user2013,cn=users,DC=ar41i1,DC=qa [...] 21.08.2018 18:29:11,642 LDAP (PROCESS): sync from ucs: [ group] [ modify] cn=domain users,cn=groups,DC=ar41i1,DC=qa [...] 21.08.2018 18:29:11,645 LDAP (INFO ): Call post_con_modify_functions: <function group_members_sync_from_ucs at 0x7f76bb0fe320> [...] 21.08.2018 18:29:11,650 LDAP (INFO ): group_members_sync_from_ucs: s4_members set([u'CN=Administrator,CN=Users,DC=ar41i1,DC=qa', u'CN=user2013,CN=Users,DC=ar41i1,DC=qa', u'CN=user2012,CN=Users,DC=ar41i1,DC=qa', u'CN=user2011,CN=Users,DC=ar41i1,DC=qa']) [...] 21.08.2018 18:29:11,650 LDAP (INFO ): Found uid=user2013,cn=users,dc=ar41i1,dc=qa in UCS group member cache: MORE DEBUG SHOWS: CN=user2013,CN=Groups,DC=ar41i1,DC=qa 21.08.2018 18:29:11,650 LDAP (INFO ): __group_cache_ucs_append_member: Append user uid=user2013,cn=users,dc=ar41i1,dc=qa to UCS group member cache of cn=domain users,cn=groups,dc=ar41i1,dc=qa [...] 21.08.2018 18:29:11,655 LDAP (INFO ): group_members_sync_from_ucs: UCS-members in s4_members_from_ucs set([u'cn=administrator,cn=users,dc=ar41i1,dc=qa', u'cn=user2013,cn=groups,dc=ar41i1,dc=qa', u'cn=user2011,cn=users,dc=ar41i1,dc=qa', u'cn=user2012,cn=users,dc=ar41i1,dc=qa']) 21.08.2018 18:29:11,655 LDAP (INFO ): group_members_sync_from_ucs: UCS-and S4-members in s4_members_from_ucs set([u'cn=administrator,cn=users,dc=ar41i1,dc=qa', u'cn=user2013,cn=groups,dc=ar41i1,dc=qa', u'cn=user2011,cn=users,dc=ar41i1,dc=qa', u'cn=user2012,cn=users,dc=ar41i1,dc=qa']) ============================================================================ So, the point is here that -- maybe due to some timing issue -- after the move, the *new* UCS DN is found in the UCS group mapping cache but it points to the *old* S4 DN. I'll commit a patch and switch assignee and QA.
d5be472d35 | update the new dn in group caches after rename 75603168f8 | Advisory
(In reply to Arvid Requate from comment #10) > d5be472d35 | update the new dn in group caches after rename > 75603168f8 | Advisory > So, the point is here that -- maybe due to some timing issue -- after the move, > the *new* UCS DN is found in the UCS group mapping cache but it points to the > *old* S4 DN. I'll commit a patch and switch assignee and QA. good point, what happend is * user create DN1 * user move DN2 , group membership is updated * only now the connector is triggerd * add for DN1 * updates group cache by looking for members of group, the DN is already updated on the group so now the connector builds the cache with the new DN2 -> DN1 so it is correct to remove the old DN from the cache AND to update the value for the new DN (DN2 -> DN2) (because the new DN may point to the old DN) OK - univention-s4-connctor OK - yaml
<http://errata.software-univention.de/ucs/4.3/224.html>
*** Bug 46470 has been marked as a duplicate of this bug. ***