JMS Troubleshooting In Weblogic
Please follow below steps to complete jms troubleshooting in weblogic servers.
1. The first debug option to be enabled is weblogic.jms.messagepath
This is the debug option that follows the flow of the JMS message through the various subsystems and is perhaps the most straightforward of the JMS message debug flags to follow. There are no details of exactly what is happening to the message. It’s recommended be used first when debugging an application, and the output is useful in that you can see the when the message is going from client to server to client, as the debugging is not verbose.
<debug-scope> <name>weblogic.jms.messagepath</name> <enabled>true</enabled> </debug-scope> <debug-jms-message-path>true</debug-jms-message-path>
A typical flow produced with this simple test looks like this:
<21-Sep-2012 16:32:58 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FEProducer: Dispatching message to BACKEND/BEDestination> The message has been received from the client by the WLS JMS front-end and being sent to the WLS JMS back-end system. <21-Sep-2012 16:32:59 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <BACKEND/BESession (id: <9223267739445403670.18>) : BACKEND/BEConsumer (id: null, sub: null) : Pushing to the frontend, message ID:<409574.1255707178970.0>> The message is being moved from the WLS JMS back-end to the WLS JMS front-end for consumption by the consumer. <21-Sep-2012 16:32:59 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FESession (id: <9223267739445403670.18>) : Pushing to the client, message ID:<409574.1255707178970.0>>
This message is being sent to the client by the WLS JMS front-end system. It is no longer in the back-end.
Next, let’s add the more complex and detailed weblogic.jms.backend debug flag. It is used to debug issues within the JMS back-end system, which is responsible for the routing, storing and manipulation of JMS messages with WLS. Basically, the back-end system is the WebLogic implementation of the JMS specification, plus proprietary additions.
<debug-scope> <name>weblogic.jms.backend</name> <enabled>true</enabled> </debug-scope>
This time the debug output is more verbose and tracks the JMS message through the WLS JMS back-end system and the interactions with the front-end System and the clients. The first thing to note, however, is that there is additional debug output on startup. JMS back-end debugging does have an impact on log files, but usually not on performance. First, let’s focus on the debug output that occurs at startup.
With the back-end debug option enabled, starting the server gives some additional information about the JMS subsystems upon startup. Notice it’s from the JMSBackEnd Debug flags.
<21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040305> <JMS service is initialized and in standby mode.> <21-Sep-2012 13:44:40 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Listening for changes to JMSServer ReceiverJMSServer>
This is a JMS server startup message. Basically it is saying that the server is starting and creating the objects that are listed in the config.xml. It appears here because the connection factory objects are being created and deployed as is seen in the next few lines.
<21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040090> <Deployed 8 default connection factories.> <21-Sep-2012 13:44:40 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Multicast socket is opened> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "DefaultXAConnectionFactory2" with its JNDI name "weblogic.jms.XAConnectionFactory2" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "MessageDrivenBeanConnectionFactory" with its JNDI name "weblogic.jms.MessageDrivenBeanConnectionFactory" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "DefaultConnectionFactory" with its JNDI name "weblogic.jms.ConnectionFactory" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "TopicConnectionFactory" with its JNDI name "javax.jms.TopicConnectionFactory" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "DefaultXAConnectionFactory" with its JNDI name "weblogic.jms.XAConnectionFactory" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "DefaultXAConnectionFactory0" with its JNDI name "weblogic.jms.XAConnectionFactory0" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "QueueConnectionFactory" with its JNDI name "javax.jms.QueueConnectionFactory" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040407> <Default connection factory "DefaultXAConnectionFactory1" with its JNDI name "weblogic.jms.XAConnectionFactory1" is started.> <21-Sep-2012 13:44:40 o'clock BST> <Info> <JMS> <BEA-040306> <JMS service is active now.>
A side note: this is from standard logging and lists the JMS objects as they are created.
<21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Listening for changes to JMSServer ReceiverJMSServer> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Creating destination: JMS_Mod!Queue on ReceiverJMSServer> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Destination JMS_Mod!Queue maximum message size 2147483647> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <New state for JMS_Mod!Queue: suspended> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Adding Queue mapping to JMS_Mod!null!JMS_Mod!Queue to table> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <New state for JMS_Mod!Queue: suspended, advertised_in_cluster_jndi> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Creating destination: JMS_Simple!StandaloneQueue on ReceiverJMSServer> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Destination JMS_Simple!StandaloneQueue maximum message size 2147483647> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <New state for JMS_Simple!StandaloneQueue: suspended> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Adding StandaloneQueue mapping to JMS_Simple!null!JMS_Simple!StandaloneQueue to table> <21-Sep-2012 13:44:49 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <New state for JMS_Simple!StandaloneQueue: suspended, advertised_in_cluster_jndi>
This next part details the actual destinations as they are created on the JMS Server. You can see the module settings being applied and then the destinations being applied.
<21-Sep-2012 13:44:50 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <About to process 0 sessionpools> <21-Sep-2012 13:44:50 o'clock BST> <Info> <JMS> <BEA-040010> <JMSServer "ReceiverJMSServer" configured no session pools.> <21-Sep-2012 13:44:50 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <0 sessionpools are created>
This is where the JMS Session Polls are registered. In this example there are none.
Now, let’s look at the debug output that occurs when we actually send a message to the system.
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FEProducer: Dispatching message to BACKEND/BEDestination> <21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Putting new message <409574.1255707543653.0> on JMS_Simple!StandaloneQueue>
The message has been received by the WLS JMS back-end system and is being made available on the queue (denoted by JMS_Module_Name!QueueName)
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Message <409574.1255707543653.0> successfully enqueued>
This indicates there were no problems in en-queuing.
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <BACKEND/BESession (id: <9223267739445403670.18>) : BACKEND/BEConsumer (id: null, sub: null) : Pushing to the frontend, message ID:<409574.1255707543653.0>> <21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Pushing TextMessage[ID:<409574.1255707543653.0>, null]. implicitAcknowledge = false>
This is more detail on the message being forwarded to the client via the WLS JMS front-end.
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FESession (id: <9223267739445403670.18>) : Pushing to the client, message ID:<409574.1255707543653.0>> <21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Starting an acknowledge request for sequence number 2>
The WLS JMS front-end has acknowledged that the message has been sent to the WLS JMS back-end. Notice the sequence number: it’s the second message to be sent to this queue since the sequence log started.
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Removing pending messages through 2>
This indicates that the message is to be deleted from the queue.
<21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Acknowledging 1 messages for JMS_Simple!StandaloneQueue> <21-Sep-2012 16:39:03 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Acknowledgement complete>
This is the final acknowledgement that the message is successfully consumed and removed from the WLS back-end.
Next, we can add the WLS JMS front-end debug, although in this example it adds very little detail.
<debug-scope> <name>weblogic.jms.frontend</name> <enabled>true</enabled> </debug-scope>
When the JMS front-end debug option is enabled, we see this output:
<21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FEProducer: Dispatching message to BACKEND/BEDestination> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Putting new message <409574.1255707957535.0> on JMS_Simple!StandaloneQueue> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSFrontEnd> <BEA-000000> <feproducer doDispatch state=1103, returnState=2, hasResults=true, weblogic.jms.backend.BEProducerSendRequest@66b8b2>
This confirms that the WLS JMS front-end successfully dispatched the message to the WLS JMS back-end.
<21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Message <409574.1255707957535.0> successfully enqueued> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <BACKEND/BESession (id: <9223267739445403670.18>) : BACKEND/BEConsumer (id: null, sub: null) : Pushing to the frontend, message ID:<409574.1255707957535.0>> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Pushing TextMessage[ID:<409574.1255707957535.0>, null]. implicitAcknowledge = false> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSMessagePath> <BEA-000000> <FRONTEND/FESession (id: <9223267739445403670.18>) : Pushing to the client, message ID:<409574.1255707957535.0>> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Starting an acknowledge request for sequence number 3> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Removing pending messages through 3> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Acknowledging 1 messages for JMS_Simple!StandaloneQueue> <21-Sep-2012 16:45:57 o'clock BST> <Debug> <JMSBackEnd> <BEA-000000> <Acknowledgement complete>
As you can see, when looking at a simple example, the JMS back-end debug gives the most useful information for examining the flow of messages within the WLS JMS subsystem. The Message Path and Front End debug options have far more limited usage.
In case of any ©Copyright or missing credits issue please check CopyRights page for faster resolutions.