S4 connector sync issues 4.1-4

UCS - Univention Corporate Server
#1

Hi, have recently upgraded to 4.1-4 errata 366.

Noticed an issue after running “univention-s4connector-list-rejected” showing two windows computer accounts that would not sync from S4 to UCS due to a UID already existing traceback.

My (probably misguided) attempt to work around it was to delete the computer accounts in UCS UMC, and unjoin the computer from the samba domain to remove the AD entry, thinking that with entries removed from both sides, I could rejoin the computers after changing the name and start fresh.

Does not seem to have worked out that way.

Now having unjoined, changed the computer names and rejoined them, I’m getting “univention-s4connector-list-rejected” errors piling up in both directions with indicated for paths on each side S4->UCS and UCS->S4 for these new computer account objects.

Really not sure what to do to move forward from here.

Output of “univention-s4connector-list-rejected” shows entries piling up at about 4 a minute. Was over 114 when I left the office. Have just sanitised real domain name to “dc=replaceddomainname,dc=com”.

[code] root@dc1:/var/log/univention# univention-s4connector-list-rejected

UCS rejected

1:   UCS DN: cn=NAV,cn=computers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427853.705730

2:   UCS DN: cn=NAV,cn=computers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427853.732950

3:   UCS DN: cn=NAV,cn=Computers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427854.166414

4:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427875.569946

5:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427875.593706

6:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427875.992033

7:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427930.890286

8:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427931.351270

9:   UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
      S4 DN: <not found>
     Filename: /var/lib/univention-connector/s4/1483427943.966653

10: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483427944.408640

11: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428002.786916

12: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428003.138910

13: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428060.893638

14: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428061.334427

15: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428098.512087

16: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428098.930595

17: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428156.707879

18: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428157.178855

19: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428215.187057

20: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428215.620075

21: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428273.668240

22: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428274.093298

23: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428332.237704

24: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428332.603446

25: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428390.633473

26: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428391.060995

27: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428449.380103

28: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428449.882448

29: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428507.996386

30: UCS DN: cn=NAV,ou=Servers,dc=replaceddomainname,dc=com
S4 DN:
Filename: /var/lib/univention-connector/s4/1483428508.247584

<<<<<THIS IS OVER 114 entries now>>>>>>

S4 rejected

1:    S4 DN: CN=NAV,CN=Computers,dc=replaceddomainname,dc=com
     UCS DN: <not found>
2:    S4 DN: CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
     UCS DN: <not found>


    last synced USN: 99143

<<<<<<<<THIS STAYS AT 2 entries>>>>>>>>>>
[/code]

Extract from connector-s4.log showing “object is currently locked” messages and tracebacks:

[code]03.01.2017 17:50:54,308 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483429736.119085 [839/4854]
03.01.2017 17:50:54,316 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,319 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:54,324 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483429736.478003
03.01.2017 17:50:54,330 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,333 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:54,337 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483429795.506436
03.01.2017 17:50:54,345 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,347 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:54,352 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483429795.530687
03.01.2017 17:50:54,364 LDAP (PROCESS): sync from ucs: [windowscomputer] [ modify] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,367 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:54,373 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483429795.911385
03.01.2017 17:50:54,380 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,382 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:54,388 LDAP (PROCESS): sync to ucs: Resync rejected dn: CN=NAV,CN=Computers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,398 LDAP (PROCESS): sync to ucs: [windowscomputer] [ add] cn=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,685 LDAP (ERROR ): Unknown Exception during sync_to_ucs
03.01.2017 17:50:54,686 LDAP (ERROR ): Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1475, in sync_to_ucs
result = self.add_in_ucs(property_type, object, module, position)
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1262, in add_in_ucs
return ucs_object.create() and self.__modify_custom_attributes(property_type, object, ucs_object, module, position)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 305, in create
return self._create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 764, in _create
self._ldap_post_create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/computers/windows.py”, line 478, in _ldap_post_create
univention.admin.handlers.simpleComputer.update_groups(self)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 2454, in update_groups
groupObject.modify(ignore_license=1)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 316, in modify
return self._modify(modify_childs, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 810, in _modify
self.lo.modify(self.dn, ml, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/uldap.py”, line 403, in modify
raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg)
ldapError: Type or value exists: modify/add: memberUid: value #0 already exists

03.01.2017 17:50:54,687 LDAP (PROCESS): sync to ucs: Resync rejected dn: CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,698 LDAP (PROCESS): sync to ucs: [windowscomputer] [ add] cn=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:54,932 LDAP (ERROR ): Unknown Exception during sync_to_ucs
03.01.2017 17:50:54,933 LDAP (ERROR ): Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1475, in sync_to_ucs
result = self.add_in_ucs(property_type, object, module, position)
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1262, in add_in_ucs
return ucs_object.create() and self.__modify_custom_attributes(property_type, object, ucs_object, module, position)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 305, in create
return self._create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 764, in _create
self._ldap_post_create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/computers/windows.py”, line 478, in _ldap_post_create
univention.admin.handlers.simpleComputer.update_groups(self)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 2454, in update_groups
groupObject.modify(ignore_license=1)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 316, in modify
return self._modify(modify_childs, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 810, in _modify
self.lo.modify(self.dn, ml, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/uldap.py”, line 403, in modify
raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg)
ldapError: Type or value exists: modify/add: memberUid: value #0 already exists

03.01.2017 17:50:59,960 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:59,962 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:59,974 LDAP (PROCESS): sync from ucs: [windowscomputer] [ modify] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
03.01.2017 17:50:59,976 LDAP (PROCESS): Unable to sync CN=NAV,OU=Servers,dc=replaceddomainname,dc=com (GUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315). The object is currently locked.
03.01.2017 17:50:59,985 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=NAV,OU=Servers,dc=replaceddomainname,dc=com
[/code]

Any ideas on how to stop the S4-connector piling up the sync errors? What is causing the object currently locked message, and can I unlock it manually?

UCS-S4-Rejects nach GPO-Änderung
#2

Can you send the output of the following commands?

[code]# univention-ldapsearch cn=nav

univention-s4search cn=nav[/code]

#3

connector-s4-status.log as of an hour later.

root@dc1:/var/lib/univention-connector/s4# cat /var/log/univention/connector-s4-status.log
Tue Jan  3 19:36:49 2017
--------------------------------------
try to sync 338 changes from UCS
done: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338
Changes from UCS: 0 (338 saved rejected)
--------------------------------------
--------------------------------------
try to sync 0 changes from S4
done:
Changes from S4:  0 (3 saved rejected)
--------------------------------------
--------------------------------------
Sync 338 rejected changes from UCS

All seem to be retries for editing the same distinguished name paths over and over.

#4

Can you please check, if the following patch works for you? Since it is not an errata-Update, I would strongly advise to test this first in a testing-environment.

[code]# wget --no-check-certificate ‘https://forge.univention.org/bugzilla/attachment.cgi?id=8323’ -O hotfix_43247.patch

patch -p7 -d /usr/share/pyshared/univention/admin/handlers/ <hotfix_43247.patch

/etc/init.d/univention-s4-connector restart[/code]

#5

[quote=“Thorp-Hansen”]Can you send the output of the following commands?

[code]# univention-ldapsearch cn=nav

univention-s4search cn=nav[/code][/quote]

Hello Thorp-Hansen, please find output below. I’ve only replaced domain component names (but same structure) and RID in objectSID out of paranoia.

[code]root@dc1:/var/log/univention# univention-ldapsearch cn=nav

extended LDIF

LDAPv3

base <dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au> (default) with scope subtree

filter: cn=nav

requesting: ALL

search result

search: 3
result: 0 Success

numResponses: 1

[/code]

[code]root@dc1:/var/log/univention# univention-s4search cn=nav

record 1

dn: CN=NAV,OU=Servers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: user
objectClass: computer
CN: NAV
instanceType: 4
whenCreated: 20170103071727.0Z
uSNCreated: 99117
name: NAV
objectGUID: 21c8f2e0-d6be-4bd9-b3b6-5351ac3c5315
userAccountControl: 4096
codePage: 0
countryCode: 0
pwdLastSet: 131279014479257810
primaryGroupID: 515
objectSid: S-1-5-21-778516209-2063164296-1083526195-<>
accountExpires: 9223372036854775807
sAMAccountName: NAV$
sAMAccountType: 805306369
operatingSystem: Windows 7 Professional
operatingSystemVersion: 6.1 (7601)
operatingSystemServicePack: Service Pack 1
dNSHostName: NAV.sanitisedsubdomain.sanitiseddomain.com.au
objectCategory: CN=Computer,CN=Schema,CN=Configuration,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
isCriticalSystemObject: FALSE
lastLogonTimestamp: 131279014484416270
msDS-SupportedEncryptionTypes: 28
lastLogon: 131279015694952970
logonCount: 1
whenChanged: 20170103072133.0Z
uSNChanged: 99146
servicePrincipalName: HOST/NAV.sanitisedsubdomain.sanitiseddomain.com.au
servicePrincipalName: RestrictedKrbHost/NAV.sanitisedsubdomain.sanitiseddomain.com.au
servicePrincipalName: HOST/NAV
servicePrincipalName: RestrictedKrbHost/NAV
servicePrincipalName: TERMSRV/nav.sanitisedsubdomain.sanitiseddomain.com.au
servicePrincipalName: TERMSRV/NAV
servicePrincipalName: WSMAN/nav.sanitisedsubdomain.sanitiseddomain.com.au
servicePrincipalName: WSMAN/nav
distinguishedName: CN=NAV,OU=Servers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

Referral

ref: ldap://sanitisedsubdomain.sanitiseddomain.com.au/CN=Configuration,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

Referral

ref: ldap://sanitisedsubdomain.sanitiseddomain.com.au/DC=DomainDnsZones,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

Referral

ref: ldap://sanitisedsubdomain.sanitiseddomain.com.au/DC=ForestDnsZones,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

returned 4 records

1 entries

3 referrals

[/code]
This was after a join from the win7 client to the UCS DC, and then a move of the computer object into Servers OU using the RSAT on windows. Nothing shows up in the UCS LDAP.

Thanks again.

#6

[quote=“Thorp-Hansen”]Can you please check, if the following patch works for you? Since it is not an errata-Update, I would strongly advise to test this first in a testing-environment.

[code]# wget --no-check-certificate ‘https://forge.univention.org/bugzilla/attachment.cgi?id=8323’ -O hotfix_43247.patch

patch -p7 -d /usr/share/pyshared/univention/admin/handlers/ <hotfix_43247.patch

/etc/init.d/univention-s4-connector restart[/code][/quote]

OK, I’ll try taking a quick VM copy of the DC and apply this.

Should it unblock the outstanding sync errors? Or will I have to clear those some other way? I’m guessing they’re just repeated attempts to perform the same action rather than independent changes.

#7

you should not need to delete the rejects. You are right, in the “/var/log/univention/connectors4.log” you will most likely see “add”, “modify”, “delete”, “add”, “modify”, “delete”, till all rejects are gone.

#8

Hi, I have applied the patch to a VM copy of the DC. The rejects seem to have stopped increasing at 468, but they haven’t decreased.

The connector-s4.log is still showing attempts to add/update etc with the “The object is currently locked.” error in the previous output.

The connector-s4-status.log is also showing a traceback EOFError (hand-typed as I only have access to the VM console over noVNC)

[code]Tue Jan 3 21:21:08 2017
— connect failed, failure was: —

Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/s4connector/s4/main.py”, line 282, in main
connect()
File “/usr/lib/pymodules/python2.7/univention/s4connector/s4/main.py”, line 181, in connect
s4.initialize_ucs()
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 964, in initialize_ucs
self.poll_ucs()
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1044, in poll_ucs
dn, new, old, old_dn = cPickle.load(f)
EOFError

— retry in 30 seconds —
[/code]

I Placed the VM copy in a standalone network that has no gateway, but I assume if the LDAP or other services need to connect to the interface IP rather than the local loopback that should still work given a static IP and the interface is up?

S4CONNECTOR reject nach Domänenbeitritt von Windows10Client
S4CONNECTOR reject nach Domänenbeitritt von Windows10Client
#9

[quote]Hi, I have applied the patch to a VM copy of the DC. The rejects seem to have stopped increasing at 468, but they haven’t decreased.

The connector-s4.log is still showing attempts to add/update etc with the “The object is currently locked.” error in the previous output.[/quote]

That is not nice of the connector, but we can fix this. Please understand, that these steps are ONLY for this occasion, you should not need to touch the next steps otherwise. Be very careful.

# service univention-s4-connector stop
# cp /etc/univention/connector/lockingdb.sqlite /etc/univention/connector/lockingdb.sqlite_OLD
# sqlite3 /etc/univention/connector/lockingdb.sqlite 'SELECT * FROM S4_LOCK;'
# sqlite3 /etc/univention/connector/lockingdb.sqlite 'DELETE FROM S4_LOCK;'
# sqlite3 /etc/univention/connector/lockingdb.sqlite 'SELECT COUNT(*) FROM S4_LOCK;'
# service univention-s4-connector start

The first sqlite command checks if there are active locks in the database - these should correspond with your rejects. The second commands removes these locks from the DB. The last command counts the S4 Locks - this should be zero now. If you then restart the S4 connector, the rejects will be resolved.

#10

Thanks for the help.

Some progress. Have performed this in the VM test copy.

Interestingly the first select statement gives me 421 GUID entries that don’t quite match up to the 468 results I get from the univention-s4connector-list-rejected command.

After doing all three commands though and restarting the connector the backlog clears with a few rejects still left.

univention-s4connector-list-rejected command now gives:

UCS rejected

    1:     UCS DN: cn=NAV,ou=Servers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
           S4 DN: cn=nav,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
           Filename:  /var/lib/univention-connector/s4/1483439168.103342

S4 rejected

    1:     S4 DN: CN=NAV,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
           UCS DN: cn=nav,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

    2:     S4 DN: CN=NAV,OU=Servers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
           UCS DN: cn=nav,ou=Servers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

    3:     S4 DN: CN=ITWS,OU=Administrative,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au  <<--- the second original computer object I renamed and rejoined.
           UCS DN: cn=itws,ou= administrative,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au

The connector-s4.log has this as the repeating errors:

03.01.2017 22:39:43,665 MAIN (------ ) : DEBUG_INIT 03.01.2017 22:39:43,690 LDAP (PROCESS): Building internal group membership cache 03.01.2017 22:39:43,700 LDAP (PROCESS): Internal group membership cache was created 03.01.2017 22:39:43,819 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483439168.103342 03.01.2017 22:39:43,823 LDAP (WARNING)sync failed, saved as rejected /var/lib/univention-connector/s4/1483439168.103342 03.01.2017 22:39:43,823 LDAP (WARNING)Traceback (most recent call last): File "/usr/lib/pymodules/python2.7/univention/s4connector/ __ init __ .py", line 987, in resync_rejected_ucs if self. __ sync_file_from_ucs(filename, append_error=' rejected'): File "/usr/lib/pymodules/python2.7/univention/s4connector/ __ init __ .py", line 712, in __ sync_file_from_ucs dn, new, old, old_dn = cPickle.load(f) EOFError
So still seems to be something wrong.
Not sure if those cPickle EOFErrors are something to do with the hotfix, or the VM networking setup. They don’t occur on the production machine. I can try another restore, and check the process again before trying on the live system.

#11

After another restore, and more playing around, I noticed that three reject files in /var/lib/univention-connector/s4/ were empty.

After deleting those, I don’t get anymore EOFErrors and everything appears to now be synced.

Will try it on the live system.

#12

Thanks for sticking with me.

The good: After applying the hotfix and clearing the locks table on the live system it cleared a backlog of over 650 rejects.

However my 2 renamed and joined Computer objects had disappeared on both sides. After another un-join and re-join of the NAV computer the same “object is currently locked” errors occur and the computer account doesn’t sync.

To troubleshoot this further I tried two scenarios.
Cleared the lock table once more.

  1. un-joined, renamed the NAV computer back to it’s original name RFBS-W7 and rejoined (its a win7 machine BTW).
    [ul]
    [li]The RFBS-W7 computer account does not show up in either directory despite it thinking it’s joined on the client.[/li]
    [li]The DNS forward and reverse zones appear to have synced the RFBS-W7 name in both S4 and UCS[/li][/ul]
  2. left my ITWS PC with its existing computer name and rejoined (its a win10 machine).
    [ul]
    [li]The ITWS computer account shows up in S4 RSAT under CN=computers. It does not appear in the UCS directory.[/li]
    [li]The DNS forward and reverse zones are not in UCS or S4.[/li][/ul]

I’ve verified that the hot fix is in place.

root@dc1:~# ls /usr/share/pyshared/univention/admin/handlers/ appcenter computers container dhcp dns groups __init__.py __init__.py.orig kerberos mail nagios networks policies saml settings shares users uvmm 


root@dc1:/etc/univention/connector# sqlite3 /etc/univention/connector/lockingdb.sqlite 'SELECT * FROM S4_LOCK;'
1|3ff1e636-8833-4bc6-a5a9-afe726bc73ba
2|3ff1e636-8833-4bc6-a5a9-afe726bc73ba

root@dc1:/etc/univention/connector# univention-s4connector-list-rejected

UCS rejected

    1:   UCS DN: cn=ITWS,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
          S4 DN: <not found>
         Filename: /var/lib/univention-connector/s4/1483452283.879606

    2:   UCS DN: cn= ITWS,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
          S4 DN: <not found>
         Filename: /var/lib/univention-connector/s4/1483452283.893747

    3:   UCS DN: cn= ITWS,cn=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
          S4 DN: <not found>
         Filename: /var/lib/univention-connector/s4/1483452284.088594

    4:   UCS DN: cn= ITWS,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
          S4 DN: <not found>
         Filename: /var/lib/univention-connector/s4/1483452342.069356

    5:   UCS DN: cn= ITWS,cn=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
          S4 DN: <not found>
         Filename: /var/lib/univention-connector/s4/1483452342.498534


S4 rejected

    1:    S4 DN: CN= ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
         UCS DN: <not found>

        last synced USN: 99807


root@dc1:/etc/univention/connector# ls /var/lib/univention-connector/s4/
1483452283.879606  1483452283.893747  1483452284.088594  1483452342.069356  1483452342.498534  tmp

Connector.log

[code]04.01.2017 00:05:47,101 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:47,102 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:47,113 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:47,115 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:09:56,502 MAIN (------ ): DEBUG_INIT
root@dc1:~# tail -n 100 /var/log/univention/connector-s4.log
04.01.2017 00:02:44,344 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] cn=rfbs-w7,cn=computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:02:44,363 LDAP (PROCESS): password_sync_ucs_to_s4: The UCS object (cn=RFBS-W7,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au) was not found. The object was removed.
04.01.2017 00:02:44,370 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483451724.914137
04.01.2017 00:02:44,373 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] cn=rfbs-w7,cn=computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:02:44,395 LDAP (PROCESS): sync to ucs: Resync rejected dn: CN=RFBS-W7,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:02:44,494 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:09dd28bf-92f1-49a8-8a4c-70a1ead11f84,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,495 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:09dd28bf-92f1-49a8-8a4c-70a1ead11f84,cn=computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:02:44,508 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:6f2666ba-2348-4bcf-9f93-d81b9b80375f,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,508 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:6f2666ba-2348-4bcf-9f93-d81b9b80375f,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:02:44,514 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:627fbd28-776b-48de-a769-2d20a34cf635,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,514 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:627fbd28-776b-48de-a769-2d20a34cf635,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:02:44,521 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:d7c22278-0a04-465d-9986-59a9ed3a636a,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,522 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:d7c22278-0a04-465d-9986-59a9ed3a636a,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:02:44,528 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:973afb4c-eee4-425f-8f1d-5b774c13531d,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,529 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:973afb4c-eee4-425f-8f1d-5b774c13531d,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:02:44,534 LDAP (PROCESS): sync to ucs: [windowscomputer] [ delete] cn=rfbs-w7
DEL:5760186d-4581-4a13-bd61-a8f30ee23141,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:02:44,534 LDAP (WARNING): Object to delete doesn’t exsist, ignore (cn=rfbs-w7
DEL:5760186d-4581-4a13-bd61-a8f30ee23141,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au)
04.01.2017 00:03:25,870 MAIN (------ ): DEBUG_INIT
04.01.2017 00:03:33,459 MAIN (------ ): DEBUG_INIT
04.01.2017 00:04:43,772 LDAP (PROCESS): sync to ucs: [windowscomputer] [ add] cn=ITWS,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:04:43,916 LDAP (ERROR ): Unknown Exception during sync_to_ucs
04.01.2017 00:04:43,916 LDAP (ERROR ): Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1475, in sync_to_ucs
result = self.add_in_ucs(property_type, object, module, position)
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1262, in add_in_ucs
return ucs_object.create() and self.__modify_custom_attributes(property_type, object, ucs_object, module, position)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 305, in create
return self._create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 764, in _create
self._ldap_post_create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/computers/windows.py”, line 478, in _ldap_post_create
univention.admin.handlers.simpleComputer.update_groups(self)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 2456, in update_groups
groupObject.modify(ignore_license=1)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 316, in modify
return self._modify(modify_childs, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 810, in _modify
self.lo.modify(self.dn, ml, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/uldap.py”, line 403, in modify
raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg)
ldapError: Type or value exists: modify/add: memberUid: value #0 already exists

04.01.2017 00:04:43,917 LDAP (WARNING): sync to ucs was not successfull, save rejected
04.01.2017 00:04:43,917 LDAP (WARNING): object was: CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:04:48,933 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:04:48,934 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:04:48,942 LDAP (PROCESS): sync from ucs: [windowscomputer] [ modify] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:04:48,943 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:04:48,949 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:04:48,950 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:41,791 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483452283.879606
04.01.2017 00:05:41,796 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:41,800 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:41,806 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483452283.893747
04.01.2017 00:05:41,811 LDAP (PROCESS): sync from ucs: [windowscomputer] [ modify] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:41,813 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:41,816 LDAP (PROCESS): sync from ucs: Resync rejected file: /var/lib/univention-connector/s4/1483452284.088594
04.01.2017 00:05:41,821 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:41,822 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:41,827 LDAP (PROCESS): sync to ucs: Resync rejected dn: CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:41,833 LDAP (PROCESS): sync to ucs: [windowscomputer] [ add] cn=ITWS,CN=Computers,dc=sanitisedsubdomain,dc=sanitiseddomain,dc=com,dc=au
04.01.2017 00:05:42,86 LDAP (ERROR ): Unknown Exception during sync_to_ucs
04.01.2017 00:05:42,86 LDAP (ERROR ): Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1475, in sync_to_ucs
result = self.add_in_ucs(property_type, object, module, position)
File “/usr/lib/pymodules/python2.7/univention/s4connector/init.py”, line 1262, in add_in_ucs
return ucs_object.create() and self.__modify_custom_attributes(property_type, object, ucs_object, module, position)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 305, in create
return self._create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 764, in _create
self._ldap_post_create()
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/computers/windows.py”, line 478, in _ldap_post_create
univention.admin.handlers.simpleComputer.update_groups(self)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 2456, in update_groups
groupObject.modify(ignore_license=1)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 316, in modify
return self._modify(modify_childs, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/handlers/init.py”, line 810, in _modify
self.lo.modify(self.dn, ml, ignore_license=ignore_license)
File “/usr/lib/pymodules/python2.7/univention/admin/uldap.py”, line 403, in modify
raise univention.admin.uexceptions.ldapError(_err2str(msg), original_exception=msg)
ldapError: Type or value exists: modify/add: memberUid: value #0 already exists

04.01.2017 00:05:47,101 LDAP (PROCESS): sync from ucs: [windowscomputer] [ add] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:47,102 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:05:47,113 LDAP (PROCESS): sync from ucs: [windowscomputer] [ delete] CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au
04.01.2017 00:05:47,115 LDAP (PROCESS): Unable to sync CN=ITWS,CN=Computers,DC=sanitisedsubdomain,DC=sanitiseddomain,DC=com,DC=au (GUID: 3ff1e636-8833-4bc6-a5a9-afe726bc73ba). The object is currently locked.
04.01.2017 00:09:56,502 MAIN (------ ): DEBUG_INIT
[/code]

I’m reluctant to keep monkeying with the live system and that lock database, but it seems to be the only thing that clears the rejects at the cost of losing some of the synced objects?

Likewise I can’t seem to join a new PC (win7/win10) without triggering this cycle of sync/lock errors.

So has there been some sort of regression with joining PCs on 4.1-4? I was on 4.1-3 errata 350 something from memory before the upgrade and had no issues joining new PCs.

Thanks again for the support.

#13

We have this issue open for the behaviour: https://forge.univention.org/bugzilla/show_bug.cgi?id=43247 - The status is “resolved fixed” that means it has to go through QA and will be released with a patch. Unfortunatly I cannot provide a quick fix at the moment.

#14

That bug does seem to fit my circumstances.

I do have a mix of upper and lowercase hostnames, and there is a strange mix of case in both RSAT and UCS DNS and computer objects and in the distinguished names in the reject messages.

Seems that my situation at the moment is that if I clear the locks, the computer objects are removed on both sides although the clients think they’re joined. Eventually the trust relationship expires with no account in LDAP and user logins stop working on the client. A rejoin brings it back into S4 (but not UCS LDAP) but kicks off the lock errors and reject build-up. Rinse and repeat.

Fortunately the two affected machines are not critical and have workarounds, but I assume I can’t add any new machines until this is fixed.

Look forward to the errata.

Thanks again for the help.

#15

This should be fixed here: http://errata.software-univention.de/ucs/4.1/367.html

#16

Just updated to errata 372. So far so good. Will update if I hit any relevant issues.

Thanks again.

Mastodon