Bug 47636 - Traceback with cross-school users after being removed from a school
Traceback with cross-school users after being removed from a school
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: S4 Connector
UCS 4.3
Other Linux
: P5 normal (vote)
: UCS 4.3-1-errata
Assigned To: Arvid Requate
Felix Botner
:
: 46470 (view as bug list)
Depends on: 25709 46682
Blocks: 46692 46971 47104
  Show dependency treegraph
 
Reported: 2018-08-23 12:06 CEST by Felix Botner
Modified: 2018-08-30 22:11 CEST (History)
10 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 5: Major Usability: Impairs usability in key scenarios
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 3: A User would likely not purchase the product
User Pain: 0.171
Enterprise Customer affected?:
School Customer affected?: Yes
ISV affected?:
Waiting Support: Yes
Flags outvoted (downgraded) after PO Review:
Ticket number: 2018031621000473
Bug group (optional):
Max CVSS v3 score:


Attachments
reproduce_bug47636.sh (2.30 KB, application/x-shellscript)
2018-08-28 20:24 CEST, Arvid Requate
Details
connector-s4.log of reproducer script at debug level 4 (945.82 KB, text/x-log)
2018-08-28 20:26 CEST, Arvid Requate
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Felix Botner univentionstaff 2018-08-23 12:06:01 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'}
Comment 1 Felix Botner univentionstaff 2018-08-23 12:18:53 CEST
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 !!
Comment 2 Felix Botner univentionstaff 2018-08-23 13:07:00 CEST
univention-s4-connector:

2c8943e0cf6cf42a5a135140223b8220b0b28921 
c7dfea793dbd5c5bc0253003f1e5c45fddf7ba1f

yaml: 

9c98dee3a2b6293b64aead14d5f03f134fa627dc
a5fbc844ecaeaa15d7ec920f5ad4045c7e2964e9
Comment 3 Arvid Requate univentionstaff 2018-08-27 18:41:35 CEST
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.
Comment 4 Arvid Requate univentionstaff 2018-08-27 18:43:28 CEST
Note: Bug 46470 was also listed in the "See Also" field of Bug 46682, which you cloned here.
Comment 5 Felix Botner univentionstaff 2018-08-28 11:34:40 CEST
(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 ...
Comment 6 Felix Botner univentionstaff 2018-08-28 13:13:04 CEST
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)
Comment 7 Arvid Requate univentionstaff 2018-08-28 20:24:45 CEST
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?
Comment 8 Arvid Requate univentionstaff 2018-08-28 20:26:46 CEST
Created attachment 9645 [details]
connector-s4.log of reproducer script at debug level 4
Comment 9 Arvid Requate univentionstaff 2018-08-28 21:36:28 CEST
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.
Comment 10 Arvid Requate univentionstaff 2018-08-28 21:43:51 CEST
d5be472d35 | update the new dn in group caches after rename
75603168f8 | Advisory
Comment 11 Felix Botner univentionstaff 2018-08-29 11:08:12 CEST
(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
Comment 12 Arvid Requate univentionstaff 2018-08-29 12:49:44 CEST
<http://errata.software-univention.de/ucs/4.3/224.html>
Comment 13 Arvid Requate univentionstaff 2018-08-30 22:11:20 CEST
*** Bug 46470 has been marked as a duplicate of this bug. ***