11 Replies Latest reply on Apr 5, 2004 4:52 AM by Adrian Brock

    Messages disappear - jboss 3.2.3

    moppersmurf Newbie

      Hi,

      JBoss version 3.2.3

      We've a system with a session bean that publishes messages on a topic. Message driven beans are subscribed to the topic. The system works fine if a approx 3 messages per seconds are posted. When more messages are posted, messages appear to disappear. They are sent to the topic but never 'reach' a message driven bean. The maximum amount of MDBs is set to 1000, much more than necessary so that shouldn't be the problem.

      If I look in the logfile, the message appears to disappear somewhere when sent to the topic.

      Directly below some loggings of a message that 'disappears'. Below that some loggings of a correctly handled message are listed. The logging 'TOPIC.testTopic->addMessage' never appears for messages that disappear. Any idea what might be the problem?

      ---- LOG
      2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
      Header {
      jmsDestination : TOPIC.testTopic
      jmsDeliveryMode : 2
      jmsExpiration : 1080818792578
      jmsPriority : 1
      jmsMessageID : ID:258-108081878257864
      jmsTimeStamp : 1080818782578
      jmsCorrelationID: null
      jmsReplyTo : null
      jmsType : null
      jmsRedelivered : false
      jmsProperties : {provider=SIM}
      jmsPropertiesReadWrite:true
      msgReadOnly : false
      producerClientId: ID:258
      }
      }
      2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
      2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778
      2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
      Principal: guest
      Principal: Roles(members:guest)
      ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
      2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778 wasHard=true
      2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageCache] add locks release6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846
      2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageCache] remove lock release message 6299 msg=1755 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=17704026 clear= false reset=false
      ...........
      ---- END LOG

      If I compare it with loggings of a messages that don't have problems, I see text in the logfile like 'TOPIC.testTopic->addMessage' which I miss for the messages that 'disappear'.

      Correctly handled message:

      ---- LOG
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
      Header {
      jmsDestination : TOPIC.testTopic
      jmsDeliveryMode : 2
      jmsExpiration : 1080818247125
      jmsPriority : 1
      jmsMessageID : ID:15-108081823712512
      jmsTimeStamp : 1080818237125
      jmsCorrelationID: null
      jmsReplyTo : null
      jmsType : null
      jmsRedelivered : false
      jmsProperties : {provider=SIM}
      jmsPropertiesReadWrite:true
      msgReadOnly : false
      producerClientId: ID:15
      }
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
      Principal: guest
      Principal: Roles(members:guest)
      ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] add lock aquire message 105 msg=37 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:4.-2147483648 priority=1 hashCode=8469194
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] add lock aquire lruCache 105 msg=37 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:4.-2147483648 priority=1 hashCode=8469194
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] add locks release105 msg=37 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:4.-2147483648 priority=1 hashCode=8469194
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] run lock aquire, validateSoftReferenceDepth
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] Need to soften 2 messages
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] soften lock acquire 104 msg=36 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=16579856
      2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock aquire 104 msg=36 hard NOT_STORED PERSISTENT

      ....

      2004-04-01 12:17:17,140 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:TOPIC.testTopic->addMessage(mes=org.jboss.mq.SpyObjectMessage {
      Header {
      jmsDestination : TOPIC.testTopic
      jmsDeliveryMode : 2
      jmsExpiration : 1080818247125
      jmsPriority : 1
      jmsMessageID : ID:15-108081823712512
      jmsTimeStamp : 1080818237125
      jmsCorrelationID: null
      jmsReplyTo : null
      jmsType : null
      jmsRedelivered : false
      jmsProperties : {provider=SIM}
      jmsPropertiesReadWrite:false
      msgReadOnly : true
      producerClientId: ID:15
      }
      ---- END LOG

        • 1. Re: JBoss MDB listening to OracleAQ queue
          Adrian Brock Master

          How todo which?

          1) Provide an alternate implemetnation to this:
          http://cvs.sourceforge.net/viewcvs.py/jboss/jboss/src/main/org/jboss/jms/jndi/JBossMQProvider.java?rev=1.9&view=auto
          2) Use this mbean to add an external context somewhere in jboss's tree
          http://cvs.sourceforge.net/viewcvs.py/jboss/jboss/src/main/org/jboss/naming/ExternalContext.java?rev=1.17&view=auto
          There are examples of (2) if you use search and avoid all the fumbling.

          Regards,
          Adrian

          • 2. Re: Messages disappear - jboss 3.2.3
            Adrian Brock Master

            You haven't posted the log all the way through to conclusion.
            You should see
            RETURN: addMessage
            when the add message has finished.

            In the second log, you have the problem that memory is tight so JBossMQ is
            pushing messages onto disk.
            2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
            What are your memory and message cache settings?

            Regards,
            Adrian

            • 3. Re: Messages disappear - jboss 3.2.3
              moppersmurf Newbie

               

              "adrian@jboss.org" wrote:
              You haven't posted the log all the way through to conclusion.
              You should see
              RETURN: addMessage
              when the add message has finished.

              In the second log, you have the problem that memory is tight so JBossMQ is
              pushing messages onto disk.
              2004-04-01 12:17:17,125 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
              What are your memory and message cache settings?

              Regards,
              Adrian


              Thanks for the fast response!

              The second log is of a message that doesn't give any problem. I posted it for the comparison. But the memory in the machine is 2GB, min is 1024 en max 1536. If I inspect the memory there is always plenty of free memory.

              The first log more complete:

              2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
              Header {
              jmsDestination : TOPIC.testTopic
              jmsDeliveryMode : 2
              jmsExpiration : 1080818792578
              jmsPriority : 1
              jmsMessageID : ID:258-108081878257864
              jmsTimeStamp : 1080818782578
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {provider=SIM}
              jmsPropertiesReadWrite:true
              msgReadOnly : false
              producerClientId: ID:258
              }
              }
              2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
              2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
              Principal: guest
              Principal: Roles(members:guest)
              ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778 wasHard=true
              2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageCache] add locks release6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846
              2004-04-01 12:26:22,578 TRACE [org.jboss.mq.server.MessageCache] remove lock release message 6299 msg=1755 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=17704026 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
              Header {
              jmsDestination : TOPIC.testTopic
              jmsDeliveryMode : 2
              jmsExpiration : 1080818792578
              jmsPriority : 1
              jmsMessageID : ID:130-108081878257897
              jmsTimeStamp : 1080818782578
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {provider=SIM}
              jmsPropertiesReadWrite:true
              msgReadOnly : false
              producerClientId: ID:130
              }
              }
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=mls-dev//176625, BranchQual=], flags=0
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock aquire, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6291 msg=1750 soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=7684703 clear=true reset=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock released 6299 msg=1755 soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=17704026
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
              Principal: guest
              Principal: Roles(members:guest)
              ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854774738, xid=XidImpl [FormatId=257, GlobalId=mls-dev//176625, BranchQual=]
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6291 msg=1750 soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=7684703 clear= true reset=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock aquire, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@a0a36 xid=XidImpl [FormatId=257, GlobalId=mls-dev//176625, BranchQual=] previous: -9223372036854774738
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6324 msg=1761 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=2355778
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.Connection] Starting connection, ClientID=ID:136
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] Using optimized 1p commit to control TX.
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Need to soften 38 messages
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : setEnabled
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message: org.jboss.mq.SpyObjectMessage {
              Header {
              jmsDestination : TOPIC.testTopic
              jmsDeliveryMode : 2
              jmsExpiration : 1080818782765
              jmsPriority : 1
              jmsMessageID : ID:132-108081877276574
              jmsTimeStamp : 1080818772765
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {provider=SIM}
              jmsPropertiesReadWrite:false
              msgReadOnly : true
              producerClientId: ID:132
              }
              }
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSessionPool] getting a server session
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] soften lock acquire 6304 msg=2272 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6291 msg=1750 soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=7684703 clear= true reset=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSessionPool] using server session: org.jboss.jms.asf.StdServerSession@216b59
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:136->setEnabled(enabled=true)
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock aquire 6304 msg=2272 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6291 msg=1750 soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=7684703
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : setEnabled
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:QUEUE.testQueue Starting the ServerSession.
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Saving message to storage 6304 msg=2272 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6291 msg=1750 soft REMOVED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=7684703
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Need to soften 38 messages
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] soften lock acquire 6304 msg=2272 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
              Header {
              jmsDestination : TOPIC.testTopic
              jmsDeliveryMode : 2
              jmsExpiration : 1080818792593
              jmsPriority : 1
              jmsMessageID : ID:136-108081878259387
              jmsTimeStamp : 1080818782593
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {provider=SIM}
              jmsPropertiesReadWrite:true
              msgReadOnly : false
              producerClientId: ID:136
              }
              }
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=7684703 clear= true reset=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] starting invokes on server session
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
              Principal: guest
              Principal: Roles(members:guest)
              ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] running...
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] onMessage done
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854774047
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] recycling...
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@1635484 xid=-9223372036854774047 previous: null
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Saved message to storage 6304 msg=2272 hard STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSessionPool] recycled server session: org.jboss.jms.asf.StdServerSession@91d7c
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:3/b1f54387dcb822beb90286e64542a365 subId=-2147483648
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResourceManager] Ack'ing message xid=-9223372036854774047
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] finished run
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6304 msg=2272 hard soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051 clear=false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
              Principal: guest
              Principal: Roles(members:guest)
              ;principal=null;roles=Roles(members:guest) for rolePrincipals [publisher, guest]
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] onMessage running (pool, session, xaSession, useLocalTX): , org.jboss.mq.SpyTopicSession@1635484, org.jboss.mq.SpyTopicSession@1635484, true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6304 msg=2272 hard soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=mls-dev//176635, BranchQual=], flags=0
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6304 msg=2272 hard soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854774047, xid=XidImpl [FormatId=257, GlobalId=mls-dev//176635, BranchQual=]
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release message 6304 msg=2272 hard soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@1635484 xid=XidImpl [FormatId=257, GlobalId=mls-dev//176635, BranchQual=] previous: -9223372036854774047
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock released 6304 msg=2272 soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.jms.asf.StdServerSession] Using optimized 1p commit to control TX.
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock aquire 6304 msg=2272 soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27689051
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939
              2004-04-01 12:26:22,593 TRACE [org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message: org.jboss.mq.SpyObjectMessage {
              Header {
              jmsDestination : QUEUE.testQueue
              jmsDeliveryMode : 2
              jmsExpiration : 1080818902328
              jmsPriority : 1
              jmsMessageID : ID:1130-10808187823281
              jmsTimeStamp : 1080818782328
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {}
              jmsPropertiesReadWrite:false
              msgReadOnly : true
              producerClientId: ID:1130
              }
              }
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock aquire, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Memory usage serverity=1.0
              Header {
              jmsDestination : QUEUE.testQueue
              jmsDeliveryMode : 2
              jmsExpiration : 1080818902328
              jmsPriority : 1
              jmsMessageID : ID:1130-10808187823281
              jmsTimeStamp : 1080818782328
              jmsCorrelationID: null
              jmsReplyTo : null
              jmsType : null
              jmsRedelivered : false
              jmsProperties : {}
              jmsPropertiesReadWrite:false
              msgReadOnly : true
              producerClientId: ID:1130
              }
              }
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] Need to soften 37 messages
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] soften lock acquire 6301 msg=1756 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] makeSoft lock aquire 6301 msg=1756 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939 wasHard=true
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6329 msg=2282 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=17987846
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6301 msg=1756 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456 clear=false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6301 msg=1756 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6301 msg=1756 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6325 msg=1762 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=32893939
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6216 msg=2243 soft STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=12680240
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] add lock aquire message 6330 msg=2283 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:4.-2147483648 priority=1 hashCode=1257809
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] remove lock release message 6301 msg=1756 hard soft STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=15703456 clear= false reset=false
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.MessageCache] add lock aquire lruCache 6330 msg=2283 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:4.-2147483648 priority=1 hashCode=1257809
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
              2004-04-01 12:26:22,593 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage

              • 4. Re: Messages disappear - jboss 3.2.3
                Adrian Brock Master

                But the default message cache size is 50M and 60M see persistence service.
                Once memory exceeds 50M you will hit the stage where jbossmq tries to move
                messages onto disk trying to keep memory below 60M.

                Regards,
                Adrian

                • 5. Re: Messages disappear - jboss 3.2.3
                  moppersmurf Newbie

                   

                  "adrian@jboss.org" wrote:
                  But the default message cache size is 50M and 60M see persistence service.
                  Once memory exceeds 50M you will hit the stage where jbossmq tries to move
                  messages onto disk trying to keep memory below 60M.

                  Regards,
                  Adrian


                  Ah, I see. I've changed the hsqldb-jdbc2-service.xml file. But I don't think that causes the disappearing messages, does it? But I'm goin to test it right now.

                  • 6. Re: Messages disappear - jboss 3.2.3
                    moppersmurf Newbie

                    I've changed the cache size settings. No memory problems are logged anymore. But the problem of the disappearing messages still exist.

                    Below a new log (hope it is not too big). The message with ID 1080826270812105 is sent to the topic, but it never seems to actually be added to the topic.


                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : addMessage
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6649 msg=1712 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=31951808 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6528 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6651 msg=1714 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6535 msg=2430 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14022169
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6640 msg=1703 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=21041004
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.SpyObjectMessage {
                    Header {
                    jmsDestination : TOPIC.testTopic
                    jmsDeliveryMode : 2
                    jmsExpiration : 1080826280812
                    jmsPriority : 1
                    jmsMessageID : ID:74-1080826270812105
                    jmsTimeStamp : 1080826270812
                    jmsCorrelationID: null
                    jmsReplyTo : null
                    jmsType : null
                    jmsRedelivered : false
                    jmsProperties : {provider=SIM}
                    jmsPropertiesReadWrite:true
                    msgReadOnly : false
                    producerClientId: ID:74
                    }
                    }
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6528 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696 clear=true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6651 msg=1714 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=14022169 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6640 msg=1703 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=21041004 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6639 msg=1702 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1045392 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                    Principal: guest
                    Principal: Roles(members:guest)
                    ;principal=null;roles=Roles(members:guest) for rolePrincipals [durpublisher, publisher, guest]
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6528 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6531 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6639 msg=1702 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1045392
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6641 msg=1704 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=16401078 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6531 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793 clear=true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6639 msg=1702 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1045392 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6642 msg=1705 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=3266284 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6531 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6641 msg=1704 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=16401078
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6643 msg=1706 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=10054231 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6642 msg=1705 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=3266284
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6644 msg=1707 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1352498 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6641 msg=1704 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=16401078 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6638 msg=1701 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=10465479 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6642 msg=1705 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=3266284 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6644 msg=1707 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1352498
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6644 msg=1707 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1352498 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6643 msg=1706 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=10054231
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6643 msg=1706 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=10054231 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6645 msg=1708 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=15091836 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6645 msg=1708 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=15091836
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6646 msg=1709 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=18147176 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6645 msg=1708 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=15091836 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6646 msg=1709 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=18147176
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6652 msg=2468 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=13821921
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6646 msg=1709 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=18147176 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6647 msg=1710 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=23590218 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6647 msg=1710 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=23590218
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6647 msg=1710 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=23590218 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6640 msg=1703 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=21041004 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6652 msg=2468 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=13821921 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6652 msg=2468 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=13821921 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6648 msg=1711 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1629012 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6648 msg=1711 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1629012
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6648 msg=1711 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1629012 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6650 msg=1713 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=8908628 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6650 msg=1713 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=8908628
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6650 msg=1713 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=8908628 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6639 msg=1702 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1045392 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6649 msg=1712 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=31951808 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6649 msg=1712 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=31951808
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6649 msg=1712 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=31951808 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6651 msg=1714 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6651 msg=1714 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 6651 msg=1714 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6528 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6528 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6528 msg=2427 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=20325696
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6531 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=20325696 clear= true reset=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6641 msg=1704 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=16401078 transaction=null
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756 wasHard=true
                    2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6531 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6631 msg=1695 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=33080756
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6652 msg=2468 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=13821921 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6531 msg=2428 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27648793
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6652 msg=2468 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=13821921
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=27648793 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSessionPool] getting a server session
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6537 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSessionPool] using server session: org.jboss.jms.asf.StdServerSession@54f169
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6530 msg=2428 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6537 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:QUEUE.testQueue Starting the ServerSession.
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=23099805 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6537 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSession] starting invokes on server session
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6532 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6537 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6532 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6537 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6642 msg=1705 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=3266284 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1072
                    2004-04-01 14:31:10,828 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6532 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6537 msg=2431 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=1359629
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSession] running...
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6532 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=1359629 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
                    2004-04-01 14:31:10,828 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854774113
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6532 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@5b55a9 xid=-9223372036854774113 previous: null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6532 msg=2429 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=26335371
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6529 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpyXAResourceManager] Ack'ing message xid=-9223372036854774113
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=26335371 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6529 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:4/0ad687b82472a8e4065fcee90572b2e8 subId=-2147483648
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6644 msg=1707 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1352498 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.security.SecurityManager] Checking authorize on subjectInfo: SubjectInfo {subject=Subject:
                    Principal: guest
                    Principal: Roles(members:guest)
                    ;principal=null;roles=Roles(members:guest) for rolePrincipals [publisher, guest]
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSession] onMessage running (pool, session, xaSession, useLocalTX): , org.jboss.mq.SpyTopicSession@5b55a9, org.jboss.mq.SpyTopicSession@5b55a9, true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=mls-dev//163373, BranchQual=], flags=0
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6529 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6529 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854774113, xid=XidImpl [FormatId=257, GlobalId=mls-dev//163373, BranchQual=]
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6534 msg=2430 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6529 msg=2427 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6534 msg=2430 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@5b55a9 xid=XidImpl [FormatId=257, GlobalId=mls-dev//163373, BranchQual=] previous: -9223372036854774113
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6529 msg=2427 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=3510804
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6534 msg=2430 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6645 msg=1708 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=15091836 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=3510804 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6533 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563
                    2004-04-01 14:31:10,828 TRACE [org.jboss.jms.asf.StdServerSession] Using optimized 1p commit to control TX.
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6534 msg=2430 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message: org.jboss.mq.SpyObjectMessage {
                    Header {
                    jmsDestination : QUEUE.testQueue
                    jmsDeliveryMode : 2
                    jmsExpiration : 0
                    jmsPriority : 4
                    jmsMessageID : ID:21-108082626876547
                    jmsTimeStamp : 1080826268765
                    jmsCorrelationID: null
                    jmsReplyTo : null
                    jmsType : null
                    jmsRedelivered : false
                    jmsProperties : {}
                    jmsPropertiesReadWrite:false
                    msgReadOnly : true
                    producerClientId: ID:21
                    }
                    }
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6533 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6533 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6534 msg=2430 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6533 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6533 msg=2429 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6533 msg=2429 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=14188563
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6643 msg=1706 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=10054231 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6534 msg=2430 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28109086
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=28109086 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6536 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=14188563 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6536 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6541 msg=2433 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6536 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6541 msg=2433 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434 clear=true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360 wasHard=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6541 msg=2433 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 6632 msg=1696 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=24894360
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6536 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255 clear= true reset=true
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6647 msg=1710 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=23590218 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6648 msg=1711 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=1629012 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6646 msg=1709 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=18147176 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6649 msg=1712 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=31951808 transaction=null
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,828 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6650 msg=1713 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=8908628 transaction=null
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 6651 msg=1714 hard STORED PERSISTENT queue=QUEUE.testQueue priority=1 hashCode=30726959 transaction=null
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:10,843 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6536 msg=2431 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6541 msg=2433 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434 clear= true reset=true
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1076
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1073
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1074
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,015 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1075
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1078
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1079
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1077
                    2004-04-01 14:31:11,031 TRACE [org.jboss.jms.asf.StdServerSessionPool] getting a server session
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6536 msg=2431 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=12220255
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6541 msg=2433 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1081
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1082
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1080
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1083
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1084
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:1085
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.jms.asf.StdServerSessionPool] using server session: org.jboss.jms.asf.StdServerSession@17aaa0e
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=12220255 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6541 msg=2433 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=27947434
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.SpySession] Session closing.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:QUEUE.testQueue Starting the ServerSession.
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6538 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=27947434 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Closed sessions
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.referenceable.SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
                    2004-04-01 14:31:11,031 TRACE [org.jboss.jms.asf.StdServerSession] starting invokes on server session
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6538 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382 clear=true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6539 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=28993973
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 DEBUG [org.jboss.mq.Connection] Notifiying the server of close
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Connection Initializing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive
                    2004-04-01 14:31:11,031 TRACE [org.jboss.jms.asf.StdServerSession] running...
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6538 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 6539 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=28993973 clear=true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Getting the serverIL
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854774112
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6538 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 6539 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=28993973 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] serverIL=org.jboss.mq.il.jvm.JVMServerIL@59c8b5
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.SpySession] Setting current tx org.jboss.mq.SpyTopicSession@2ee7e5 xid=-9223372036854774112 previous: null
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6538 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 6539 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=28993973 clear= true reset=true
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Authenticating
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:4/0ad687b82472a8e4065fcee90572b2e8 subId=-2147483648
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.SpyXAResourceManager] Ack'ing message xid=-9223372036854774112
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 6538 msg=2432 hard REMOVED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=28359382
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 6539 msg=2432 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:1.-2147483648 priority=1 hashCode=28993973
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server
                    2004-04-01 14:31:11,031 TRACE [org.jboss.mq.Connection] Disconnected from server

                    • 7. Re: Messages disappear - jboss 3.2.3
                      Adrian Brock Master

                      This looks like the cause of your problem:

                      2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805

                      The message is passing its TTL (time to live). Which is 10 seconds by the looks of it.

                      You might also try your test using 3.2.4RC1 which has a lot more TRACE
                      logging so you can see what is happening.

                      Regards,
                      Adrian

                      • 8. Re: Messages disappear - jboss 3.2.3
                        moppersmurf Newbie

                         

                        "adrian@jboss.org" wrote:
                        This looks like the cause of your problem:

                        2004-04-01 14:31:10,812 TRACE [org.jboss.mq.server.BasicQueue] message expired: 6530 msg=2428 hard NOT_STORED PERSISTENT queue=TOPIC.testTopic.ID:3.-2147483648 priority=1 hashCode=23099805

                        The message is passing its TTL (time to live). Which is 10 seconds by the looks of it.

                        You might also try your test using 3.2.4RC1 which has a lot more TRACE
                        logging so you can see what is happening.

                        Regards,
                        Adrian


                        But why does it expire and is it not handled by a MDB? There are al lot of MDB resources available.

                        • 9. Re: Messages disappear - jboss 3.2.3
                          moppersmurf Newbie

                          I did some tests, one with a time-to-live of 20 seconds and one with a time-to-live of 120 seconds. When the time-to-live is 120 seconds all requests (approx. 1600 in 8 minutes) are handled by a MDB. But with 20 seconds approx 25% expire on the topic and are therfore never handled by a MDB.
                          I configured that 1000 MDBs can exist. This should be more than enough considering the fact that one request is handled by a MDB in 2 seconds.

                          Any idea why 25% never get handled by a MDB with a time-to-live of 20 seconds? is the JMS provider not capable of handling more than 3 messages sent to a topic? Or does it take some time for the MDBs to return to the pool?

                          • 10. Re: Messages disappear - jboss 3.2.3
                            moppersmurf Newbie

                             

                            "adrian@jboss.org" wrote:
                            You haven't posted your configuration that shows you have 1000 mdbs.

                            Most likely you have configured the pool and not the most important part
                            which is the serversession pool (default size 15).
                            See the FAQ topic for some examples.


                            <invoker-proxy-binding>
                            message-driven-bean
                            <invoker-mbean>default</invoker-mbean>
                            <proxy-factory>org.jboss.ejb.plugins.jms.JMSContainerInvoker</proxy-factory>
                            <proxy-factory-config>
                            DefaultJMSProvider
                            StdJMSPool
                            1000
                            1
                            ...
                            and

                            <container-configuration>
                            <container-name>Standard Message Driven Bean</container-name>
                            ...
                            <container-pool-conf>
                            1000
                            </container-pool-conf>
                            ...

                            "adrian@jboss.org" wrote:

                            Even so, it depends what your MDB does. You only have so much cpu.
                            If it takes .5 seconds of cpu to process a request that is 20 requests in 10 seconds
                            for one cpu (and I assume nothing else is using cpu).

                            Regards,
                            Adrian


                            The CPU usage at the time of testing is approx. 15-25%.

                            • 11. Re: Messages disappear - jboss 3.2.3
                              Adrian Brock Master

                              So show me where it is spending the time.

                              We could be here until the end of the world trying to guess what is happening.

                              If you don't have a profiler, a quick and dirty is to take a couple of thread dumps
                              and look at the stacktraces. e.g. is it stuck in db operations, entity beans locks, etc.?

                              Regards,
                              Adrian