Openfire

Duplicate entry 'user xxx' for key 1 -- Exposed during load testing.

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Minor Minor
  • Resolution: Fixed
  • Affects Version/s: 3.6.4
  • Fix Version/s: 3.7.2
  • Component/s: Connection Manager, Database
  • Labels:
    None
  • Environment:

    Local load testing enviro:
    WF/CM-1/MySQL on lachesis
    CM-2 on load-35
    4 Tsung Clients (151,152,155,157)

  • Acceptance Test - Add?:
    No
  • Acceptance Test - Entry:
    Hide

    A 'blocker' since 2006... Obviously not that much of a blocking issue (downgrading priority).

    Show
    A 'blocker' since 2006... Obviously not that much of a blocking issue (downgrading priority).

Description

The following Exception is showing up multiple times (with different usernames) on the console for lachesis. This seems to occur around the same time things start going downhill in the testing.

java.sql.SQLException: Duplicate entry 'user33703' for key 1
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2975)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1600)
at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1125)
at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:677)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:794)
at org.jivesoftware.wildfire.spi.PresenceManagerImpl.userUnavailable(PresenceManagerImpl.java:261)
at org.jivesoftware.wildfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:122)
at org.jivesoftware.wildfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:153)
at org.jivesoftware.wildfire.SessionManager$ClientSessionListener.onConnectionClose(SessionManager.java:1497)
at org.jivesoftware.wildfire.net.VirtualConnection.notifyCloseListeners(VirtualConnection.java:179)
at org.jivesoftware.wildfire.net.VirtualConnection.close(VirtualConnection.java:155)
at org.jivesoftware.wildfire.multiplex.ConnectionMultiplexerManager.closeClientSession(ConnectionMultiplexerManager.java:162)
at org.jivesoftware.wildfire.multiplex.MultiplexerPacketHandler.handle(MultiplexerPacketHandler.java:85)
at org.jivesoftware.wildfire.net.MultiplexerStanzaHandler.processIQ(MultiplexerStanzaHandler.java:49)
at org.jivesoftware.wildfire.net.StanzaHandler.process(StanzaHandler.java:256)
at org.jivesoftware.wildfire.net.StanzaHandler.process(StanzaHandler.java:155)
at org.jivesoftware.wildfire.net.ConnectionHandler.messageReceived(ConnectionHandler.java:83)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:703)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:54)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:62)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:186)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:54)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:231)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:286)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Timur added a comment -

Client XML to reproduce:
1. This will give you one such error log message. jivePresence database entry already exists cause user haven't been available and his offline presence wasn't deleted by PresenceManager.userAvailable()

<?xml version="1.0"?>

<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="server" >

<iq type="set" id="auth_1" to="rw12" >
<query xmlns="jabber:iq:auth">
<username>user</username>
<password>password</password>
<resource>res</resource>
</query>
</iq>

<presence type="unavailable"/>

</stream:stream>

2. This will give you two error messages. Cause first unavailable presence will be written to database. And then for two others "entry already exists"

<?xml version="1.0"?>

<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="server" >

<iq type="set" id="auth_1" to="rw12" >
<query xmlns="jabber:iq:auth">
<username>user</username>
<password>password</password>
<resource>res</resource>
</query>
</iq>

<presence type="available"/>

<presence type="unavailable">
<status> I'm gone </status>
</presence>

<presence type="unavailable">
<priority>5</priority>
</presence>

<presence type="unavailable"/>

</stream:stream>

The way to fix this issue is to change PresenceManager.INSERT_OFFLINE_PRESENCE to "REPLACE INTO jivePresence(username, offlinePresence, offlineDate) VALUES(?,?,?)". Hope that this comment was useful.

Show
Timur added a comment - Client XML to reproduce: 1. This will give you one such error log message. jivePresence database entry already exists cause user haven't been available and his offline presence wasn't deleted by PresenceManager.userAvailable() <?xml version="1.0"?> <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="server" > <iq type="set" id="auth_1" to="rw12" > <query xmlns="jabber:iq:auth"> <username>user</username> <password>password</password> <resource>res</resource> </query> </iq> <presence type="unavailable"/> </stream:stream> 2. This will give you two error messages. Cause first unavailable presence will be written to database. And then for two others "entry already exists" <?xml version="1.0"?> <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="server" > <iq type="set" id="auth_1" to="rw12" > <query xmlns="jabber:iq:auth"> <username>user</username> <password>password</password> <resource>res</resource> </query> </iq> <presence type="available"/> <presence type="unavailable"> <status> I'm gone </status> </presence> <presence type="unavailable"> <priority>5</priority> </presence> <presence type="unavailable"/> </stream:stream> The way to fix this issue is to change PresenceManager.INSERT_OFFLINE_PRESENCE to "REPLACE INTO jivePresence(username, offlinePresence, offlineDate) VALUES(?,?,?)". Hope that this comment was useful.
Hide
Permalink
Guus der Kinderen added a comment -

Exceptions like these take up about a quarter of our logs. Could you please consider bumping up the priority of this issue?

Show
Guus der Kinderen added a comment - Exceptions like these take up about a quarter of our logs. Could you please consider bumping up the priority of this issue?
Hide
Permalink
Rogue XZ added a comment -

Hi,

I was going through the discussion thread associated with this bug and had a few updates.

1. I can confirm that this issue happens for all users, not just the admin users.
2. This issue is happening if I try to access the system using Netbean's IM Module.
3. I can login via Spark (2.5.8)

Now, if I am logged in via Spark, and then try to login using the Netbeans module, I see a different error (invalid JID)

But, if I logoff spark and then attempt to login via netbeans, I see the exception stack again.

Hope this helps.

thanks,
Harsha

Show
Rogue XZ added a comment - Hi, I was going through the discussion thread associated with this bug and had a few updates. 1. I can confirm that this issue happens for all users, not just the admin users. 2. This issue is happening if I try to access the system using Netbean's IM Module. 3. I can login via Spark (2.5.8) Now, if I am logged in via Spark, and then try to login using the Netbeans module, I see a different error (invalid JID) But, if I logoff spark and then attempt to login via netbeans, I see the exception stack again. Hope this helps. thanks, Harsha
Hide
Permalink
Rogue XZ added a comment -

Quick update. This error is occurring on openfire-3.5.2-1.i386 / Sun JDK 6 / Fedora 9 box.

Show
Rogue XZ added a comment - Quick update. This error is occurring on openfire-3.5.2-1.i386 / Sun JDK 6 / Fedora 9 box.
Hide
Permalink
Guus der Kinderen added a comment -

Similar issue reported here: http://www.igniterealtime.org/community/message/200974

Show
Guus der Kinderen added a comment - Similar issue reported here: http://www.igniterealtime.org/community/message/200974
Hide
Permalink
LG added a comment -

For Oracle it is "MERGE" and not "REPLACE INTO". A previous executed DELETE statement would be compatible for all databases. One should be able to catch the exception and log only a warn message.

Show
LG added a comment - For Oracle it is "MERGE" and not "REPLACE INTO". A previous executed DELETE statement would be compatible for all databases. One should be able to catch the exception and log only a warn message.
Hide
Permalink
LG added a comment -

Openfire 371 exception is:
org.jivesoftware.openfire.spi.PresenceManagerImpl - Error storing offline presence of user: <username>
org.postgresql.util.PSQLException: ERROR: duplicate key violates unique constraint "ofpresence_pk"
...
at org.jivesoftware.openfire.spi.PresenceManagerImpl.userUnavailable(PresenceManagerImpl.java:290)
...

Show
LG added a comment - Openfire 371 exception is: org.jivesoftware.openfire.spi.PresenceManagerImpl - Error storing offline presence of user: <username> org.postgresql.util.PSQLException: ERROR: duplicate key violates unique constraint "ofpresence_pk" ... at org.jivesoftware.openfire.spi.PresenceManagerImpl.userUnavailable(PresenceManagerImpl.java:290) ...
Hide
Permalink
LG added a comment -

Patch to delete offline presence before inserting it. Tested as described with multiple "<presence type="unavailable">...</presence>" packets using Spark debug window.

Show
LG added a comment - Patch to delete offline presence before inserting it. Tested as described with multiple "<presence type="unavailable">...</presence>" packets using Spark debug window.
Hide
Permalink
Guus der Kinderen added a comment -

Your patch looks OK. There might be some concurrency issues, but that's probably true for the rest of that class too.

Show
Guus der Kinderen added a comment - Your patch looks OK. There might be some concurrency issues, but that's probably true for the rest of that class too.
Hide
Permalink
Guus der Kinderen added a comment -

Applied patch to trunk (rev 12955).

Show
Guus der Kinderen added a comment - Applied patch to trunk (rev 12955).

People

Vote (6)
Watch (4)

Dates

  • Created:
    Updated:
    Resolved:
Atlassian JIRA (v4.4.3#663-r165197) | Report a problem
Powered by a free Atlassian JIRA open source license for igniterealtime.org. Try JIRA - bug tracking software for your team.