Re: [JBoss-user] MDB stopping and starting

Bruce Slawson Thu, 02 Oct 2003 17:07:52 -0700

Took awhile to get it to fail with TRACE logging but it finally did. I used essentially the same test conditions that you mentioned. Without trace logging I could get it to fail quickly. It seems like the delays provided by the additional logging helped somewhat. In previous tests I noticed that sometimes the message was gone after restarting JBoss.

Bruce

2003-10-02 14:48:40,388 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 wasHard=true 2003-10-02 14:48:40,388 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 wasHard=true 2003-10-02 14:48:40,388 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 2003-10-02 14:48:40,388 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 wasHard=true 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 wasHard=true 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 wasHard=true 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:QUEUE.DLQ->addMessage(mes=org.jboss.mq.SpyTextMessage { Header { jmsDestination : QUEUE.DLQ jmsDeliveryMode : 2 jmsExpiration : 0 jmsPriority : 4 jmsMessageID : ID:2-10651313203828235 jmsTimeStamp : 1065131320382 jmsCorrelationID: null jmsReplyTo : null jmsType : null jmsRedelivered : false jmsProperties : {JBOSS_ORIG_MESSAGEID=ID:25-10651313201402490, JBOSS_ORIG_DESTINATION=QUEUE.testQueue} jmsPropertiesReadWrite:false msgReadOnly : true producerClientId: ID:22 } Body { text :hello } }) 2003-10-02 14:48:40,389 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : addMessage 2003-10-02 14:48:40,390 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1], flags=67108864 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.SpySession] Unsetting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1] previous: XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1] 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1], success=true 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.SpyXAResource] Commit xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1], onePhase=true 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395295, BranchQual=1], onePhase=true 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact 2003-10-02 14:48:40,390 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : [EMAIL PROTECTED] 2003-10-02 14:48:40,391 TRACE [org.jboss.mq.SpyConnectionConsumer] SpyConnectionConsumer:QUEUE.DLQ Starting the ServerSession. 2003-10-02 14:48:40,391 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -1 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:3/906caa01132ed4e2881800fcc0e5523e subId=-2147483648 2003-10-02 14:48:40,392 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 [guest] 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 0 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:3/906caa01132ed4e2881800fcc0e5523e subId=-2147483648 2003-10-02 14:48:40,392 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 [guest] 2003-10-02 14:48:40,392 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854767573 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpySession] Setting current tx [EMAIL PROTECTED] xid=-9223372036854767573 previous: null 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpyXAResourceManager] Ack'ing message xid=-9223372036854767573 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1], flags=0 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpyXAResourceManager] Converting tx anonXid=-9223372036854767573, xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] 2003-10-02 14:48:40,393 TRACE [org.jboss.mq.SpySession] Setting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] previous: -9223372036854767573 2003-10-02 14:48:40,394 INFO [test.mdb.DLQMDBBean] ID:2-10651313203828235 2003-10-02 14:48:40,394 DEBUG [org.jboss.resource.adapter.jms.JmsSessionFactoryImpl] [EMAIL PROTECTED], [EMAIL PROTECTED], isTopic=false 2003-10-02 14:48:40,394 TRACE [org.jboss.mq.SpyXAResource] Start xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], flags=0 2003-10-02 14:48:40,394 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] 2003-10-02 14:48:40,394 TRACE [org.jboss.mq.SpySession] Setting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] previous: null 2003-10-02 14:48:40,395 TRACE [org.jboss.mq.SpyXAResourceManager] Adding xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], message=org.jboss.mq.SpyTextMessage { Header { jmsDestination : QUEUE.testQueue jmsDeliveryMode : 2 jmsExpiration : 0 jmsPriority : 4 jmsMessageID : ID:25-10651313203952492 jmsTimeStamp : 1065131320395 jmsCorrelationID: null jmsReplyTo : null jmsType : null jmsRedelivered : false jmsProperties : {JBOSS_ORIG_MESSAGEID=ID:25-10651313201402490, JBOSS_ORIG_DESTINATION=QUEUE.testQueue} jmsPropertiesReadWrite:false msgReadOnly : true producerClientId: ID:22 } Body { text :hello } } 2003-10-02 14:48:40,395 TRACE [org.jboss.mq.SpyXAResourceManager] [EMAIL PROTECTED] txState=0, sendMessages=[], ackedMessages=[] } 2003-10-02 14:48:40,395 DEBUG [org.jboss.resource.adapter.jms.JmsSession] Closing session 2003-10-02 14:48:40,395 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] Sending connection event: 1 2003-10-02 14:48:40,395 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], flags=33554432 2003-10-02 14:48:40,396 TRACE [org.jboss.mq.SpySession] Unsetting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] previous: XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] 2003-10-02 14:48:40,396 TRACE [org.jboss.mq.SpyXAResourceManager] Suppending tx xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] 2003-10-02 14:48:40,396 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1], flags=67108864 2003-10-02 14:48:40,396 TRACE [org.jboss.mq.SpySession] Unsetting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] previous: XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] 2003-10-02 14:48:40,396 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1], success=true 2003-10-02 14:48:40,397 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], flags=67108864 2003-10-02 14:48:40,397 TRACE [org.jboss.mq.SpySession] Unsetting current tx [EMAIL PROTECTED] xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] previous: null 2003-10-02 14:48:40,397 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], success=true 2003-10-02 14:48:40,397 TRACE [org.jboss.mq.SpyXAResource] Prepare xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] 2003-10-02 14:48:40,398 TRACE [org.jboss.mq.SpyXAResourceManager] Preparing xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1] 2003-10-02 14:48:40,398 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact 2003-10-02 14:48:40,398 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : [EMAIL PROTECTED] 2003-10-02 14:48:40,399 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 transaction=198764 2003-10-02 14:48:40,401 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 transaction=198764 2003-10-02 14:48:40,403 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removing message 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 transaction=198765 2003-10-02 14:48:40,404 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Removed message 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 transaction=198765 2003-10-02 14:48:40,405 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,405 TRACE [org.jboss.mq.SpyXAResource] Prepare xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] 2003-10-02 14:48:40,405 TRACE [org.jboss.mq.SpyXAResourceManager] Preparing xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2] 2003-10-02 14:48:40,405 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact 2003-10-02 14:48:40,405 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : [EMAIL PROTECTED] 2003-10-02 14:48:40,407 TRACE [org.jboss.mq.server.MessageCache] counter lock aquire 16472 2003-10-02 14:48:40,407 TRACE [org.jboss.mq.server.MessageCache] counter lock release 16472 2003-10-02 14:48:40,407 TRACE [org.jboss.mq.server.MessageCache] add lock aquire message 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] add lock aquire lruCache 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] add locks release16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] run lock aquire, validateSoftReferenceDepth 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] run lock release, validateSoftReferenceDepth 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageReference] invalidate lock aquire 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.server.MessageReference] invalidate lock relased 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,408 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] About to add message 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 transaction=198766 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire message 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire lrucache 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent locks released 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 wasHard=true 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 2003-10-02 14:48:40,409 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Inserting message 16472 msg=32877 hard NOT_STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 transaction=198766 2003-10-02 14:48:40,412 TRACE [org.jboss.mq.pm.jdbc2.PersistenceManager] Added message 16472 msg=32877 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=163397 transaction=198766 2003-10-02 14:48:40,412 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,413 TRACE [org.jboss.mq.SpyXAResource] Commit xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1], onePhase=false 2003-10-02 14:48:40,413 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=1], onePhase=false 2003-10-02 14:48:40,413 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact 2003-10-02 14:48:40,413 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : [EMAIL PROTECTED] 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 clear=true reset=true 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 clear= true reset=true 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 clear= true reset=true 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 16471 msg=8234 hard STORED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 16471 msg=8234 hard REMOVED PERSISTENT queue=QUEUE.DLQ priority=4 hashCode=12427668 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=12427668 clear= true reset=true 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.SpyXAResource] Commit xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], onePhase=false 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=whisper.local.//395301, BranchQual=2], onePhase=false 2003-10-02 14:48:40,415 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact 2003-10-02 14:48:40,416 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : [EMAIL PROTECTED] 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 16464 msg=32873 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=12414241 clear=true reset=true 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 16464 msg=32873 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=12414241 clear= true reset=true 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 16464 msg=32873 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=12414241 clear= true reset=true 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 16464 msg=32873 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=12414241 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 16464 msg=32873 hard REMOVED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=12414241 2003-10-02 14:48:40,419 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=12414241 clear= true reset=true 2003-10-02 14:48:40,420 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 16463 msg=32872 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=6411156 clear=true reset=true 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 16463 msg=32872 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=6411156 clear= true reset=true 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 16463 msg=32872 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=6411156 clear= true reset=true 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 16463 msg=32872 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=6411156 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 16463 msg=32872 hard REMOVED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=6411156 2003-10-02 14:48:40,421 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=6411156 clear= true reset=true 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : receive 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : -2147483648 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 0 2003-10-02 14:48:40,422 TRACE [org.jboss.mq.security.ServerSecurityInterceptor] Checking receive authorize on SpyDistributedConnection:ID:1/ea1186cc4f9df88f92a659019c0dd4a9 subId=-2147483648 2003-10-02 14:48:40,422 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] 2003-10-02 14:48:40,423 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : receive 2003-10-02 14:48:40,423 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire message 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 clear=true reset=true 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire lrucache 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 clear= true reset=true 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageCache] remove lock release lrucache 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 clear= true reset=true 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire 16469 msg=32875 hard STORED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageReference] clear lock relased 16469 msg=32875 hard REMOVED PERSISTENT queue=QUEUE.testQueue priority=4 hashCode=2540062 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.MessageCache] remove lock release message NOT IN CACHE hashCode=2540062 clear= true reset=true 2003-10-02 14:48:40,425 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,426 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:48:40,427 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact 2003-10-02 14:49:38,571 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000 2003-10-02 14:49:38,573 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-02 14:49:38,573 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-02 14:49:38,573 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:26 2003-10-02 14:49:38,573 TRACE [org.jboss.mq.Connection] Closed sessions 2003-10-02 14:49:38,573 DEBUG [org.jboss.mq.Connection] Notifiying the server of close 2003-10-02 14:49:38,573 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing 2003-10-02 14:49:38,573 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:26->close() 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.Connection] Disconnected from server 2003-10-02 14:49:38,574 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-02 14:49:38,574 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.Connection] Closing sessions, ClientID=ID:25 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.Connection] Closed sessions 2003-10-02 14:49:38,574 DEBUG [org.jboss.mq.Connection] Notifiying the server of close 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : connectionClosing 2003-10-02 14:49:38,574 TRACE [org.jboss.mq.server.ClientConsumer] ClientConsumer:ID:25->close() 2003-10-02 14:49:38,575 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : connectionClosing 2003-10-02 14:49:38,575 TRACE [org.jboss.mq.Connection] Stoping the ClientIL service 2003-10-02 14:49:38,575 TRACE [org.jboss.mq.Connection] Disconnected from server 2003-10-02 14:49:38,575 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:49:38,579 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:49:38,582 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:49:38,585 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:49:38,588 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:57:08,575 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000 2003-10-02 14:57:08,578 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:57:08,581 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:57:08,584 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:57:08,587 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 14:57:08,590 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:04:38,577 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000 2003-10-02 15:04:38,580 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:04:38,583 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:04:38,587 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:04:38,590 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:04:38,592 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:12:08,580 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000 2003-10-02 15:12:08,582 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:12:08,586 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:12:08,588 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:12:08,591 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:12:08,594 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=sa, password=} 2003-10-02 15:19:38,583 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000

<repeats.>

Adrian Brock wrote:

On Thu, 2003-10-02 at 05:35, Bruce Slawson wrote:

Adrian,

Looks like I'm not crazy after all. I was able to recreate the problem running your code. It looks like it has nothing to do with stopping/starting the JMS container invoker. This is what I did to recreate it.

I built your test case and created a single message using "ant send". This causes a single message to thrash back and forth between the main queue and the DLQ. All is good at this point and it will run indefinitely.

The problem occurs after additional load is put on JBoss. What happens is that the message just "disappears" and the logging messages stops. If another app is running a mildly intensive operation or something significant is hot deployed while the thrashing is occurring, it just stops. This is all the indication I get when a finder method was called that returned a dozen or so entity beans. No other messages appear after this.

2003-10-01 16:39:46,669 INFO [test.mdb.MainMDBBean] ID:23-10650515866582586 null 2003-10-01 16:39:46,674 INFO [test.mdb.MainMDBBean] ID:23-10650515866582586 1 2003-10-01 16:39:46,695 INFO [test.mdb.MainMDBBean] ID:23-10650515866582586 2 2003-10-01 16:39:46,700 WARN [org.jboss.ejb.plugins.jms.DLQHandler] Message resent too many times; sending it to DLQ; message id=ID:23-10650515866582586 2003-10-01 16:39:46,703 INFO [test.mdb.DLQMDBBean] ID:2-10650515867013092 2003-10-01 16:39:46,703 DEBUG [org.jboss.resource.adapter.jms.JmsSessionFactoryImpl] [EMAIL PROTECTED], [EMAIL PROTECTED], isTopic=false 2003-10-01 16:39:46,704 DEBUG [org.jboss.resource.adapter.jms.JmsSession] Closing session 2003-10-01 16:39:46,704 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] Sending connection event: 1 2003-10-01 16:39:46,713 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-01 16:39:46,716 INFO [test.mdb.MainMDBBean] ID:23-10650515867042587 null 2003-10-01 16:39:46,722 INFO [test.mdb.MainMDBBean] ID:23-10650515867042587 1 2003-10-01 16:39:46,729 INFO [test.mdb.MainMDBBean] ID:23-10650515867042587 2 2003-10-01 16:39:46,734 WARN [org.jboss.ejb.plugins.jms.DLQHandler] Message resent too many times; sending it to DLQ; message id=ID:23-10650515867042587 2003-10-01 16:39:46,743 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-01 16:39:46,744 INFO [test.mdb.DLQMDBBean] ID:2-10650515867353093 2003-10-01 16:39:46,744 DEBUG [org.jboss.resource.adapter.jms.JmsSessionFactoryImpl] [EMAIL PROTECTED], [EMAIL PROTECTED], isTopic=false 2003-10-01 16:39:46,744 DEBUG [org.jboss.resource.adapter.jms.JmsSession] Closing session 2003-10-01 16:39:46,744 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] Sending connection event: 1 2003-10-01 16:42:48,201 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000 2003-10-01 16:42:48,203 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-01 16:42:48,204 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-01 16:42:48,204 DEBUG [org.jboss.mq.SpySession] Session closing. 2003-10-01 16:42:48,204 DEBUG [org.jboss.mq.SpySession] Session closing.

Restarting JBoss usually causes the message to reappear and the thrashing to continue. I am running JBoss 3.2.2RC4, Java 1.4.1_01, Mac OS X 10.2.6, PowerBook G4 1Ghz, 1 GB RAM. Hardware resources shouldn't be an issue.
I managed to reproduce this after the message bounced backwards and
forwards for an hour. (I've set the deployment scanner to ScanPeriod=0
which means it is continually looping down the deploy/ folder looking
for new deployments - at "idle" jboss uses 95% cpu).
It is not a deadlock.
I've enabled TRACE logging for org.jboss.mq but it hasn't reoccured
after 3 hours. Can you try the same thing?
I'm trying two messages to see if this makes it more likely.
It sounds like the tranaction failed to commit, rebooting jboss
causes jdbc2 to recover (rollback) the incomplete transaction.
Regards,
Adrian
Bruce

-------------------------------------------------------
This sf.net email is sponsored by:ThinkGeek
Welcome to geek heaven.
http://thinkgeek.com/sf
_______________________________________________
JBoss-user mailing list
[EMAIL PROTECTED]
https://lists.sourceforge.net/lists/listinfo/jboss-user

Re: [JBoss-user] MDB stopping and starting

Reply via email to