Bug 1011042 - MDB stops processing messages after failover from master to slave
MDB stops processing messages after failover from master to slave
Status: ASSIGNED
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: JMS (Show other bugs)
6.2.0
Unspecified Unspecified
unspecified Severity high
: ---
: EAP 6.4.0
Assigned To: Gary Tully
Miroslav Novak
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-09-23 10:16 EDT by Miroslav Novak
Modified: 2017-10-09 20:22 EDT (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


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

  None (edit)
Description Miroslav Novak 2013-09-23 10:16:33 EDT
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 10:17:33 EDT
Created attachment 801678 [details]
conf_logs.zip
Comment 2 Gary Tully 2014-02-17 12:34:27 EST
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 07:38:02 EST
found a bunch of problems - full detail in https://issues.jboss.org/browse/ENTMQ-510
Comment 6 Kabir Khan 2014-11-25 11:38:47 EST
@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.