Bug 43368 - Traceback after re-initializing the s4-connector
Traceback after re-initializing the s4-connector
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: S4 Connector
UCS 4.1
Other Linux
: P5 normal (vote)
: UCS 4.2-0-errata
Assigned To: Arvid Requate
Felix Botner
:
Depends on:
Blocks: 44289 44517
  Show dependency treegraph
 
Reported: 2017-01-18 16:03 CET by Christina Scheinig
Modified: 2017-05-02 17:15 CEST (History)
3 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 4: Minor Usability: Impairs usability in secondary scenarios
Who will be affected by this bug?: 1: Will affect a very few installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.046
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:
requate: Patch_Available+


Attachments
s4-connector.log (1.55 MB, text/x-log)
2017-01-19 09:48 CET, Christina Scheinig
Details
pickle file (1.11 KB, text/plain)
2017-02-10 16:55 CET, Florian Best
Details
reject file (1.11 KB, text/plain)
2017-02-28 13:08 CET, Roman
Details
bug43368.patch (2.09 KB, patch)
2017-03-02 14:40 CET, Arvid Requate
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Christina Scheinig univentionstaff 2017-01-18 16:03:14 CET
In my test environment I happened to reinitialized the s4-connector and as a result I came across the following traceback in my s4-connector.log

-------------------------------------------------------------------------------
11.11.2016 08:25:24,389 LDAP        (PROCESS): sync from ucs:   Resync rejected file: /var/lib/univention-connector/s4/1478847638.880242
11.11.2016 08:25:24,394 LDAP        (PROCESS): sync from ucs: [         group] [       add] cn=Printer-Admins,cn=groups,DC=acheron,DC=mail
11.11.2016 08:25:24,481 LDAP        (WARNING): sync failed, saved as rejected
        /var/lib/univention-connector/s4/1478847638.880242
11.11.2016 08:25:24,482 LDAP        (WARNING): Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 843, 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 2414, in sync_from_ucs
    objectSid = decode_sid(objectSid_attr_value)
  File "/usr/lib/pymodules/python2.7/univention/s4connector/s4/__init__.py", line 517, in decode_sid
    sid += "%d" % ord(value[0])
TypeError: 'NoneType' object has no attribute '__getitem__'

11.11.2016 08:25:24,483 LDAP        (PROCESS): sync to ucs: Resync rejected dn: CN=Print Operators,CN=Builtin,DC=acheron,DC=mail
11.11.2016 08:25:24,492 LDAP        (PROCESS): sync to ucs:   [         group] [    modify] cn=Printer-Admins,cn=groups,dc=acheron,dc=mail
11.11.2016 08:25:24,493 LDAP        (PROCESS): Unable to sync cn=Printer-Admins,cn=groups,dc=acheron,dc=mail (UUID: 150065a0-3ab0-1036-889b-9dfaca459e67). The object is currently locked.

-----------------------------------------------------------------------------
I could reproduce it in an other test environment.
Both environments have in common, that the cups-printserver is installed.

According to the mapping.py 
 [..]
 mapping_table = {

                        'cn': [
                                (u'Printer-Admins', u'Print Operators'),
                                ]

                        },
[..]

I found 
--------------------------------------------------------------------------------
# univention-s4search cn='Print Operators'
# record 1
dn: CN=Print Operators,CN=Builtin,DC=acheron,DC=mail
objectClass: top
objectClass: group
cn: Print Operators
description: Members can administer domain printers
instanceType: 4
whenCreated: 20161109200716.0Z
uSNCreated: 3569
name: Print Operators
objectGUID: a3da13c3-9696-40e8-8cfa-5a40badc1e85
objectSid: S-1-5-32-550
adminCount: 1
sAMAccountType: 536870912
systemFlags: -1946157056
groupType: -2147483643
objectCategory: CN=Group,CN=Schema,CN=Configuration,DC=acheron,DC=mail
isCriticalSystemObject: TRUE
sAMAccountName: Printer-Admins
whenChanged: 20161109201040.0Z
uSNChanged: 3735
distinguishedName: CN=Print Operators,CN=Builtin,DC=acheron,DC=mail
--------------------------------------------------------------------------------
and
--------------------------------------------------------------------------------
# Printer-Admins, groups, acheron.mail
dn: cn=Printer-Admins,cn=groups,dc=acheron,dc=mail
objectClass: top
objectClass: posixGroup
objectClass: univentionGroup
objectClass: sambaGroupMapping
objectClass: univentionObject
univentionObjectType: groups/group
univentionGroupType: -2147483643
cn: Printer-Admins
sambaSID: S-1-5-32-550
sambaGroupType: 5
gidNumber: 5016
description: Members can administer domain printers
--------------------------------------------------------------------------------
Comment 1 Florian Best univentionstaff 2017-01-18 17:10:32 CET
Can you also attach /var/lib/univention-connector/s4/1478847638.880242 ?
Comment 2 Christina Scheinig univentionstaff 2017-01-19 09:48:53 CET
Created attachment 8356 [details]
s4-connector.log
Comment 3 Florian Best univentionstaff 2017-02-10 16:55:34 CET
Created attachment 8421 [details]
pickle file

I have the same problem on UCS 4.2 - the connector log is full of tracebacks.
Comment 4 Roman 2017-02-28 13:08:50 CET
Created attachment 8474 [details]
reject file

s4 rejects
Comment 5 Roman 2017-02-28 13:10:31 CET
I attached file if that helps, I also have a lot of "Printer operators" however I do not have a file for that in /var/lib/univention-connector/s4

    1:    S4 DN: CN=Print Operators,CN=Builtin,DC=domain,DC=com
         UCS DN: <not found>
Comment 6 Arvid Requate univentionstaff 2017-03-02 14:38:32 CET
The S4 mapping for 'group' uses

dn_mapping_function=[ univention.s4connector.s4.group_dn_mapping ]

and this calls samaccountname_dn_mapping, which correctly applies the mapping_table in this case to construct the search filter:

(INFO   ): samaccount_dn_mapping: search in s4 for
           (&(objectclass=group)(samaccountname=Print Operators))


The problem is, that in this special case, the objects sAMAccountName has been created without considering the mapping function:

=========================================================================
root@ucs-5140:~# univention-s4search '(cn=Print Operators)'
# record 1
dn: CN=Print Operators,CN=Builtin,DC=acheron,DC=mail
objectClass: group
cn: Print Operators
sAMAccountName: Printer-Admins
=========================================================================

This special behavior only causes a traceback now due to the new code added for Bug 41864 / Bug 42120.

While this might actually be good for identity mapping (e.g. Bug 26693), the S4-Connector should consider this special case too.
Comment 7 Arvid Requate univentionstaff 2017-03-02 14:40:06 CET
Created attachment 8486 [details]
bug43368.patch

Handle the special case of UCS cn="Printer-Admins":

* Add special case to univention.s4connector.s4.group_dn_mapping
* Fix fetching the SID in sync_rom_ucs ALREADY_EXISTS handling
  (code introduced via Bug 41864 / Bug 42120)
Comment 8 Florian Best univentionstaff 2017-03-02 15:18:22 CET
(In reply to Arvid Requate from comment #7)
> Created attachment 8486 [details]
> bug43368.patch
> 
> Handle the special case of UCS cn="Printer-Admins":
> 
> * Add special case to univention.s4connector.s4.group_dn_mapping
> * Fix fetching the SID in sync_rom_ucs ALREADY_EXISTS handling
>   (code introduced via Bug 41864 / Bug 42120)

The patch is missing correct escaping of the LDAP filter.
Comment 9 Arvid Requate univentionstaff 2017-04-13 11:55:13 CEST
Fixed for UCS 4.2 along with Bug #44276. Advisory updated. I'll clone the Bug again for errata4.1-4
Comment 10 Felix Botner univentionstaff 2017-04-13 14:04:59 CEST
please remove 
modules/univention/s4connector/s4/__init__.py       (Revision 78780)
@@ -322,6 +322,8 @@

+                                               if ucsval == "Printer-Admins":
+                                                       continue

This breaks the sync of this group if a mapping_table entry exists for this group.

13.04.2017 14:46:25,927 LDAP        (PROCESS): sync from ucs:   Resync rejected file: /var/lib/univention-connector/s4/1492081790.892809
13.04.2017 14:46:25,929 LDAP        (INFO   ): _ignore_object: Do not ignore cn=Printer-Admins,cn=groups,dc=w2k12,dc=test
...
13.04.2017 14:46:25,931 LDAP        (INFO   ): samaccount_dn_mapping: check newdn for key dn:
13.04.2017 14:46:25,931 LDAP        (INFO   ): samaccount_dn_mapping: not premapped (in first instance)
13.04.2017 14:46:25,932 LDAP        (INFO   ): samaccount_dn_mapping: got an UCS-Object
13.04.2017 14:46:25,932 LDAP        (INFO   ): samaccount_dn_mapping: search in s4 for (&(objectclass=group)(samaccountname=Printer-Admins))
13.04.2017 14:46:25,932 LDAP        (INFO   ): samaccount_dn_mapping: newdn: cn=Printer-Admins,cn=groups,dc=w2k12,dc=test
13.04.2017 14:46:25,933 LDAP        (INFO   ): samaccount_dn_mapping: newdn for key dn:
13.04.2017 14:46:25,933 LDAP        (INFO   ): samaccount_dn_mapping: olddn: cn=Printer-Admins,cn=groups,dc=w2k12,dc=test
...
13.04.2017 14:46:25,935 LDAP        (INFO   ): sync_from_ucs: sync object: cn=Printer-Admins,cn=groups,DC=w2k12,DC=test
13.04.2017 14:46:25,936 LDAP        (PROCESS): sync from ucs: [         group] [       add] cn=Printer-Admins,cn=groups,DC=w2k12,DC=test
13.04.2017 14:46:25,936 LDAP        (INFO   ): sync_from_ucs: add object: cn=Printer-Admins,cn=groups,DC=w2k12,DC=test
13.04.2017 14:46:25,937 LDAP        (INFO   ): sync_from_ucs: lock UCS entryUUID: c12beafe-2c86-1035-80f1-4d2f8263a280
13.04.2017 14:46:25,937 LDAP        (INFO   ): LockingDB: Execute SQL command: 'INSERT INTO UCS_LOCK(uuid) VALUES(?);', '('c12beafe-2c86-1035-80f1-4d2f8263a280',)'
13.04.2017 14:46:25,943 LDAP        (INFO   ): groupType: -2147483643
13.04.2017 14:46:25,943 LDAP        (INFO   ): sambaSID: S-1-5-32-550
13.04.2017 14:46:25,943 LDAP        (INFO   ): to add: cn=Printer-Admins,cn=groups,DC=w2k12,DC=test
13.04.2017 14:46:25,947 LDAP        (PROCESS): sync_from_ucs: error during add, searching for conflicting deleted object in S4
13.04.2017 14:46:25,947 LDAP        (INFO   ): sync_from_ucs: search filter: (&(sAMAccountName=Opérateurs d’impression)(objectSid=S-1-5-32-550)(isDeleted=TRUE))
13.04.2017 14:46:25,948 LDAP        (PROCESS): sync_from_ucs: no conflicting deleted object found
13.04.2017 14:46:25,953 LDAP        (WARNING): sync failed, saved as rejected
        /var/lib/univention-connector/s4/1492081790.892809
13.04.2017 14:46:25,954 LDAP        (WARNING): Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.7/univention/s4connector/__init__.py", line 843, 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 2516, in sync_from_ucs
    self.lo_s4.lo.add_ext_s(compatible_modstring(object['dn']), compatible_addlist(addlist), serverctrls=ctrls)  # FIXME encoding
  File "/usr/lib/python2.7/dist-packages/ldap/ldapobject.py", line 187, in add_ext_s
    resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.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)
ALREADY_EXISTS: {'info': "00002071: samldb: samAccountName 'Op\\C3\\A9rateurs\\20d\\E2\\80\\99impression' already in use!", 'desc': 'Already exists'}
Comment 11 Arvid Requate univentionstaff 2017-04-13 14:47:37 CEST
I've adjusted the filter. See also Bug 42675#c1.
Comment 12 Felix Botner univentionstaff 2017-04-13 15:17:45 CEST
OK - re-initializing s4connector works, even with

dn: CN=Print Operators,CN=Builtin,DC=four,DC=two
cn: Print Operators
sAMAccountName: Printer-Admins

in samba
Comment 13 Janek Walkenhorst univentionstaff 2017-04-19 13:17:31 CEST
<http://errata.software-univention.de/ucs/4.2/2.html>