Message softening fails with multiple subscribers with same
pra Nov 23, 2004 11:29 AMHi,
I have stumbled on the following problem with JBossMQ in 3.2.6:
org.jboss.mq.SpyJMSException: Could not store message: 77986 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=3716546; - nested throwable: (java.sql.SQLException: Invalid argument value, message from server: "Duplicate entry '42152-TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648' for key 1")
After some digging around (its quite a while since I dug around last time...) it seems as if the problem has to do with multiple subscribers having the same clientID.
Each subscribers gets an internal queue. Each such queue ads a MessageReference to the cache. When softening sets in, if several MessageReferences is softened which points to the same message, and have the same queue description string (wich is made unque through the clientID), the above will happen, since the persistence manager will try to save the message twice with the same destination string.
Should mutiple connections with the same clientID even be allowed? I do not have the 1.0.2b doc at hand, but 1.1 says: "If another connection with the same clientID is already running when this method is called, the JMS provider should detect the duplicate ID and throw an InvalidClientIDException."
Any way. Here is the debug-log wich triggers the exception described above. (We have two subscribers here with the same clientID (eventdispatcher_polopolyclien - this was a bug in out code). Follow msg 42152:
2004-11-23 16:34:29,480 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77985 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=18583231 10540 org.jboss.mq.server.ExclusiveQueue@1d9780d{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,481 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.2750086
2004-11-23 16:34:29,481 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77986 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=3716546 10540 org.jboss.mq.server.ExclusiveQueue@719b4b{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,481 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.28560156
2004-11-23 16:34:29,481 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77987 msg=42153 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=19198314 10540 org.jboss.mq.server.ExclusiveQueue@1d9780d{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,482 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.29619062
2004-11-23 16:34:29,482 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77988 msg=42153 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=6658041 10540 org.jboss.mq.server.ExclusiveQueue@719b4b{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,482 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.30678436
2004-11-23 16:34:29,482 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77989 msg=42154 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=31227254 10540 org.jboss.mq.server.ExclusiveQueue@1d9780d{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,483 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.31737342
2004-11-23 16:34:29,483 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77990 msg=42154 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=11597289 10540 org.jboss.mq.server.ExclusiveQueue@719b4b{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,483 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.32796875
2004-11-23 16:34:29,483 TRACE [org.jboss.mq.server.MessageCache] Need to soften 2 messages
2004-11-23 16:34:29,483 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 77985 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=18583231
2004-11-23 16:34:29,493 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 77985 msg=42152 hard STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=18583231
2004-11-23 16:34:29,494 TRACE [org.jboss.mq.server.BasicQueue] addMessage 77991 msg=42155 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=31504449 10540 org.jboss.mq.server.ExclusiveQueue@1d9780d{id=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648}
2004-11-23 16:34:29,495 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=0.41557813
2004-11-23 16:34:29,495 TRACE [org.jboss.mq.server.MessageCache] Need to soften 2 messages
2004-11-23 16:34:29,495 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 77986 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=3716546
2004-11-23 16:34:29,515 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.parentTraceEnabled=true
2004-11-23 16:34:29,517 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.nestedTraceEnabled=false
2004-11-23 16:34:29,518 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.detectDuplicateNesting=true
2004-11-23 16:34:29,519 DEBUG [org.jboss.mq.server.JMSDestinationManager] Exception occured, rolling back transaction:
org.jboss.mq.SpyJMSException: Could not store message: 77986 msg=42152 hard NOT_STORED PERSISTENT queue=TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648 priority=4 lateClone=false hashCode=3716546; - nested throwable: (java.sql.SQLException: Invalid argument value, message from server: "Duplicate entry '42152-TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648' for key 1")
at org.jboss.mq.pm.jdbc2.PersistenceManager.saveToStorage(PersistenceManager.java:1285)
at org.jboss.mq.server.MessageCache.saveToStorage(MessageCache.java:416)
at org.jboss.mq.server.MessageReference.makeSoft(MessageReference.java:302)
at org.jboss.mq.server.MessageCache.validateSoftReferenceDepth(MessageCache.java:363)
at org.jboss.mq.server.MessageCache.addInternal(MessageCache.java:154)
at org.jboss.mq.server.MessageCache.add(MessageCache.java:124)
at org.jboss.mq.server.JMSTopic.addMessage(JMSTopic.java:358)
at org.jboss.mq.server.JMSDestinationManager.addMessage(JMSDestinationManager.java:414)
at org.jboss.mq.server.JMSDestinationManager.transact(JMSDestinationManager.java:440)
at org.jboss.mq.server.JMSServerInterceptorSupport.transact(JMSServerInterceptorSupport.java:186)
at org.jboss.mq.security.ServerSecurityInterceptor.transact(ServerSecurityInterceptor.java:182)
at org.jboss.mq.server.TracingInterceptor.transact(TracingInterceptor.java:447)
at org.jboss.mq.server.JMSServerInvoker.transact(JMSServerInvoker.java:186)
at org.jboss.mq.il.uil2.ServerSocketManagerHandler.handleMsg(ServerSocketManagerHandler.java:166)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:358)
at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:377)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
at java.lang.Thread.run(Thread.java:534)
Caused by: java.sql.SQLException: Invalid argument value, message from server: "Duplicate entry '42152-TOPIC.polopolyCM_topic.eventdispatcher_polopolyclient.-2147483648' for key 1"
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:1905)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1109)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1203)
at com.mysql.jdbc.Connection.execSQL(Connection.java:2090)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1680)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1527)
at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:335)
at org.jboss.mq.pm.jdbc2.PersistenceManager.add(PersistenceManager.java:840)
at org.jboss.mq.pm.jdbc2.PersistenceManager.saveToStorage(PersistenceManager.java:1271)
... 17 more
"
Actually