2 Replies Latest reply on Aug 9, 2011 1:51 PM by king huang

    message not consumed by MDB in clustered JBOSS servers

    king huang Newbie

       

          

       

       

      Out application use MDB to consume message, using JBoss 5.0 app server. 3 nodes run as a cluster.

       

       

      ActiveMQ 5.4.2 using db persistence - postgresql, two ActiveMQ brokers run as Master/Slaver.

       

       

       

      Our load test put 8000 messages in each queue and we have total 4-5 queues tested in the same load test. The MDB get message from the queue and do some database access. The onMessage() method takes average 110 ms, and can be more than 10s.

       

       

       

      I see three problems in out load test.

       

       

      • 1. When all nodes are running, some messages are left in the queue and never be able to be consumed. One example is, we put 8000 message in a queue, and 7903 were consumed but the rest 97 are stay in the queue forever. If I shut down some nodes and leave one running, or bounce all the nodes, these messages finally will be consumed.

       

      • 2. . WARN level log in both jboss and ActiveMQ broker log files.

       

      WARN  (ActiveMQ Connection Executor: tcp://ucruj1:61616) Connection error occurred: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@5a6117ea[state=NORMAL mc=org.apache.activemq.ra.ActiveMQManagedConnection@2f00319d handles=0 lastUse=1312223179565 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@73e789cc context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@6607eb86 xaResource=org.apache.activemq.ra.ActiveMQManagedConnection$1@1c693201 txSync=null]

       

       

      javax.jms.JMSException: Transaction 'XID:131075:312d613164366330633a383730303a34653336656639383a373433:613164366330633a383730303a34653336656639383a373434' has not been started.

       

       

                          at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:49)

       

       

                          at org.apache.activemq.ActiveMQConnection.onAsyncException(ActiveMQConnection.java:1833)

       

       

                          at org.apache.activemq.ActiveMQConnection$2$1.run(ActiveMQConnection.java:1754)

       

       

                          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

       

       

                          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

       

       

                          at java.lang.Thread.run(Thread.java:619)

       

       

      Caused by: javax.transaction.xa.XAException: Transaction 'XID:131075:312d613164366330633a383730303a34653336656639383a373433:613164366330633a383730303a34653336656639383a373434' has not been started.

       

       

                          at org.apache.activemq.broker.TransactionBroker.getTransaction(TransactionBroker.java:290)

       

       

                          at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:211)

       

       

                          at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)

       

       

                          at org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:462)

       

       

                          at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:677)

       

       

                          at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:311)

       

       

                          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:185)

       

       

                          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:69)

       

       

                          at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)

       

       

                          at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:228)

       

       

                          at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)

       

       

                          at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:220)

       

       

                          at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:202)

       

       

                          ... 1 more

       

       

      • 3. See ERROR in jboss log:

       

      ERROR (WorkManager(2)-8) There is something wrong with the pooling?

       

       

      java.lang.IllegalStateException: afterCompletion called with wrong tx! Expected: TxSync1624544554{tx=TransactionImple < ac, BasicAction: a1d6c0c:8700:4e36ef98:6f1 status: ActionStatus.COMMITTED > wasTrackByTx=true enlisted=true}, actual: null

       

       

                     at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener$TransactionSynchronization.afterCompletion(TxConnectionManager.java:954)

       

       

                     at org.jboss.resource.connectionmanager.TransactionSynchronizer.invokeAfter(TransactionSynchronizer.java:301)

       

       

                     at org.jboss.resource.connectionmanager.TransactionSynchronizer.afterCompletion(TransactionSynchronizer.java:265)

       

       

                     at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:123)

       

       

                     at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:381)

       

       

                     at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99)

       

       

                     at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)

       

       

                     at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)

       

       

                     at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

       

       

                     at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

       

       

                     at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:464)

       

       

                     at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:343)

       

       

                     at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:259)

       

       

                     at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)

       

       

                     at $Proxy938.afterDelivery(Unknown Source)

       

       

                     at org.apache.activemq.ra.MessageEndpointProxy$MessageEndpointAlive.afterDelivery(MessageEndpointProxy.java:128)

       

       

                     at org.apache.activemq.ra.MessageEndpointProxy.afterDelivery(MessageEndpointProxy.java:69)

       

       

                     at org.apache.activemq.ra.ServerSessionImpl.afterDelivery(ServerSessionImpl.java:224)

       

       

                     at org.apache.activemq.ActiveMQSession.run(ActiveMQSession.java:897)

       

       

                     at org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)

       

       

                     at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)

       

       

                     at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)

       

       

                     at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

       

       

                     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

       

       

                     at java.lang.Thread.run(Thread.java:619)

       

       

       

      Now I only let one node run and it seems to be a work around. I still like all nodes ( at two nodes run together ) .

       

       

       

      I tried some configuration tuning to solve the problem 1.  Following the  instruction  on ActiveMQ web site, I make prefetch size as 0 ( also tried 1) ,  but some time it work, some time it don't work. So I suspect  problem 2 and 3 are the cause of problem 1.

       

       

       

      My questions:

       

      • 1. Does any one has idea how to fix the problem 1. In addition to changing the prefetch size, is there any configuration setting can contribute to this problem?

      • 2. I analyzed the log related to problem 2. I found a couple of WARN log that have the same XID. Following two lines of log have different time stamp but the XID are the identical. How XID is generated? Is it created by Jboss or ActiveMQ?

       

       

      17:07:29,753 WARN  Connection failed: javax.jms.JMSException: Transaction 'XID:131075:312d613164366330633a623561613a34653361663032343a3331366361:613164366330633a623561613a34653361663032343a3331366362' has not been started.

       

       

      ...

       

       

      17:07:29,757 WARN  Connection failed: javax.jms.JMSException: Transaction 'XID:131075:312d613164366330633a623561613a34653361663032343a3331366361:613164366330633a623561613a34653361663032343a3331366362' has not been started.

       

       

       

      Thanks in advance for your help!

       

      broker config file - activemq.xml and jboss jca config file ra.xml and activemq-jms-ds.xml are attached.

      and serverUrl in ra.xml is peremeterized. the value is failover:(tcp://ucruj1:61616,tcp://ucruj3:61616)?timeout=3000&jms.prefetchPolicy.all=0

       

       

       

      *Xueqin (King) Huang *