Listener.log meldet Duplicate entry Fehler

arminsys · October 6, 2014, 12:25pm

Hallo,

auf unserem DC-Backup (mit Open-Xchange) finde ich ca. alle 5 Minuten Fehlermeldungen zu Gruppen. Diese Gruppen wurde im UDM des
DC-Master vor Tagen geändert (z.B. Member hinzugefügt):

UNIVENTION_DEBUG_BEGIN  : uldap.__open host=lantia.sysgo.com port=7389 base=dc=sysgo,dc=com
UNIVENTION_DEBUG_END    : uldap.__open host=lantia.sysgo.com port=7389 base=dc=sysgo,dc=com
06.10.14 14:20:19.348  LISTENER    ( PROCESS ) : ox-group: user, domain: xyz, sysgo.com
...
06.10.14 14:20:23.956  LISTENER    ( ERROR   ) : OX: failed with 106: group p4trainer in context 10 could not be changed:
Server response:
 java.sql.BatchUpdateException: Duplicate entry '10-339-36' for key 'PRIMARY'
    at com.openexchange.admin.storage.mysqlStorage.OXGroupMySQLStorage.addMember(OXGroupMySQLStorage.java:241)
    at com.openexchange.admin.rmi.impl.OXGroup.addMember(OXGroup.java:170)
    at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:622)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
    at sun.rmi.transport.Transport$1.run(Transport.java:177)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:173)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:553)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:808)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:667)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:701)
    at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:273)
    at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:251)
    at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:160)
    at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:194)
    at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:148)
    at com.sun.proxy.$Proxy0.addMember(Unknown Source)
    at com.openexchange.admin.console.group.ChangeCore.commonfunctions(ChangeCore.java:104)
    at com.openexchange.admin.console.group.Change.<init>(Change.java:70)
    at com.openexchange.admin.console.group.Change.main(Change.java:63)


06.10.14 14:20:23.956  LISTENER    ( PROCESS ) : ox-groups: transaction deferred: dn='cn=p4trainer,cn=groups,dc=sysgo,dc=com' ['/opt/open-xchange/sbin/changegroup', '--displayname=Team: P4 Trainer', '--addmembers=36,36,36,36,36,36,36,36', '--adminuser=oxadmin', '--adminp
Server response:
 java.sql.BatchUpdateException: Duplicate entry '10-339-36' for key 'PRIMARY'
    at com.openexchange.admin.storage.mysqlStorage.OXGroupMySQLStorage.addMember(OXGroupMySQLStorage.java:241)
    at com.openexchange.admin.rmi.impl.OXGroup.addMember(OXGroup.java:170)
    at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:622)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
    at sun.rmi.transport.Transport$1.run(Transport.java:177)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:173)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:553)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:808)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:667)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:701)
    at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:273)
    at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:251)
    at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:160)
    at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:194)
    at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:148)
    at com.sun.proxy.$Proxy0.addMember(Unknown Source)
    at com.openexchange.admin.console.group.ChangeCore.commonfunctions(ChangeCore.java:104)
    at com.openexchange.admin.console.group.Change.<init>(Change.java:70)
    at com.openexchange.admin.console.group.Change.main(Change.java:63)

Vor allem das

--addmembers=36,36,36,36,36,36,36,36

erscheint mir seltsam.
Ist hier ein Fehler im Listener? Wie können wir den Fehler beseitigen?

Meybohm · October 7, 2014, 6:52am

Hallo,

ich würde mir hierzu einmal das LDAP-Objekt der betroffenen Gruppe anschauen.

Mit freundlichen Grüßen
Janis Meybohm

arminsys · October 7, 2014, 7:12am

Es sind aktuell 3 Gruppen die diesen Fehler im listener.log zeigen.
Zwei davon sehen im LDAP genauso aus wie alle anderen auch. Aber eine hat zusätzlich
zwei Einträge, die einige andere nicht haben:

objectClass: univentionObject
univentionGroupType: -2147483646

Die Liste der Members ist bei allen Gruppen in Ordnung.

arminsys · October 7, 2014, 7:31am

Jetzt wird es noch seltsamer.
Eine Gruppe habe ich nun komplett gelöscht. Das listener.log zeigt nun ein Fehler bei create mit einer riesen Liste von Usern:

07.10.14 09:25:07.553  LISTENER    ( PROCESS ) : ox-groups: transaction deferred: dn='cn=sales-int,cn=groups,dc=sysgo,dc=com' ['/opt/open-xchange/sbin/creategroup', '--displayname=Team: Sales Group International', '--addmembers=98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,278,98,321,73,370,314,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,370,347,321,316,314,313,311,300,278,233,98,73,60,55', '--adminuser=oxadmin', '--adminpass=xxxxl', '--contextid=10', '--name=sales-int'] returned 108: group in context 10 could not be created: 
Server response:
 No such user

Meybohm · October 7, 2014, 7:32am

Hallo,

das Modul prüfe die aktuellen und neuen Gruppenmitgliedschaften und generiert darüber die Argumente für die –addmembers Option:

ADMIN_PASSWORD=$(cat /etc/ox-secrets/context10.secret) /opt/open-xchange/sbin/listgroup -A oxadmin -c 10 --csv

Im Listener Log sollten man das bei höherem Loglevel auch sehen können (ucr set listener/debug/level=‘4’;/etc/init.d/univention-directory-listener restart).
Wenn das an Debug noch nicht reicht, können Sie vor den diversen auskommentierten “univention-debug”-Zeilen die Raute entfernen, den Listener noch mal neu starten und den Vorgang wiederholen.

Grüße
Janis

arminsys · October 7, 2014, 8:00am

Das ‘listgroup’ meldet den korrekten Stand der Gruppen und Mitglieder im OX.

Nach dem Erhöhen des debug levels für den listener sieht man aber, daß dieser zwar die richtige Liste der User
aus dem LDAP bekommt, aber bei der Liste der OX Context User IDs falsche dabei sind.
Beispiel einer neuen Gruppe:

07.10.14 09:49:48.566  LISTENER    ( INFO    ) : ox-group: Group usermap: <korrekte liste der User>
07.10.14 09:49:48.567  LDAP        ( INFO    ) : uldap.search filter=(&(objectClass=univentionMailDomainname)(oxContextName=context10)) base=cn=mail,dc=sysgo,dc=com scope=sub attr=['cn'] unique=0 required=0 timeout=-1 sizelimit=0
07.10.14 09:49:52.882  LISTENER    ( INFO    ) : ox-group: Context Users IDs: ['55', '60', '73', '98', '233', '278', '300', '311', '313', '314', '316',...
07.10.14 09:49:53.382  LISTENER    ( INFO    ) : ox-group: Old Group Member IDs: []
07.10.14 09:49:53.383  LISTENER    ( INFO    ) : ox-group: addmembers: 98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316,60,233,98,321,73,370,314,278,300,313,311,347,55,316...

Bei addmembers ist im Grunde jeder User geliestet.

Bei einer veränderten Gruppe (ein neues Mitglied) scheint der Listener die neue ID mehrfach zu finden:

07.10.14 09:49:58.373  LISTENER    ( INFO    ) : ox-group: addmembers: 349,349,349,349,349,349,349,349,349

Meybohm · October 7, 2014, 9:15am

Hallo,

im Fehlerfall kann der Listener die Transaktion zurückstellen (" transaction deferred …") und zu einem späteren Zeitpunkt erneut versuchen diese durchzuführen. Das scheint zumindest bei “cn=sales-int,cn=groups,dc=sysgo,dc=com” und “cn=p4trainer,cn=groups,dc=sysgo,dc=com” der Fall zu sein. Warum das so eingetreten ist kann ich ohne nähere Analyse des Ablaufs nicht sagen.

Sie können aber, am besten auf einem Testsystem, prüfen ob es ausreicht die Listener Queue für die entsprechenden Module zu leeren und betroffene Listener-Module neu zu initialisieren, z.B:./etc/init.d/univention-directory-listener stop rm -r /var/spool/univention-directory-listener/ox-group /etc/init.d/univention-directory-listener start univention-directory-listener-ctrl resync ox-group

Mit freundlichen Grüßen
Janis Meybohm

arminsys · October 7, 2014, 9:29am

Macht dieser resync auch Sinn, wenn die queue eigentlich leer ist?
Denn auf dem System existiert die Datei /var/spool/univention-directory-listener/ox-group gar nicht.

Ich habe für eine Gruppe (p4trainer), die mehrfach eine ID bei addmembers hat, den Befehl aus dem Log mal manuell
ausgeführt und bei addmembers die ID nur einfach angebeben. Dies hat funktioniert und die Gruppe ist nun korrekt.

Die Gruppe, die ich zum Test gelöscht und neu angelegt habe (sales-int) hat aber weiterhin das Problem, dass alle
IDs bei addmembers angegeben werden. Offensichtlich auch IDs, die gar nicht existieren.

arminsys · October 7, 2014, 9:39am

Oh, es heisst ox-groups, nicht ox-group. Ich habe es getestet, aber der Listener kommt wieder auf den gleichen Fehler
und hat zu viele und falsche ID in addmembers.

arminsys · October 7, 2014, 10:35am

Bei genauer Betrachtung fällt auf, daß die addmembers Liste nicht falsche User enthält, sondern die richtigen User nur mehrfach.
Es wird also eine ID Liste mit korrekten Usern 7 mal, 8 mal oder 9 mal an einander gefügt.

arminsys · October 8, 2014, 7:24am

Das Problem ist nicht auf die bereits genannten Gruppen beschränkt. Lege ich eine neue Gruppe an, die auch für
OX aktiviert ist, passiert das gleiche. Der Listener meldet den Fehler weil bei addmembers die IDs mehrfach gelistet werden.

Das ganze muss ca. in den letzten zwei Wochen passiert sein. In dieser Zeit gab es auch Updates. Sonstige Änderungen wurden am
System in den letzten Wochen nicht vorgenommen.

arminsys · October 8, 2014, 8:40am

Ich denke ich habe den Ort des Fehlers gefunden. Es ist wohl das Script

/opt/open-xchange/sbin/listuser

welches vom Listener aufgerufen wird, um die Liste der User zu bekommen. Rufe ich dieses Script in der Shell auf

/opt/open-xchange/sbin/listuser --adminuser=oxadmin --adminpass=xxxxxx --csv --contextid=10

bekomme ich alle User 10fach gelistet.
Schaue ich in der OX Datenbank nach, sind dort die User aber korrekterweise nur einmal drin.

Vor kurzem haben einige User ein persönliches Adressbuch (contacts folder) im privaten Bereich angelegt und hierhinein die Einträge des “Global address book” kopiert.
Dies wurde gemacht, da bei ActiveSync die Einträge im Global address book nicht aufs Handy gesynced werden, sondern nur als Suche verfügbar sind. Das private Adressbuch wird aber gesynced (viel besser für unsere Außendienstler).
Kann es nun sein, dass das listuser Script dadurch eine Mehrfachliste der User erzeugt?
Das ist zumindest die einzige Änderung auf unserem System, die einen Zusammenhang bietet. Abgesehen von Updates der letzten Wochen.
So oder so ist dies ein Fehler und ich hoffe der wird schnellstmöglich behoben. Die Fehleranalyse habe ich ja nun schon gut vorbereitet

Meybohm · October 9, 2014, 9:29am

Hallo,

ich glaube nicht dass es normal ist das listuser die Datensätze doppelt ausgibt. Evtl. hilft es wenn Sie die Ausgabe einmal posten.

Mit freundlichen Grüßen
Janis Meybohm

arminsys · October 9, 2014, 9:59am

Ich denke das ist zu groß zum Posten hier und beinhaltet auch alle unsere User mit sehr vielen Daten.
Und wie sollte das helfen? Wenn ich mir den Output von listuser ansehe, finde ich Userzeilen, die so anfangen:

Name,Language,Id,Info,Display_name,PrimaryEmail,....
"acs","en_US","23",,"Schindler, Armin", ...

Wir haben ca. 100 User und diese sind geliestet. Nach dem letzten User kommen alle User nochmal und nochmal und nochmal…
Zur Zeit hat die Ausgabe über 900 Zeilen, alle User tauchen also 9 mal als 9 Zeilen auf.

arminsys · November 5, 2014, 9:02am

Hallo,

gibt es hierzu Neuigkeiten? Das Problem besteht bei uns immer noch. Das Script

/opt/open-xchange/sbin/listuser

listet immer noch, auch nach den letzten Updates, alle User mehrfach auf.

Muss ich das ggf an Open-Xchange melden (da es sich ja um ein OX Java Programm handelt)?

ahrnke · November 5, 2014, 10:11am

Hallo,

auf unserer Referenzinstallation mit dem aktuellen Updates listet

/opt/open-xchange/sbin/listuser -A oxadmin -P $(cat /etc/ox-secrets/context10.secret) -c 10

alle eingerichteten Nutzer nur einmal auf. Es scheint demzufolge kein generelles Problem der UCS-Integration zu sein. Wahrscheinlich wird Open-Xchange hier besser helfen können.

Viele Grüße,
Dirk Ahrnke

Meybohm · November 5, 2014, 10:17am

Hallo,

lt. den Kollegen bei OX ist ein solches Verhalten nicht bekannt und kann auch nicht durch das Kopieren von Adressbüchern reproduziert/nachgestellt werden. Ich würde dazu Raten dass von den Kollegen bei OX untersuchen zu lassen wenn Sie die Möglichkeit dazu haben.

Mit freundlichen Grüßen
Janis Meybohm

arminsys · November 5, 2014, 1:23pm

Ich konnte die Ursache nun finden. Das Problem kommt tatsächlich von den Adressbuch-Kopien.
Macht man diese Kopien über das OX-Web manuell, entsteht das Problem allerdings nicht.
Bei uns macht dies aber automatisch ein Script auf Basis der OX-API. Hierbei werden über die HTTP-OX-API
die Addressbuch Einträge gelesen und über diese API auch in das private Adressbuch übertragen. Bei dieser
Kopie wurden alle Felder mitkopiert. Und genau das ist der Fehler. Das Feld user_id, welches im Global Address Book
mit dabei ist, darf nicht gesetzt werden in der Kopie, sonst werden die User mehrfach gelistet.

Ich habe das in unserem Script geändert und der Fehler ist beseitigt. Allerdings denke ich daß listuser hier diesen Fehler auch nicht
machen sollte…