Spark/Openfire 'Unable to add contact' error with 'UserAlreadyExistsException'

Hi everyone,

I’m having issues adding a contact to my Spark Client using Openfire.

Background:

CentOS 4.5

2.6 Kernel (i386)

~]# java -version
java version "1.6.0_07"
Java™ SE Runtime Environment (build 1.6.0_07-b06)
Java HotSpot™ Client VM (build 10.0-b23, mixed mode, sharing)

Openfire 3.6.1 compiled from source with fixes/changes outlined in ****http://www.igniterealtime.org/community/thread/36093

Spark Client 2.5.8 (also tried with pidgin)

The Openfire server is using an LDAP connection to an OpenLDAP Server.

2 users can message eachother fine, the problem occurs when a user tries to add another user to the “Friends” or any group. The client exits, re-signs in then displays “Unable to add contact.”

Debug Output:

2008.11.21 20:15:54 000550 (01/05/00) - Connection #5 tested: OK
2008.11.21 20:15:54 000551 (01/05/00) - Connection #5 tested: OK
2008.11.21 20:15:54 000551 (01/05/00) - Connection #1 tested: OK
2008.11.21 20:15:54 000552 (01/05/00) - Connection #1 tested: OK

< SEARCHING FOR USER >

2008.11.21 20:16:08 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:08 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:08 LdapManager: … context created successfully, returning.
2008.11.21 20:16:08 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:08 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:08 LdapManager: … context created successfully, returning.
2008.11.21 20:16:08 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:08 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:08 LdapManager: … context created successfully, returning.
2008.11.21 20:16:08 000552 (01/05/00) - Connection #2 tested: OK
2008.11.21 20:16:08 000553 (01/05/00) - Connection #2 tested: OK

< ATTEMPTING TO ADD USER >

2008.11.21 20:16:42 LdapManager: Trying to find a user’s DN based on their username. uid: TestUser, Base DN: dc=biz-company,dc=mil…
2008.11.21 20:16:42 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:42 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:42 LdapManager: … context created successfully, returning.
2008.11.21 20:16:42 LdapManager: Starting LDAP search…
2008.11.21 20:16:42 LdapManager: … search finished
2008.11.21 20:16:42 LdapManager: Trying to find a user’s DN based on their username. uid: TestUser, Base DN: dc=biz-company,dc=mil…
2008.11.21 20:16:42 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:42 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:42 LdapManager: … context created successfully, returning.
2008.11.21 20:16:42 LdapManager: Starting LDAP search…
2008.11.21 20:16:42 LdapManager: … search finished
2008.11.21 20:16:42 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:42 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:42 LdapManager: … context created successfully, returning.
2008.11.21 20:16:42 000553 (01/05/00) - Connection #3 tested: OK
2008.11.21 20:16:42 000554 (01/05/00) - Connection #3 tested: OK
2008.11.21 20:16:42 000554 (01/05/00) - Connection #4 tested: OK
2008.11.21 20:16:42 000555 (01/05/00) - Connection #4 tested: OK
2008.11.21 20:16:52 NIOConnection: startTLS: using c2s
2008.11.21 20:16:52 000555 (01/05/00) - Connection #5 tested: OK
2008.11.21 20:16:52 000556 (01/05/00) - Connection #5 tested: OK
2008.11.21 20:16:52 LdapManager: Trying to find a user’s DN based on their username. uid: TestUser, Base DN: dc=biz-company,dc=mil…
2008.11.21 20:16:52 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:52 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:52 LdapManager: … context created successfully, returning.
2008.11.21 20:16:52 LdapManager: Starting LDAP search…
2008.11.21 20:16:52 LdapManager: … search finished
2008.11.21 20:16:52 LdapManager: In LdapManager.checkAuthentication(userDN, password), userDN is: cn=Daniel Pottumati,ou=People…
2008.11.21 20:16:52 LdapManager: Created context values, attempting to create context…
2008.11.21 20:16:53 LdapManager: … context created successfully, returning.
2008.11.21 20:16:53 AuthorizationManager: Trying Default Mapping.map(TestUser)
2008.11.21 20:16:53 DefaultAuthorizationMapping: No realm found
2008.11.21 20:16:53 AuthorizationManager: Trying Default Policy.authorize(TestUser , TestUser)
2008.11.21 20:16:53 DefaultAuthorizationPolicy: Checking authenID realm
2008.11.21 20:16:53 LdapManager: Trying to find a user’s DN based on their username. uid: TestUser, Base DN: dc=biz-company,dc=mil…
2008.11.21 20:16:53 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:53 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:53 LdapManager: … context created successfully, returning.
2008.11.21 20:16:53 LdapManager: Starting LDAP search…
2008.11.21 20:16:53 LdapManager: … search finished
2008.11.21 20:16:53 LdapManager: Trying to find a user’s DN based on their username. uid: TestUser, Base DN: dc=biz-company,dc=mil…
2008.11.21 20:16:53 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:53 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:53 LdapManager: … context created successfully, returning.
2008.11.21 20:16:53 LdapManager: Starting LDAP search…
2008.11.21 20:16:53 LdapManager: … search finished
2008.11.21 20:16:53 LdapManager: Creating a DirContext in LdapManager.getContext()…
2008.11.21 20:16:53 LdapManager: Created hashtable with context values, attempting to create context…
2008.11.21 20:16:53 LdapManager: … context created successfully, returning.
2008.11.21 20:16:53 000556 (01/05/00) - Connection #1 tested: OK
2008.11.21 20:16:53 000557 (01/05/00) - Connection #1 tested: OK
2008.11.21 20:16:57 000557 (01/05/00) - Connection #2 tested: OK
2008.11.21 20:16:57 000558 (01/05/00) - Connection #2 tested: OK
2008.11.21 20:16:57 000558 (01/05/00) - Connection #3 tested: OK
2008.11.21 20:16:57 000559 (01/05/00) - Connection #3 tested: OK

Error Output:

org.jivesoftware.openfire.handler.IQRosterHandler.handleIQ(IQRosterHandler.java: 128)] Internal server error
org.jivesoftware.openfire.user.UserAlreadyExistsException: UserToAdd@192.168.202.5
at org.jivesoftware.openfire.roster.RosterItemProvider.createItem(RosterItemProvid er.java:109)
at org.jivesoftware.openfire.roster.Roster.provideRosterItem(Roster.java:330)
at org.jivesoftware.openfire.roster.Roster.createRosterItem(Roster.java:292)
at org.jivesoftware.openfire.handler.IQRosterHandler.manageRoster(IQRosterHandler. java:226)
at org.jivesoftware.openfire.handler.IQRosterHandler.handleIQ(IQRosterHandler.java :105)
at org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:49)
at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:351)
at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:79)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:133)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived (AbstractIoFilterChain.java:570)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:185)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.lang.Thread.run(Unknown Source)

Any assistance would be much appreciated,

Thanks,

Regards,

Grant

Hi Grant,

We had the same problem after migration to the last version of Openfire. The problem was inconsistent data in the ofRoster table. We emptied the table and the problem solved. After that we have to create al relationtships again with a migration script.

Regards,

Nicolas