hi all,
we are currently in the process of replacing JBoss messaging with
ActiveMQ (version 5.3.0). unfortunately we are running into a problem
related to MDB's.
the first message to the MDB is delivered and a reply is send back. the
2nd, and subsequent messages, are never delivered. a snippet from the
log file with full tracing results in:
2010-03-15 15:21:36,376 DEBUG
[org.apache.activemq.broker.region.AbstractRegion] localhost adding
destination:
topic://ActiveMQ.Advisory.Consumer.Topic.ID:segfault-34222-1268659100904-2:6:1
2010-03-15 15:21:36,384 DEBUG
[za.co.mtn.usa.server.requestmanager.RequestMngrBean] ReqMngrBean
instance [za.co.mtn.usa.server.requestmanager.requestmngrb...@630b813f]
created. Using temp reply topic
[temp-topic://ID:segfault-34222-1268659100904-2:6:1]
2010-03-15 15:21:36,423 DEBUG
[org.apache.activemq.broker.region.AbstractRegion] localhost adding
destination: topic://ActiveMQ.Advisory.Producer.Topic.topic/testNRM_Topic
2010-03-15 15:21:36,624 TRACE [org.apache.activemq.ActiveMQSession]
ID:segfault-34222-1268659100904-2:6:1 sending message:
ActiveMQObjectMessage {commandId = 0, responseRequired = false,
messageId = ID:segfault-34222-1268659100904-2:6:1:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:segfault-34222-1268659100904-2:6:1:1, destination =
topic://topic/testNRM_Topic, transactionId = null, expiration = 0,
timestamp = 1268659296596, arrival = 0, brokerInTime = 0, brokerOutTime
= 0, correlationId = 1268659296386_1, replyTo =
temp-topic://ID:segfault-34222-1268659100904-2:6:1, persistent = true,
type = null, priority = 4, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content =
org.apache.activemq.util.byteseque...@5c1f9b4a, marshalledProperties =
null, dataStructure = null, redeliveryCounter = 0, size = 0, properties
= null, readOnlyProperties = true, readOnlyBody = true, droppable = false}
2010-03-15 15:21:36,630 TRACE [org.jboss.jms.asf.StdServerSessionPool]
getting a server session
2010-03-15 15:21:36,630 TRACE [org.jboss.jms.asf.StdServerSessionPool]
using server session: org.jboss.jms.asf.stdserversess...@62787c64
2010-03-15 15:21:36,630 TRACE [org.jboss.jms.asf.StdServerSession]
starting invokes on server session
2010-03-15 15:21:36,639 TRACE [org.jboss.jms.asf.StdServerSession]
running...
2010-03-15 15:21:36,640 TRACE [org.jboss.jms.asf.StdServerSession]
onMessage running (pool, session, xaSession, useLocalTX): ,
ActiveMQSession {id=ID:segfault-34222-1268659100904-2:5:1,started=true},
null, false
2010-03-15 15:21:36,642 TRACE
[org.jboss.ejb.plugins.jms.JMSContainerInvoker] processing message:
ActiveMQObjectMessage {commandId = 7, responseRequired = true, messageId
= ID:segfault-34222-1268659100904-2:6:1:1:1, originalDestination = null,
originalTransactionId = null, producerId =
ID:segfault-34222-1268659100904-2:6:1:1, destination =
topic://topic/testNRM_Topic, transactionId = null, expiration = 0,
timestamp = 1268659296596, arrival = 0, brokerInTime = 1268659296625,
brokerOutTime = 1268659296629, correlationId = 1268659296386_1, replyTo
= temp-topic://ID:segfault-34222-1268659100904-2:6:1, persistent = true,
type = null, priority = 4, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content =
org.apache.activemq.util.byteseque...@5c1f9b4a, marshalledProperties =
null, dataStructure = null, redeliveryCounter = 0, size = 1606,
properties = null, readOnlyProperties = true, readOnlyBody = true,
droppable = false}
2010-03-15 15:21:36,654 INFO
[za.co.mtn.usa.server.nrm.NRMStaticCacheController] Registered for
notifications from Protocol Config
2010-03-15 15:21:36,654 INFO
[za.co.mtn.usa.server.nrm.NRMStaticCacheController] Registered for
notifications from Authentication Config
2010-03-15 15:21:36,662 DEBUG
[org.apache.activemq.broker.TransportConnection] Setting up new
connection: vm://localhost#14
2010-03-15 15:21:36,664 DEBUG
[org.apache.activemq.broker.region.AbstractRegion] localhost adding
consumer: ID:segfault-34222-1268659100904-2:7:-1:1 for destination:
topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
2010-03-15 15:21:36,676 DEBUG
[za.co.mtn.usa.server.config.session.ProtocolEJB] Connector =
mtn_usa/config/LocalConnector:[.101.]
2010-03-15 15:21:36,684 DEBUG
[za.co.mtn.usa.server.config.session.ProtocolEJB] Hostname = USAInternal
2010-03-15 15:21:36,686 DEBUG
[za.co.mtn.usa.server.config.session.ProtocolEJB] Found 1 pm's
2010-03-15 15:21:36,691 INFO
[za.co.mtn.usa.server.nrm.NRMStaticCacheController] Retrieving elements
for view [defaultCV]
2010-03-15 15:21:36,698 DEBUG [za.co.mtn.usa.util.protocol.AXEPool]
(USAINTERNAL_USA) Got Connector For Service - First time
2010-03-15 15:21:36,698 DEBUG [za.co.mtn.usa.util.protocol.AXEPool]
AXEPool(USAINTERNAL_USA)::performRequest -> sending [ping_pong]
2010-03-15 15:21:36,699 DEBUG [za.co.mtn.usa.util.protocol.AXEPool]
AXEPool starting external timer. Total external time [120000]
2010-03-15 15:21:36,746 DEBUG [za.co.mtn.usa.util.protocol.USAConnector]
Got command handler for ping_pong
2010-03-15 15:21:36,747 DEBUG [za.co.mtn.usa.util.protocol.AXEPool]
AXEPool(USAINTERNAL_USA)::performRequest -> receiving data done
[Messages [null]Named Messages [{pong=, time=Mon Mar 15 15:21:36 SAST
2010, server=[127.0.0.1:1099], version=6.13-SNAPSHOT_2010-03-15 11:01:40}]]
2010-03-15 15:21:36,748 DEBUG
[org.apache.activemq.broker.region.AbstractRegion] localhost adding
destination:
topic://ActiveMQ.Advisory.Producer.Topic.ID:segfault-34222-1268659100904-2:6:1
2010-03-15 15:21:36,756 TRACE [org.apache.activemq.ActiveMQSession]
ID:segfault-34222-1268659100904-2:7:1 sending message:
ActiveMQObjectMessage {commandId = 0, responseRequired = false,
messageId = ID:segfault-34222-1268659100904-2:7:1:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:segfault-34222-1268659100904-2:7:1:1, destination =
temp-topic://ID:segfault-34222-1268659100904-2:6:1, transactionId =
null, expiration = 0, timestamp = 1268659296755, arrival = 0,
brokerInTime = 0, brokerOutTime = 0, correlationId = 1268659296386_1,
replyTo = null, persistent = true, type = null, priority = 4, groupID =
null, groupSequence = 0, targetConsumerId = null, compressed = false,
userID = null, content = org.apache.activemq.util.byteseque...@a7a1258,
marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody
= true, droppable = false}
2010-03-15 15:21:36,759 TRACE
[org.apache.activemq.ActiveMQMessageConsumer]
ID:segfault-34222-1268659100904-2:6:1:1 received message:
MessageDispatch {commandId = 8, responseRequired = false, consumerId =
ID:segfault-34222-1268659100904-2:6:1:1, destination =
temp-topic://ID:segfault-34222-1268659100904-2:6:1, message =
ActiveMQObjectMessage {commandId = 5, responseRequired = true, messageId
= ID:segfault-34222-1268659100904-2:7:1:1:1, originalDestination = null,
originalTransactionId = null, producerId =
ID:segfault-34222-1268659100904-2:7:1:1, destination =
temp-topic://ID:segfault-34222-1268659100904-2:6:1, transactionId =
null, expiration = 0, timestamp = 1268659296755, arrival = 0,
brokerInTime = 1268659296756, brokerOutTime = 1268659296757,
correlationId = 1268659296386_1, replyTo = null, persistent = true, type
= null, priority = 4, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content =
org.apache.activemq.util.byteseque...@a7a1258, marshalledProperties =
null, dataStructure = null, redeliveryCounter = 0, size = 1757,
properties = null, readOnlyProperties = true, readOnlyBody = true,
droppable = false}, redeliveryCounter = 0}
2010-03-15 15:21:36,767 TRACE [org.jboss.jms.asf.StdServerSession]
Commiting the JMS transaction
2010-03-15 15:21:36,769 DEBUG [org.apache.activemq.ActiveMQSession]
ID:segfault-34222-1268659100904-2:5:1 Transaction Commit :null
2010-03-15 15:21:36,769 TRACE [org.jboss.jms.asf.StdServerSession]
onMessage done
2010-03-15 15:21:36,777 DEBUG [org.apache.activemq.TransactionContext]
Begin:TX:ID:segfault-34222-1268659100904-2:5:1
2010-03-15 15:21:36,781 DEBUG [za.co.mtn.usa.util.logging.CALogger]
Creating new CALogger instance...
2010-03-15 15:21:36,781 TRACE [org.jboss.jms.asf.StdServerSession]
recycling...
2010-03-15 15:21:36,782 TRACE [org.jboss.jms.asf.StdServerSessionPool]
recycled server session: org.jboss.jms.asf.stdserversess...@62787c64
2010-03-15 15:21:36,782 TRACE [org.jboss.jms.asf.StdServerSession]
finished run
note the <i>onMessage done</i> and following <i>TransactionContext]
Begin:TX</i>.
a new transaction is started when sending an ACK. this happens in
ActiveMQSession.java:785. for some reason i cannot find where this
transaction is supposed to be committed?
an error is logged when shutting down JBoss or undeploying the MDB:
2010-03-15 15:17:15,416 DEBUG
[org.apache.activemq.broker.TransportConnection.Service] Error occured
while processing async command: MessageAck {commandId = 9,
responseRequired = false, ackType = 3, consumerId =
ID:segfault-52712-1268658554640-2:5:-1:2, firstMessageId =
ID:segfault-52712-1268658554640-2:6:1:1:1, lastMessageId =
ID:segfault-52712-1268658554640-2:6:1:1:1, destination =
topic://topic/testNRM_Topic, transactionId = null, messageCount = 1},
exception: java.lang.IllegalArgumentException: The subscription does not
exist: ID:segfault-52712-1268658554640-2:5:-1:2
java.lang.IllegalArgumentException: The subscription does not exist:
ID:segfault-52712-1268658554640-2:5:-1:2
at
org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:363)
at
org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:470)
at
org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:194)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
at
org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:85)
at
org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:449)
at
org.apache.activemq.command.MessageAck.visit(MessageAck.java:205)
at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:297)
at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:175)
at
org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:109)
at
org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at
org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:205)
at
org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
at
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
all session are create with Session.AUTO_ACKNOWLEDGE.
anything else that i can try or additional information that will help?
regards,
roelof.
