Univention Bugzilla – Bug 29625
Absturz des S4 Connector Prozesses
Last modified: 2013-02-09 12:04:06 CET
Bei Produkttests zu Samba4 Performance beim Anlegen von 5000 Benutzern ist ein einem der Testläufe der S4 Connector-Prozess abgestüzt. In connector-s4-status.log fanden sich Binärdaten, im connector-s4.log war der letzte Eintrag "Scan all changes from UCS ...".
Created attachment 4873 [details] connector-s4.log, listener.log, /etc/univention/connector etc. Aufgerufen wurde das Skript mit "time ./create_users 5000". Die nächste Pickle-Datei, die unter /var/lib/univention-connector/s4/ liegt, lässt sich in Python manuell problemlos laden: ('cn=test1304,cn=uid,cn=temporary,cn=univention,dc=arucs31i17,dc=qa', {'hasSubordinates': ['FALSE'], 'entryCSN': ['20121205185123.425062Z#000000#000#000000'], 'cn': ['test1304'], 'objectClass': ['top', 'lock'], 'creatorsName': ['cn=admin,dc=arucs31i17,dc=qa'], 'entryUUID': ['82866516-d358-1031-9376-810c49c5d6e5'], 'modifiersName': ['cn=admin,dc=arucs31i17,dc=qa'], 'createTimestamp': ['20121205185123Z'], 'structuralObjectClass': ['lock'], 'subschemaSubentry': ['cn=Subschema'], 'entryDN': ['cn=test1304,cn=uid,cn=temporary,cn=univention,dc=arucs31i17,dc=qa'], 'lockTime': ['1354733783'], 'modifyTimestamp': ['20121205185123Z']}, {}, None)
Created attachment 4874 [details] connector-s4.log mit connector/debug/level=4 Das Problem ist persistent auf VM arequate_ucs31qa16.130 konserviert. Wenn man sich per gdb an den Prozedd hängt, dann sieht man am Ende: Program exited normally. Zwei Dinge finde ich bemerkenswert an den noormalen (level 2) Logmeldungen: Erstens sieht es so aus, als würde der Initialisierungsprozess nach dem ersten "Scan all changes from UCS ..." nochmal neu gestartet (DEBUG_INIT). Zweitens kommen dann alle Logmeldungen doppelt. 05.12.2012 21:51:49,66 MAIN (------ ): DEBUG_INIT 05.12.2012 21:51:49,113 LDAP (PROCESS): Building internal group membership cache 05.12.2012 21:51:49,170 LDAP (PROCESS): Internal group membership cache was created 05.12.2012 21:51:49,437 LDAP (PROCESS): Scan all changes from UCS ... 05.12.2012 21:52:38,585 MAIN (------ ): DEBUG_INIT 05.12.2012 21:52:38,585 MAIN (------ ): DEBUG_INIT 05.12.2012 21:52:38,614 LDAP (PROCESS): Building internal group membership cache 05.12.2012 21:52:38,614 LDAP (PROCESS): Building internal group membership cache 05.12.2012 21:52:38,636 LDAP (PROCESS): Internal group membership cache was created 05.12.2012 21:52:38,636 LDAP (PROCESS): Internal group membership cache was created 05.12.2012 21:52:38,825 LDAP (PROCESS): Scan all changes from UCS ... 05.12.2012 21:52:38,825 LDAP (PROCESS): Scan all changes from UCS ..
Created attachment 4875 [details] /var/lib/univention-connector/s4/1354733999.967263 Ursache ist, das eine bestimmte Pickle-Datei für eine Änderung an "Domain Users" hier defekt ist. Kurzer Test mit der extrahierten Funktion _generate_dn_list_from: unpickle /var/lib/univention-connector/s4/1354733999.967263 Traceback (most recent call last): File "./1.py", line 43, in <module> ding._generate_dn_list_from(files) File "./1.py", line 33, in _generate_dn_list_from dn,new,old,old_dn=cPickle.load(f) ValueError: too many values to unpack Nach manuellem Einlesen des Objekts (mit pickle oder cPickle) handelts es sich um eine Liste der Länge 8: obj[0]= 'cn=Domain Users,cn=groups,dc=arucs31i17,dc=qa', obj[1]= {'objectClass': ['top', 'posixGroup', 'univentionGroup', 'sambaGroupMapping', 'univentionObject'], 'sambaGroupType': ['2'], 'hasSubordinates': ['FALSE'], 'entryCSN': ['20121205185959.738668Z#000000#000#000000'], 'cn': ['Domain Users']} obj[2]= 'memberUid' obj[3]= ## Liste mit 1386 Elementen, ## die letzten beiden sind 'test1381', 'test1382' obj[4]= "te(S'cn=test2283,cn=uid,cn=temporary,cn=univention,dc=arucs31i17,dc=qa" obj[5]= {'hasSubordinates': ['FALSE'], 'entryCSN': ['20121205185959.542120Z#000000#000#000000'], 'cn': ['test2283'], 'objectClass': ['top', 'lock'], 'creatorsName': ['cn=admin,dc=arucs31i17,dc=qa'], 'entryUUID': ['b6279bb4-d359-1031-9fa5-810c49c5d6e5'], 'modifiersName': ['cn=admin,dc=arucs31i17,dc=qa'], 'createTimestamp': ['20121205185959Z'], 'structuralObjectClass': ['lock'], 'subschemaSubentry': ['cn=Subschema'], 'entryDN': ['cn=test2283,cn=uid,cn=temporary,cn=univention,dc=arucs31i17,dc=qa'], 'lockTime': ['1354734299'], 'modifyTimestamp': ['20121205185959Z']} obj[6]= {} obj[7]= None
Created attachment 4876 [details] Insgesamt vier von 32219 pickle Objekten sind defekt. Diese vier beziehen sich jeweils auf Domain Users. Ich gehe davon aus, dass cPickle im Listener Modul s4-connector Probleme mit großen Objekten hat.
Arvid hat dazu noch folgendens gefunden: > zu dem cPickle-Bug gestern habe ich nur folgendes Posting gefunden: > http://bugs.python.org/issue616013#msg70751 > Im Extremfall wäre das eine Option, z.B. als Code-Vergleich um einen Patch > zu finden. > > ( > http://svn.python.org/projects/python/branches/release30-maint/Modules/_pic >kle.c vs. > http://svn.python.org/projects/python/branches/release26-maint/Modules/cPic >kle.c )
Das Listener-Modul s4-connector ist jetzt um einen Test erweitert der die geschriebene Pickle-Datei direkt nochmal ausliest und prüft, ob die enthaltenen Liste genau 4 Elemente enthält. Dieser Test ist ohne Speicher-Korruption möglich. Falls ernicht erfolgreich ist, wird eine Logmeldung auf Level WARN ausgegeben (Schlüsselwort "broken") und das Pickle erneut mit plain-python-pickle geschirieben. Der Test wird erneut durchgeführt und im Fehlerfall wird eine Meldung mit Level ERROR ausgegeben. Im Test ließ sich das Originalproblem noch nicht wieder nachstellen, die Funktion des Listeners war jedoch korrekt, daher erstmal fixed. Advisory: 2012-12-18-univention-s4-connector.yaml
Im errata Scope ist die Connector Version aus 3.1-1 importiert. Ich habe für Bug #30119 jetzt die Version aus 3.1-0 wieder importiert. Du müsstest den Patch dann noch extrahieren und im Patches Verzeichnis ablegen.
Paket ist mit extrahiertem Patch neu gebaut.
OK, das eigentliche Problem konnte ich nicht reproduzieren, Code + YAML OK.
http://errata.univention.de/3.1-errata35.html
*** Bug 27332 has been marked as a duplicate of this bug. ***