I am working on a simple standalone application reading messages from
ActiveMQ and storing them into a database using ActiveMQ 5.7, Spring 3.1.2
(DMLC), and Bitronix Transaction manager 2.1.3. ActiveMQ logs show Unmatched
acknowledge for every message processed in a JTA transaction. Detailed
inspection shows that the JTA transaction successfully committed but after a
few milliseconds another acknowledge message is sent by ActiveMQ with
transactionId=null. Because the message was dequeued from previous JTA
transaction, ActiveMQ can not find it (Could not find Message-ID), hence
Unmatched acknowledge. Changing the JTA transaction manager to Atomikos
improved the situation and I am not getting this error when messages are
processed with commit. But, if the message is rolled back, the "hidden"
acknowledge is back, confirming the message as successfully processed, hence
the re-delivery is not working with Atomikos configuration.
Logs for bitronix:
org.apache.activemq.transaction.XATransaction DEBUG 2012-12-27 09:37:43,618
- XA Transaction new/begin :
XID:[1114926712,globalId=737072696e672d62746d00008311610003ffffffb0,branchId=737072696e672d62746d00008311614003ffffffb1]
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,619 -
in.test.queue toPageIn: 200, Inflight: 0, pagedInMessages.size 234,
enqueueCount: 2000, dequeueCount: 173
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,619 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=0, delivered=0, pending=0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,619
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%,
size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,619 -
in.test.queue toPageIn: 200, Inflight: 0, pagedInMessages.size 234,
enqueueCount: 2000, dequeueCount: 173
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,619 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=1, delivered=1, pending=0
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,620 -
Running task iteration 0 - Transport Connection to: tcp://127.0.0.1:6205
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
09:37:43,620 - ID:cslnb086-6204-1356597414434-1:1:211:1 dispatched:
ID:cslnb086-6207-1356597452449-1:1:2:1:174 - queue://in.test.queue,
dispatched: 1, inflight: 1
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,620 -
Running task iteration 1 - Transport Connection to: tcp://127.0.0.1:6205
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,620
- Run task done: Transport Connection to: tcp://127.0.0.1:6205
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
09:37:43,621 - ack:MessageAck {commandId = 2512, responseRequired = false,
ackType = 0, consumerId = ID:cslnb086-6204-1356597414434-1:1:211:1,
firstMessageId = ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId =
XID:[1114926712,globalId=737072696e672d62746d00008311610003ffffffb0,branchId=737072696e672d62746d00008311614003ffffffb1],
messageCount = 1, poisonCause = null}
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,622 -
Running task iteration 0 - queue://in.test.queue, subscriptions=1,
memory=0%, size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,622 -
in.test.queue toPageIn: 200, Inflight: 1, pagedInMessages.size 234,
enqueueCount: 2000, dequeueCount: 173
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,622 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=1, delivered=1, pending=0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,622
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%,
size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
09:37:43,624 - ack:MessageAck {commandId = 2513, responseRequired = false,
ackType = 2, consumerId = ID:cslnb086-6204-1356597414434-1:1:211:1,
firstMessageId = ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId =
XID:[1114926712,globalId=737072696e672d62746d00008311610003ffffffb0,branchId=737072696e672d62746d00008311614003ffffffb1],
messageCount = 1, poisonCause = null}
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,625 -
Running task iteration 0 - queue://in.test.queue, subscriptions=1,
memory=0%, size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,625 -
in.test.queue toPageIn: 200, Inflight: 1, pagedInMessages.size 234,
enqueueCount: 2000, dequeueCount: 173
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,625 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=1, delivered=0, pending=0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,625
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%,
size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.transaction.XATransaction DEBUG 2012-12-27 09:37:43,632
- XA Transaction prepare:
XID:[1114926712,globalId=737072696e672d62746d00008311610003ffffffb0,branchId=737072696e672d62746d00008311614003ffffffb1]
org.apache.activemq.transaction.XATransaction DEBUG 2012-12-27 09:37:43,687
- XA Transaction commit onePhase:false, xid:
XID:[1114926712,globalId=737072696e672d62746d00008311610003ffffffb0,branchId=737072696e672d62746d00008311614003ffffffb1]
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,716 -
Running task iteration 0 - queue://in.test.queue, subscriptions=1,
memory=0%, size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,717 -
in.test.queue toPageIn: 200, Inflight: 0, pagedInMessages.size 233,
enqueueCount: 2000, dequeueCount: 174
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,717 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=0, delivered=0, pending=0
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,718 -
Running task iteration 1 - queue://in.test.queue, subscriptions=1,
memory=0%, size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,719 -
in.test.queue toPageIn: 200, Inflight: 0, pagedInMessages.size 233,
enqueueCount: 2000, dequeueCount: 174
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,719 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=0, delivered=0, pending=0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,719
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%,
size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 09:37:43,719 -
Running task iteration 0 - queue://in.test.queue, subscriptions=1,
memory=0%, size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,720 -
in.test.queue toPageIn: 200, Inflight: 0, pagedInMessages.size 233,
enqueueCount: 2000, dequeueCount: 174
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 09:37:43,720 -
Subscription full QueueSubscription:
consumer=ID:cslnb086-6204-1356597414434-1:1:211:1, destinations=1,
dispatched=0, delivered=0, pending=0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 09:37:43,721
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%,
size=1593, in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
09:37:43,721 - ack:MessageAck {commandId = 2519, responseRequired = false,
ackType = 2, consumerId = ID:cslnb086-6204-1356597414434-1:1:211:1,
firstMessageId = ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId = null, messageCount = 1, poisonCause =
null}
org.apache.activemq.broker.TransportConnection DEBUG 2012-12-27
09:37:43,722 - Error occured while processing async command: MessageAck
{commandId = 2519, responseRequired = false, ackType = 2, consumerId =
ID:cslnb086-6204-1356597414434-1:1:211:1, firstMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId = null, messageCount = 1, poisonCause =
null}, exception: javax.jms.JMSException: Unmatched acknowledge: MessageAck
{commandId = 2519, responseRequired = false, ackType = 2, consumerId =
ID:cslnb086-6204-1356597414434-1:1:211:1, firstMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId = null, messageCount = 1, poisonCause =
null}; Could not find Message-ID ID:cslnb086-6207-1356597452449-1:1:2:1:174
in dispatched-list (start of ack)
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 2519,
responseRequired = false, ackType = 2, consumerId =
ID:cslnb086-6204-1356597414434-1:1:211:1, firstMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, lastMessageId =
ID:cslnb086-6207-1356597452449-1:1:2:1:174, destination =
queue://in.test.queue, transactionId = null, messageCount = 1, poisonCause =
null}; Could not find Message-ID ID:cslnb086-6207-1356597452449-1:1:2:1:174
in dispatched-list (start of ack)
at
org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481)
at
org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206)
at
org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427)
at
org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
at
org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77)
at
org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87)
at
org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458)
at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236)
at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294)
at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152)
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:256)
at
org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
at java.lang.Thread.run(Thread.java:722)
Logs for Atomikos config:
org.apache.activemq.transaction.XATransaction DEBUG 2012-12-27 08:54:56,275
- XA Transaction new/begin :
XID:[1096044365,globalId=6c6f677365727665725f746d30303131313030303032,branchId=6c6f677365727665725f746d313036]
org.apache.activemq.broker.region.Queue DEBUG 2012-12-27 08:54:56,275 -
in.test.queue toPageIn: 0, Inflight: 0, pagedInMessages.size 1,
enqueueCount: 3, dequeueCount: 2
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 08:54:56,276 -
Running task iteration 0 - Transport Connection to: tcp://127.0.0.1:5707
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
08:54:56,277 - ID:cslnb086-5706-1356594794222-1:1:212:1 dispatched:
ID:cslnb086-5687-1356594524812-7:1:1:1:1 - queue://in.test.queue,
dispatched: 1, inflight: 1
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 08:54:56,278 -
Running task iteration 1 - Transport Connection to: tcp://127.0.0.1:5707
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 08:54:56,278
- Run task done: Transport Connection to: tcp://127.0.0.1:5707
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
08:54:56,280 - ack:MessageAck {commandId = 1078, responseRequired = false,
ackType = 0, consumerId = ID:cslnb086-5706-1356594794222-1:1:212:1,
firstMessageId = ID:cslnb086-5687-1356594524812-7:1:1:1:1, lastMessageId =
ID:cslnb086-5687-1356594524812-7:1:1:1:1, destination =
queue://in.test.queue, transactionId =
XID:[1096044365,globalId=6c6f677365727665725f746d30303131313030303032,branchId=6c6f677365727665725f746d313036],
messageCount = 1, poisonCause = null}
org.apache.activemq.thread.PooledTaskRunner DEBUG 2012-12-27 08:54:56,280 -
Running task iteration 0 - queue://in.test.queue, subscriptions=1,
memory=0%, size=0, in flight groups=active message group buckets: 0
org.apache.activemq.thread.PooledTaskRunner$1 DEBUG 2012-12-27 08:54:56,280
- Run task done: queue://in.test.queue, subscriptions=1, memory=0%, size=0,
in flight groups=active message group buckets: 0
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
08:54:56,284 - ack:MessageAck {commandId = 1079, responseRequired = false,
ackType = 2, consumerId = ID:cslnb086-5706-1356594794222-1:1:212:1,
firstMessageId = ID:cslnb086-5687-1356594524812-7:1:1:1:1, lastMessageId =
ID:cslnb086-5687-1356594524812-7:1:1:1:1, destination =
queue://in.test.queue, transactionId =
XID:[1096044365,globalId=6c6f677365727665725f746d30303131313030303032,branchId=6c6f677365727665725f746d313036],
messageCount = 1, poisonCause = null}
org.apache.activemq.transaction.XATransaction DEBUG 2012-12-27 08:54:56,286
- XA Transaction rollback:
XID:[1096044365,globalId=6c6f677365727665725f746d30303131313030303032,branchId=6c6f677365727665725f746d313036]
org.apache.activemq.broker.region.PrefetchSubscription DEBUG 2012-12-27
08:54:56,287 - ack:MessageAck {commandId = 1082, responseRequired = false,
ackType = 1, consumerId = ID:cslnb086-5706-1356594794222-1:1:212:1,
firstMessageId = ID:cslnb086-5687-1356594524812-7:1:1:1:1, lastMessageId =
ID:cslnb086-5687-1356594524812-7:1:1:1:1, destination =
queue://in.test.queue, transactionId = null, messageCount = 1, poisonCause =
null}
--
View this message in context:
http://activemq.2283324.n4.nabble.com/Duplicate-acknowledge-when-using-XA-transactions-tp4661141.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
