Trouble forwarding from MDB to remote Q
paulbandler Feb 27, 2003 3:06 AMFolks,
I am trying to develop a 'Forwarding' MDB who's task it is to reliably on-forward a message from a local Q to a Q on a different (normally remote) JBoss instance. I'm using a configuration of the JCA based JMS Resource Adapter to provide connections to the other JBoss instance - I _think_ I've understood how to do this and after much trial and error my Forwarding MDB can be seen to establish a connection with the other JBoss (and I see the trace of that connection on both sides), and the ForwardingMDB appears to send the message successfully. However there is no sign of the message appearing on the other JBoss instance.
Can anyone suggest how to best go about trouble shooting this scenario? I am not expecting that someone has the time to diagnose from my trace output, but to give some indication of where I have got to I attach some more details below - what I hope for from the forum is a suggestion of how to investigate further what is happening...
Here is the code that establishes the connection and on-sends the message - it's a hacked version of one of the JBoss examples (ch6,ex2)... (mQueue is provided via ENC configuration and is the name of Q to forward to).
private void setupPTP() throws JMSException, NamingException
{
InitialContext ic = new InitialContext();
log.debug(":setupPTP, this="+ hashCode());
conn = getConnection(ic);
session = conn.createQueueSession(false, QueueSession.AUTO_ACKNOWLEDGE);
// Now get and hold the Sink (Q).
mQueue = (Queue) ic.lookup("java:comp/env/jms/Sink");
log.debug(":setupPTP, this=" + hashCode() + "Dest Q: " + mQueue);
}
private void sendReply(String text, Queue dest)
throws JMSException
{
log.debug(":sendReply, this="+hashCode() +", dest="+dest);
// Change to use mQueue
QueueSender sender = session.createSender(mQueue);
TextMessage tm = session.createTextMessage(text);
sender.send(tm);
sender.close();
}
I've enabled JBoss TRACE on org.jboss.mq... and various other things and from the trace output I get the distinct impression that rather than the message being sent over the connection, it looks more like it's being written to a transactional persistent store. A bit odd - I include this trace below in case.
DEBUG FROM MDB CREATION - SHOWS CONNECTION TO REMOTE JBOSS BEING ESTABLISHED - there is also connection establishement trace on the other JBoss...
2003-02-26 13:28:44,320 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] ctor, this=7633640
2003-02-26 13:28:44,330 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :setMessageDrivenContext, this=7633640
2003-02-26 13:28:44,330 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :ejbCreate, this=7633640
2003-02-26 13:28:44,330 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :setupPTP, this=7633640
2003-02-26 13:28:44,350 DEBUG [org.jboss.resource.adapter.jms.JmsSessionFactoryImpl] mcf=org.jboss.resource.adapter.jms.JmsManagedConnectionFactory@18ae4571, cm=org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy@37b407, isTopic=false
2003-02-26 13:28:44,350 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] Retrieved conn: org.jboss.resource.adapter.jms.JmsSessionFactoryImpl@c5e67 using: org.jboss.resource.adapter.jms.JmsConnectionFactoryImpl@572200
2003-02-26 13:28:44,400 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: registering pool with interval 900000 old interval: 9223372036854775807
2003-02-26 13:28:44,400 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: about to notify thread: old next: 1046266574400, new next: 1046266574400
2003-02-26 13:28:44,400 DEBUG [org.jboss.jms.jndi.JBossMQProvider] connecting to remote JNDI with props: {java.naming.provider.url=localhost:1100, java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.rmi.security.manager=yes, java.naming.factory.url.pkgs=org.jboss.naming}
2003-02-26 13:28:44,400 DEBUG [org.jboss.jms.jndi.JBossMQProvider] created context: javax.naming.InitialContext@eb7b8
2003-02-26 13:28:44,480 DEBUG [org.jboss.mq.referenceable.SpyConnectionFactoryObjectFactory] Extracting SpyConnectionFactory from reference
2003-02-26 13:28:44,480 DEBUG [org.jboss.mq.referenceable.SpyConnectionFactoryObjectFactory] Extracting SpyConnectionFactory from reference
2003-02-26 13:28:44,480 DEBUG [org.jboss.mq.referenceable.SpyConnectionFactoryObjectFactory] The GenericConnectionFactory is: GenericConnectionFactory:[server=org.jboss.mq.il.oil.OILServerIL@24c414,connectionProperties={OIL_TCPNODELAY_KEY=yes, PingPeriod=60000, OIL_PORT_KEY=8092, ClientILService=org.jboss.mq.il.oil.OILClientILService, OIL_ADDRESS_KEY=192.168.1.90}]
2003-02-26 13:28:44,480 DEBUG [org.jboss.mq.referenceable.SpyConnectionFactoryObjectFactory] The GenericConnectionFactory is: GenericConnectionFactory:[server=org.jboss.mq.il.oil.OILServerIL@24c414,connectionProperties={OIL_TCPNODELAY_KEY=yes, PingPeriod=60000, OIL_PORT_KEY=8092, ClientILService=org.jboss.mq.il.oil.OILClientILService, OIL_ADDRESS_KEY=192.168.1.90}]
2003-02-26 13:28:44,490 DEBUG [org.jboss.jms.ConnectionFactoryHelper] using connection factory: org.jboss.mq.SpyConnectionFactory@4ca6b6
2003-02-26 13:28:44,490 DEBUG [org.jboss.jms.ConnectionFactoryHelper] using username/password: guest/guest
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Connection Initializing
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Connection Initializing
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Getting the serverIL
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Getting the serverIL
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Authenticating
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Authenticating
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Authenticating user guest
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.Connection] Authenticating user guest
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.il.oil.OILServerIL] Connecting to : pbandler/192.168.1.90:8092
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.il.oil.OILServerIL] Connecting to : pbandler/192.168.1.90:8092
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.il.oil.OILServerIL] Connecting with addr=pbandler/192.168.1.90, port=8092, localAddr=null, localPort=0, socketFactory=javax.net.DefaultSocketFactory@43a083
2003-02-26 13:28:44,490 TRACE [org.jboss.mq.il.oil.OILServerIL] Connecting with addr=pbandler/192.168.1.90, port=8092, localAddr=null, localPort=0, socketFactory=javax.net.DefaultSocketFactory@43a083
2003-02-26 13:28:44,500 TRACE [org.jboss.mq.Connection] Starting the clientIL service
2003-02-26 13:28:44,500 TRACE [org.jboss.mq.Connection] Starting the clientIL service
2003-02-26 13:28:44,510 DEBUG [org.jboss.mq.GenericConnectionFactory] Handing out ClientIL: org.jboss.mq.il.oil.OILClientILService
2003-02-26 13:28:44,510 DEBUG [org.jboss.mq.GenericConnectionFactory] Handing out ClientIL: org.jboss.mq.il.oil.OILClientILService
2003-02-26 13:28:44,520 DEBUG [org.jboss.mq.il.oil.OILClientILService] Waiting for the server to connect to me on port 2108
2003-02-26 13:28:44,520 DEBUG [org.jboss.mq.il.oil.OILClientILService] Waiting for the server to connect to me on port 2108
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Connection establishment successful
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Connection establishment successful
2003-02-26 13:28:44,520 DEBUG [org.jboss.jms.ConnectionFactoryHelper] created QueueConnection: org.jboss.mq.SpyConnection@7243d1
2003-02-26 13:28:44,520 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] created connection: org.jboss.mq.SpyConnection@7243d1
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Checking clientID :null
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Checking clientID :null
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Connection establishment successful
2003-02-26 13:28:44,520 TRACE [org.jboss.mq.Connection] Connection establishment successful
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854775808
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.SpyXAResourceManager] Starting tx with new xid=-9223372036854775808
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.SpySession] Current transaction id: -9223372036854775808
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.SpySession] Current transaction id: -9223372036854775808
2003-02-26 13:28:44,550 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] Using a non-XA QueueConnection. It will not be able to participate in a Global UOW
2003-02-26 13:28:44,550 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] xaQueueSession=null, queueSession=org.jboss.mq.SpyQueueSession@69aa13
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.Connection] Starting connection, ClientID=ID:4
2003-02-26 13:28:44,550 TRACE [org.jboss.mq.Connection] Starting connection, ClientID=ID:4
2003-02-26 13:28:44,560 TRACE [org.jboss.mq.Connection] PING
2003-02-26 13:28:44,560 TRACE [org.jboss.mq.Connection] PING
2003-02-26 13:28:44,560 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] transacted=true, ack=1
2003-02-26 13:28:44,570 DEBUG [org.jboss.resource.adapter.jms.JmsManagedConnection] ConnectionEvent listener added: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@52bdc7
2003-02-26 13:28:44,580 DEBUG [org.jboss.mq.referenceable.SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
2003-02-26 13:28:44,580 DEBUG [org.jboss.mq.referenceable.SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
2003-02-26 13:28:44,580 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :setupPTP, this=7633640Dest Q: QUEUE.A
2003-02-26 13:28:44,580 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 13:28:44,580 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
DEBUG STATEMENTS FROM MDB...
2003-02-26 14:59:09,002 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :onMessage, this=7633640
2003-02-26 14:59:09,002 DEBUG [com.nexagent.rmpframework.message.ForwardingMDB] :sendReply, this=7633640, dest=QUEUE.A
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Adding xid=-9223372036854775808, message=org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462715490023
jmsTimeStamp : 1046271549002
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Adding xid=-9223372036854775808, message=org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462715490023
jmsTimeStamp : 1046271549002
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] TXState=org.jboss.mq.SpyXAResourceManager$TXState@498713{ txState=0, sendMessages=[org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462661245901
jmsTimeStamp : 1046266124590
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}, org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462663357882
jmsTimeStamp : 1046266335788
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}], ackedMessages=[] }
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] TXState=org.jboss.mq.SpyXAResourceManager$TXState@498713{ txState=0, sendMessages=[org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462661245901
jmsTimeStamp : 1046266124590
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}, org.jboss.mq.SpyTextMessage {
Header {
jmsDestination : QUEUE.A
jmsDeliveryMode : 2
jmsExpiration : 0
jmsPriority : 4
jmsMessageID : ID:4-10462663357882
jmsTimeStamp : 1046266335788
jmsCorrelationID: null
jmsReplyTo : null
jmsType : null
jmsRedelivered : false
jmsPropertiesReadWrite:true
msgReadOnly : false
producerClientId: ID:4
}
Body {
text :A text msg#0processed by: 7633640
}
}], ackedMessages=[] }
DEBUG STATEMENT FROM AN ENHANCED JMSCONTAINER INVOKER => THAT THE INVOKE CALL TO MDB HAS RETURNED OKAY:
2003-02-26 14:59:09,002 DEBUG [com.nexagent.jbossext.plugin.EnhancedJMSContainerInvoker] :MDB Invocation OKAY
NOW WHAT DOES THE FOLLOWING TRACE IMPLY? IS IT THE MESSAGE BEING TIDIED UP FROM THE QUEUE SERVICED BY THE FORWARDING MDB OR IS IT EVIDENCE OF SOMETHING BEING WRITTEN TO A NEW QUEUE LOCALLY RATHER THAN REMOTELY...
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], flags=67108864
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResource] End xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], flags=67108864
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpySession] Unsetting current tx id
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpySession] Unsetting current tx id
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], success=true
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Ending xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], success=true
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], onePhase=true
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.SpyXAResourceManager] Commiting xid=XidImpl [FormatId=257, GlobalId=pbandler//4, BranchQual=], onePhase=true
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : transact
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.TransactionRequest@771eb1
2003-02-26 14:59:09,002 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : org.jboss.mq.TransactionRequest@771eb1
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock aquire
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageCache] messageReferenceUsedEvent lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released
2003-02-26 14:59:09,012 TRACE [org.jboss.mq.server.MessageReference] getMessage lock released
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageCache] remove lock aquire
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageReference] clear lock aquire
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageReference] clear lock relased
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageReference] clear lock relased
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageCache] remove lock release
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.MessageCache] remove lock release
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact
2003-02-26 14:59:09,022 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : transact
2003-02-26 14:59:45,314 TRACE [org.jboss.mq.Connection] PING
2003-02-26 14:59:45,314 TRACE [org.jboss.mq.Connection] PING
2003-02-26 14:59:45,314 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 14:59:45,314 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1046271608939
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1046271608939
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
2003-02-26 15:00:08,939 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
2003-02-26 15:00:45,322 TRACE [org.jboss.mq.Connection] PING
2003-02-26 15:00:45,322 TRACE [org.jboss.mq.Connection] PING
2003-02-26 15:00:45,322 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 15:00:45,322 TRACE [org.jboss.mq.Connection] PONG, serverIL=org.jboss.mq.il.oil.OILServerIL@552a2b
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1046271668946
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1046271668946
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
2003-02-26 15:01:08,946 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
2003-02-26 15:01:45,329 TRACE [org.jboss.mq.Connection] PING
Thanks very much for your time in reading, and maybe replying to this message?
Paul Bandler