Bug 1011042 - MDB stops processing messages after failover from master to slave
Summary: MDB stops processing messages after failover from master to slave
Keywords:
Status: CLOSED EOL
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: JMS
Version: 6.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
: EAP 6.4.0
Assignee: Gary Tully
QA Contact: Miroslav Novak
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-09-23 14:16 UTC by Miroslav Novak
Modified: 2019-08-19 12:49 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-08-19 12:49:13 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
conf_logs.zip (740.70 KB, application/zip)
2013-09-23 14:17 UTC, Miroslav Novak
no flags Details

Description Miroslav Novak 2013-09-23 14:16:33 UTC
Description of problem:
Test scenario:
1. Start two JBoss A-MQ servers (jms1 and jms2) in master/slave topology with shared journal
2. Start EAP 6.2.0.ER1 server (mdb server) with deployed ActiveMQ RA 5.9
3. Sent 1000 messages to queue jms/queue/Q1 to jms1
4. Deploy MDB to mdb server -  MDB reads messages from Q1 and sends to Q2 in container managed transaction
5. When MDB processes messages, kill jms1 server (which is current master)
6. Wait for MDB to process all the messages and start receiver on Q2 which reads all messages

Result: 
In step 5. when jms1(master) server is killed, MDB stops processing messages and not all messages from Q1 are processed.

In mdb server log there are exceptions:
15:47:50,184 ERROR [org.apache.activemq.ra.ActiveMQEndpointWorker] (ActiveMQ Connection Executor: tcp://192.168.40.2:61616) Connection to broker failed: Could not correlate acknowledgment with dispatched message: MessageAck {commandId = 1651, responseRequired = false, ackType = 3, consumerId = ID:localhost.localdomain-35983-1379944027766-5:1:-1:2, firstMessageId = ID:localhost.localdomain-35983-1379944027766-1:1:1:1:326, lastMessageId = ID:localhost.localdomain-35983-1379944027766-1:1:1:1:326, destination = queue://Q1, transactionId = null, messageCount = 1, poisonCause = null}: javax.jms.JMSException: Could not correlate acknowledgment with dispatched message: MessageAck {commandId = 1651, responseRequired = false, ackType = 3, consumerId = ID:localhost.localdomain-35983-1379944027766-5:1:-1:2, firstMessageId = ID:localhost.localdomain-35983-1379944027766-1:1:1:1:326, lastMessageId = ID:localhost.localdomain-35983-1379944027766-1:1:1:1:326, destination = queue://Q1, transactionId = null, messageCount = 1, poisonCause = null}
	at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:357) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:426) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:408) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:508) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:329) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:184) [activemq-broker-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:288) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196) [activemq-client-5.9-SNAPSHOT.jar:5.9-SNAPSHOT]
	at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_40]

15:47:50,366 WARN  [org.apache.activemq.TransactionContext] (default-threads - 24) prepare of: XID:[131077,globalId=0000000000ffffffffffffffff7f001ffffff8a377775240465500affffffa231,branchId=0000000000ffffffffffffffff7f001ffffff8a377775240465500affffffa300000000] failed with: javax.jms.JMSException: Context is null: javax.jms.JMSException: Context is null
	at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:54)
	at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1391)
	at org.apache.activemq.TransactionContext.syncSendPacketWithInterruptionHandling(TransactionContext.java:748)
	at org.apache.activemq.TransactionContext.prepare(TransactionContext.java:451)
	at org.apache.activemq.ra.LocalAndXATransaction.prepare(LocalAndXATransaction.java:120)
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:213)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2515)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2482)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2059)
	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1481)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98)
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
	at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.afterDelivery(MessageEndpointInvocationHandler.java:72) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source) [:1.7.0_40]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_40]
	at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_40]
	at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at com.sun.proxy.$Proxy10.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:936)
	at org.apache.activemq.ra.ServerSessionImpl.run(ServerSessionImpl.java:169)
	at org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:218)
	at org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)
	at org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:806)
	at org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)
	at org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:826)
	at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_40]
	at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: java.lang.NullPointerException: Context is null
	at org.apache.activemq.broker.TransportConnection.processPrepareTransaction(TransportConnection.java:427)
	at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:98)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:329)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:184)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:288)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
	at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_40]

Attaching logs + configuration (conf_logs.zip)

Comment 1 Miroslav Novak 2013-09-23 14:17:33 UTC
Created attachment 801678 [details]
conf_logs.zip

Comment 2 Gary Tully 2014-02-17 17:34:27 UTC
have not been able to reproduce this but my test does deal with the possibility of  a failed ack commit.
see test at: https://github.com/gtully/activemq-arquillian/blob/master/javaee/mdb-tx-failover/src/test/java/org/hornetq/javaee/examples/MDBCMTTxSendRunnerTest.java

Comment 3 Gary Tully 2014-03-07 12:38:02 UTC
found a bunch of problems - full detail in https://issues.jboss.org/browse/ENTMQ-510

Comment 6 Kabir Khan 2014-11-25 16:38:47 UTC
@Gary Tully, MODIFIED is the wrong state. MODIFIED means the fix is part of the built 6.4.0. Setting to ASSIGNED, which means either someone is looking, or it failed QA.


Note You need to log in before you can comment on or make changes to this bug.