2 Replies Latest reply on Nov 23, 2004 3:04 PM by adrian.brock

    Message softening fails with multiple subscribers with same

    pra Nov 23, 2004 11:29 AM

      Hi,
      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

      • 4432 Views
      • Tags:
        • 1. Re: Message softening fails with multiple subscribers with s
          adrian.brock Nov 23, 2004 12:12 PM (in response to pra)

          This is a bug. Please report it at http://sourceforge.net/tracker/?group_id=22866&atid=376685

          I moved this check in 3.2.4 to when durable subscriptions are made because
          this just confused a lot of people.
          But if it is in the spec, it must go back in.

          Your error message also shows that you cannot have two nondurable subscriptions
          to the same topic with the same client id (the internal subscription id is no longer unique).

          It would be trivial to subclass the statemanager to reintroduce the behaviour,
          then use the new class in place of the JDBCStateManager in the config.

          import java.util.*;
import javax.jms.*;
import org.jboss.mq.sm.jdbc.JDBCStateManager;
public class MyStateManager extends JDBCStateManager
{
 private final Set loggedOnClientIds = new HashSet();

 public String checkUser(String login, String passwd) throws JMSException
 {
 String clientId = super.checkUser(login,passwd);

 if (clientId != null)
 {
 synchronized (loggedOnClientIds)
 {
 if (loggedOnClientIds.contains(clientId))
 {
 throw new JMSSecurityException
 ("The login id has an assigned client id. " +
 "That client id is already connected to the server!");
 }
 loggedOnClientIds.add(clientId);
 }
 }
 return clientId;
 }

 public void addLoggedOnClientId(String ID) throws JMSException
 {
 //Check : this ID must not be registered
 synchronized (loggedOnClientIds)
 {
 if (loggedOnClientIds.contains(ID))
 {
 throw new InvalidClientIDException("This loggedOnClientIds is already registered !");
 }
 }

 super.addLoggedOnClientId(ID);

 synchronized (loggedOnClientIds)
 {
 loggedOnClientIds.add(ID);
 }
 }

 public void removeLoggedOnClientId(String ID)
 {
 synchronized (loggedOnClientIds)
 {
 loggedOnClientIds.remove(ID);
 }
 }
}


          NOTE: I've just copied this code from jboss-3.2.3 - I have not tested or even compiled it.

            • Actions