Fehler Anlage neuer Benutzer / Open-xchange

german

#1

Hallo zusammen,

ich habe gestern versucht einen neuen Benutzer anzulegen mit Zugriff auf Open-xchange. Das Anlegen in der management-console funktionierte, leider war kein Login in OX möglich.
Fehlermeldung in etwa “User nicht im Context 10” (habs leider nicht genau greifbar, aber der Sinn dürfte ja klar sein :wink: )

im context ist er wirklich nicht. listuser -c 10 [...] zeigte den Benutzer nicht an, aber alle anderen, funktionierenden Benutzer.

in open-xchange.log.0 brachte er folgende Fehlermeldung:

2016-05-23T19:27:56,482+0200 ERROR [RMI TCP Connection(134)-12.34.56.78] com.openexchange.admin.rmi.impl.OXUser.createUserCommon(OXUser.java:1626) com.openexchange.admin.rmi.exceptions.InvalidDataException: The displayname is already used at com.openexchange.admin.storage.mysqlStorage.OXToolMySQLStorage.checkCreateUserData(OXToolMySQLStorage.java:2510) at com.openexchange.admin.rmi.impl.OXUser.createUserCommon(OXUser.java:1617) at com.openexchange.admin.rmi.impl.OXUser.create(OXUser.java:1532) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322) at sun.rmi.transport.Transport$2.run(Transport.java:202) at sun.rmi.transport.Transport$2.run(Transport.java:199) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:198) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:567) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:828) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(TCPTransport.java:619) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:684) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:681) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:681) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)

Der Displayname is aber unique. Der Displayname sollte ja das Feld “OX Anzeigename” im Reiter “Kontakt” oder “Anzeigename” im Reiter “Allgemein” sein.
Beides haben wir mit “Vorname Nachname” gefüllt und es gibt keinen zweiten Mitarbeiter mit diesem Namen.

Wir nutzen die aktuellen Versionen:
Open-xchange: 7.8.1-7-ucs1
UCS: 4.1-2 errata183

Hat jemand eine Idee wo man da ansetzen kann? Kann ich irgendwie den Befehl sehen der zur Anlage des Benutzers genutzt wird?

Besten Dank im Vorraus.

Schöne Grüße

sela


#2

Hallo,

der OX Anzeigename (oxDisplayName im LDAP) und Anzeigename (displayName im LDAP) werden beim Anlegen eines OX Benutzers automatisch mit Vor- und Nachname befüllt. Danach sind es aber zwei unabhängige Attribute. Beim Anlegen eines OX Benutzers wird dann im UCS LDAP nach einem OX Benutzer mit gleichem oxDisplayName gesucht, falls vorhanden gibt es eine entsprechende Fehlermeldung. Das hat hier jetzt anscheinend nicht gegriffen. Folgendes sollten wir zunächst prüfen:

Gibt es ein entsprechendes Objekt im UCS LDAP:

-> univention-ldapsearch oxDisplayName="$ANZEIGENAME"  # $ANZEIGENAME bitte mit dem tatsächlichem Wert ersetzen

Gibt es in OX einen entsprechenden Benutzer:

-> /opt/open-xchange/sbin/listuser -c 10 -A oxadmin -P $(< /etc/ox-secrets/context10.secret) | grep "$ANZEIGENAME"

Weitere Informationen bzgl. des Anlegens/Änderns von OX Benutzern finden sich vielleicht auch in der Log-Datei /var/log/univention/listener.log.

Viele Grüße


#3

Hallo,

vielen Dank für die Antwort und sorry für die verspätete Rückmeldung-

univention-ldapsearch oxDisplayName="Vorname Nachname" hat den User gefunden

[code]#: univention-ldapsearch oxDisplayName=“Vorname Nachname”

extended LDIF

LDAPv3

base <dc=firma,dc=intern> (default) with scope subtree

filter: oxDisplayName=Vorname Nachname

requesting: ALL

usrname, users, firma.intern

dn: uid=usrname,cn=users,dc=firma,dc=intern
uid: usrname
krb5PrincipalName: usrname@firma.INTERN
objectClass: top
objectClass: person
objectClass: univentionPWHistory
objectClass: posixAccount
objectClass: shadowAccount
objectClass: univentionMail
objectClass: sambaSamAccount
objectClass: organizationalPerson
objectClass: inetOrgPerson
objectClass: krb5Principal
objectClass: krb5KDCEntry
objectClass: univentionSAMLEnabled
objectClass: oxUserObject
objectClass: univentionXMPPAccount
objectClass: openproject-user
objectClass: univentionObject
oxTimeZone: Europe/Berlin
uidNumber: 2056
sambaAcctFlags: [U ]
sambaPasswordHistory: D49C27[…]077
oxDisplayName: Vorname Nachname
xmppDomain: firma.intern
krb5MaxLife: 86400
cn: Vorname Nachname
oxLanguage: de_DE
xmppEnabled: TRUE
krb5MaxRenew: 604800
isOxUser: OK
openproject-isadmin: FALSE
mail: usrname@firma.intern
sambaLogonScript: script.bat
univentionMailHomeServer: servername.firma.intern
sambaMungedDial: bQAg[…]==
loginShell: /bin/bash
univentionObjectType: users/user
oxAccess: premium
krb5KDCFlags: 126
univentionMailUserQuota: 0
displayName: Vorname Nachname
mailPrimaryAddress: Vorname.muelller@firma.de
sambaHomeDrive: H:
gecos: Vorname Nachname
sn: Nachname
pwhistory: $6$zY18frQ[…]D6QL/
homeDirectory: /home/usrname/
givenName: Vorname
gidNumber: 5001
sambaPrimaryGroupSID: S-1-5-21-226130263-146004491-3614410490-513
sambaSID: S-1-5-21-226130263-146004491-3614410490-1174
sambaHomePath: \servername.firma.intern\usrname
sambaNTPassword: 1C525[…]D30
krb5Key:: MB2hGzAZ[…]==
krb5Key:: MEuhKzAp[…]=
krb5Key:: MDuhGzAZ[…]==
krb5Key:: MDOhEzAR[…]=
krb5Key:: MDOhEzAR[…]=
krb5KeyVersionNumber: 2
userPassword:: e0[…]==
shadowLastChange: 16946
sambaPwdLastSet: 1464154943

search result

search: 3
result: 0 Success

numResponses: 2

numEntries: 1[/code]

in /opt/open-xchange/sbin/listuser -c 10 -A oxadmin -P $(< /etc/ox-secrets/context10.secret) wurde er nicht angezeigt.

Darauf hin habe ich den Nutzer gelöscht, neu angelegt und mir die /var/log/univention/listener.log angesehen und das war recht interessant.

Er versucht hier 2 exsistierende Nutzer anzulegen. Die Mailadresse (hier bestehende.mailadresse@firma.de) ist bereits einem Nutzer zugeordnet.
Vorher war die Mail einem anderen, mitlerweise gelöschtem Nutzer zugeordnet (hier veralteter_username).

Dies bricht auch mit der Meldung ab:

user in context 10 could not be created: Server response: The displayname is already used

Ist ja auch korrekt.

Danach versucht er einen immer noch bestehenden Nutzer (hier Info) anzulegen. Der Nutzer/Mail wurde “damals” mehrfach angelegt, da es sich um eine “Gemeinsame Mailadresse” handelte und wir etwas mit den verschiedenen Optionen experimentiert haben.
Dieser Versuch bricht aber hart ab:

[code]04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: new username: info
04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: new mailPrimaryAddress: info@firma.de
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
04.06.16 13:11:06.033 LISTENER ( ERROR ) : ox-user: handler failed: dn=‘uid=info,cn=users,dc=firma,dc=intern’
Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 177, in process
result = func(dn, entry.new, entry.old, entry.action)
File “/usr/lib/univention-directory-listener/system/ox-user.py”, line 365, in handler
filter = ‘(&(gidNumber=%s)(objectClass=posixGroup))’ % gidnumber
UnboundLocalError: local variable ‘gidnumber’ referenced before assignment

local variable ‘gidnumber’ referenced before assignment
Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 129, in wrapper
return self.process(func)
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 177, in process
result = func(dn, entry.new, entry.old, entry.action)
File “/usr/lib/univention-directory-listener/system/ox-user.py”, line 365, in handler
filter = ‘(&(gidNumber=%s)(objectClass=posixGroup))’ % gidnumber
UnboundLocalError: local variable ‘gidnumber’ referenced before assignment
04.06.16 13:11:08.083 LISTENER ( WARN ) : handler: ox-user (failed)[/code]

Sieht für mich so aus, als ob er hier eine exception wirft bevor er den neuen Nutzer anlegen kann.

Hier noch der komplette Log für den Vorgang

[code]04.06.16 12:53:27.527 LISTENER ( PROCESS ) : dovecot: Deleted mail home of ‘vorname.nachname@firma.de’.
04.06.16 12:53:27.555 LISTENER ( PROCESS ) : samba4-idmap: removing entry for S-1-5-21-226130263-146004491-3614410490-1174
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
04.06.16 12:53:27.714 LISTENER ( PROCESS ) : ox-group: user, domain: Other_usrname, firma.de
[… wiederholt sich für alle angelegten Nutzer …]
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
04.06.16 12:55:02.430 DEBUG_INIT
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: New Object is OX-User: True
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: Old Object is OX-User: True
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: old username: veralteter_username
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: new username: veralteter_username
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: new mailPrimaryAddress: bestehende.mailadresse@firma.de
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: aliases bestehende.mailadresse@firma.de,bestehende.mailadresse@firma.intern
04.06.16 12:55:02.431 LISTENER ( PROCESS ) : ox-user: old mailPrimaryAddress: bestehende.mailadresse@firma.de
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
04.06.16 12:55:02.802 LISTENER ( PROCESS ) : ox-user: lockfilename: /var/lock/deleteuid-2038
04.06.16 12:55:02.802 LISTENER ( PROCESS ) : ox-user: Creating ox user ‘veralteter_username’
04.06.16 12:55:03.175 LISTENER ( ERROR ) : OX: failed with 103: user in context 10 could not be created:
Server response:
The displayname is already used
at com.openexchange.admin.storage.mysqlStorage.OXToolMySQLStorage.checkCreateUserData(OXToolMySQLStorage.java:2510)
at com.openexchange.admin.rmi.impl.OXUser.createUserCommon(OXUser.java:1617)
at com.openexchange.admin.rmi.impl.OXUser.create(OXUser.java:1532)
at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
at sun.rmi.transport.Transport$2.run(Transport.java:202)
at sun.rmi.transport.Transport$2.run(Transport.java:199)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:198)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:567)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:828)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(TCPTransport.java:619)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:684)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:681)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:681)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:275)
at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:252)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:161)
at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:227)
at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:179)
at com.sun.proxy.$Proxy0.create(Unknown Source)
at com.openexchange.admin.console.user.Create.maincall(Create.java:87)
at com.openexchange.admin.console.user.CreateCore.commonfunctions(CreateCore.java:133)
at com.openexchange.admin.console.user.Create.(Create.java:75)
at com.openexchange.admin.console.user.Create.main(Create.java:68)

04.06.16 12:55:03.175 LISTENER ( PROCESS ) : ox-user: transaction deferred: dn=‘uid=veralteter_username,cn=users,dc=firma,dc=intern’ [’/opt/open-xchange/sbin/createuser’, ‘–adminuser=oxadmin’, ‘–adminpass=cydL7lQ1fU’, ‘–contextid=10’, ‘–username=veralteter_username’, ‘–password=dummy’, ‘–email=bestehende.mailadresse@firma.de’, ‘–imaplogin=bestehende.mailadresse@firma.de’, ‘–aliases=bestehende.mailadresse@firma.de,bestehende.mailadresse@firma.intern’, ‘–imapserver=servername.firma.intern’, ‘–smtpserver=localhost’, ‘–mailenabled=true’, ‘–access-combination-name=oxseforucs_premium’, ‘–access-syncml=off’, ‘–access-edit-resource=off’, ‘–displayname=Vorname2 Nachname2’, ‘–title=Frau’, ‘–email1=bestehende.mailadresse@firma.de’, ‘–company=firma’, ‘–surname=Nachname2’, ‘–givenname=Vorname2’, ‘–gui_spam_filter_capabilities_enabled=true’, ‘–defaultsenderaddress=bestehende.mailadresse@firma.de’, ‘–language=de_DE’, ‘–timezone=Europe/Berlin’] returned 103: user in context 10 could not be created:
Server response:
The displayname is already used
at com.openexchange.admin.storage.mysqlStorage.OXToolMySQLStorage.checkCreateUserData(OXToolMySQLStorage.java:2510)
at com.openexchange.admin.rmi.impl.OXUser.createUserCommon(OXUser.java:1617)
at com.openexchange.admin.rmi.impl.OXUser.create(OXUser.java:1532)
at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
at sun.rmi.transport.Transport$2.run(Transport.java:202)
at sun.rmi.transport.Transport$2.run(Transport.java:199)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:198)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:567)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:828)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.access$400(TCPTransport.java:619)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:684)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$1.run(TCPTransport.java:681)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:681)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:275)
at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:252)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:161)
at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:227)
at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:179)
at com.sun.proxy.$Proxy0.create(Unknown Source)
at com.openexchange.admin.console.user.Create.maincall(Create.java:87)
at com.openexchange.admin.console.user.CreateCore.commonfunctions(CreateCore.java:133)
at com.openexchange.admin.console.user.Create.(Create.java:75)
at com.openexchange.admin.console.user.Create.main(Create.java:68)

04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: New Object is OX-User: True
04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: Old Object is OX-User: False
04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: new username: info
04.06.16 13:11:06.008 LISTENER ( PROCESS ) : ox-user: new mailPrimaryAddress: info@firma.de
UNIVENTION_DEBUG_BEGIN : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
UNIVENTION_DEBUG_END : uldap.__open host=servername.firma.intern port=7389 base=dc=firma,dc=intern
04.06.16 13:11:06.033 LISTENER ( ERROR ) : ox-user: handler failed: dn=‘uid=info,cn=users,dc=firma,dc=intern’
Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 177, in process
result = func(dn, entry.new, entry.old, entry.action)
File “/usr/lib/univention-directory-listener/system/ox-user.py”, line 365, in handler
filter = ‘(&(gidNumber=%s)(objectClass=posixGroup))’ % gidnumber
UnboundLocalError: local variable ‘gidnumber’ referenced before assignment

local variable ‘gidnumber’ referenced before assignment
Traceback (most recent call last):
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 129, in wrapper
return self.process(func)
File “/usr/lib/pymodules/python2.7/univention/ox/listener_tools.py”, line 177, in process
result = func(dn, entry.new, entry.old, entry.action)
File “/usr/lib/univention-directory-listener/system/ox-user.py”, line 365, in handler
filter = ‘(&(gidNumber=%s)(objectClass=posixGroup))’ % gidnumber
UnboundLocalError: local variable ‘gidnumber’ referenced before assignment
04.06.16 13:11:08.083 LISTENER ( WARN ) : handler: ox-user (failed)
[/code]

Edit:

Fragt sich natürlich auch warum er da alte/bestehende Nutzer anlegen möchte. Gibt es einen Cache/Queue die man da mal löschen könnte?


#4

Hi,

Ja, es gibt eine Queue. Folgendes schlage ich vor:

Queue bereinigen:
Unter /var/spool/univention-directory-listener/ox-user werden Objekte (python pickle Datei) gespeichert, bei denen es Probleme gab (z.B. wenn der open-xchange daemon beim Anlegen eines Benutzers gerade nicht lief). Dort würde ich mal schauen, ob es für die betroffenen Benutzer noch Dateien gibt und diese löschen:

/etc/init.d/univention-directory-listener stop rm /var/spool/univention-directory-listener/ox-user/1466345967.5255689621 /etc/init.d/univention-directory-listener start

OX bereinigen:
Vielleicht nochmal schauen, ob es die betroffenen Benutzer noch im OX gibt und ggf. dort auch entfernen (Achtung, das löscht auch die Maildaten):

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

Und jetzt nochmal die/den Benutzer in UCS neu anlegen.

Ich vermute, das Problem kam durch eine Kombination aus Benutzer Anlegen/Umbenennen, vielleicht auch bei nicht laufenden OX Daemon, zustande. Ich kann das aber noch nicht reproduzieren.

Bzgl. der Exception, das sieht mir wie ein Fehler im OX Listener-Modul aus .(Listener Module reagieren auf Veränderungen im UCS Verzeichnisdienst und starten dann Aktionen, z.B. legen Benutzer im OX an). Dafür werde ich einen Bug anlegen.

Viele Grüße
Felix


#5

Hallo,

vielen Dank. Das hat funktioniert! Habe die Dateien gelöscht und den Nutzer neu angelegt. Funktionierte!

In der listner.log tauchen auch keine Fehler mehr auf.

Vielen Dank!

Grüße
sela