activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Roelof Naude <roelof.na...@gmail.com>
Subject JBoss 4.2.3 MDB problem
Date Mon, 15 Mar 2010 14:17:20 GMT
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.RequestMngrBean@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.ByteSequence@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.StdServerSession@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.ByteSequence@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.ByteSequence@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.ByteSequence@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.StdServerSession@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.

Mime
View raw message