message not consumed by MDB in clustered JBOSS servers

[king_xhuang]

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 *

[garytully]

Not sure about the transaction related errors, it may be worth flipping the 'trackByTx' attribute in JBoss.

It may be that messages are accumulating on consumers in the connection pool. Do the missing messages appear as 'inflight' on the broker, when view through JMX, jconsole or webconsole?

Configuring prefetch on the resource adapter is a little non intuitive because it is the product of two resource adapter activation spec attributes, maxMessagesPerSession and maxSessions

There is also the possibility that it can be extended, so you may want to set usePrefetchExtension=false on all destinations

http://activemq.apache.org/activation-spec-properties.html

https://issues.apache.org/jira/browse/AMQ-2651

[king_xhuang]

Thanks for your timely reply. These two links that you sent to me is really valuable, I will give them a try.

You asked me, 'Do the missing messages appear as 'inflight' on the broker, when view through JMX, jconsole or webconsole?'.

I am not sure about you question. I do can view the messages in webconsole and I wrote a java JMS client browser which also verified these messages are stay on the broker side.