Interested about the Future of Enterprise Integration with the UltraESB ?
 

Tuesday, 29th May from 09:00 - 10:00 AM PDT, Presented by Asankha Perera, Founder and CTO of AdroitLogic

Register for the Webinar

Skip to end of metadata
Comment: Corrected links that should have been relative instead of absolute.
Go to start of metadata

It is important that you understand and learn how to verify a mediation flow, whether it has been correctly executed. While UltraESB supports step through debugging of the mediation sequences, analyzing logs is far more easy and useful in verifying the flows in the development mode as well as in production deployments, provided that you have enabled logging.

Note

While it is not recommended to have logging enabled to print much information at production deployments, any ESB should support turning debug on dynamically to detect any suspicious activities or miss-behaviours of the flow.

Before going into analyzing the logs lets look at what we see from the clients perspective of this invocation. From the client side, we see it as the client sending the following HTTP POST request to the URL http://localhost:8280/service/echo-proxy with message body;

<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://soap.services.samples/">
   <soapenv:Body>
      <soap:getQuote>
         <request>
            <symbol>ADRT</symbol>
         </request>
      </soap:getQuote>
   </soapenv:Body>
</soapenv:Envelope>

The HTTP response that is received by the client for this request is as follows;

HTTP/1.0 200 OK
port: 9000
Content-Type: text/xml; charset=utf-8
Date: Thu, 08 Sep 2011 04:58:41 GMT
Server: UltraESB/1.6.0 (GA)
Content-Length: 294
Connection: close
 
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://soap.services.samples/">
   <soapenv:Body>
      <soap:getQuote>
         <request>
            <symbol>ADRT</symbol>
         </request>
      </soap:getQuote>
   </soapenv:Body>
</soapenv:Envelope>

Now you can see that the response for this request came from UltraESB as the Server HTTP header reflects it and also note that the exact same request that the client sent has been received by the client as the response.

Now if you look at the UltraESB command line console running the server, you can see the following printed on it.

Reply payload : <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://soap.services.samples/">
   <soapenv:Body>
      <soap:getQuote>
         <request>
            <symbol>ADRT</symbol>
         </request>
      </soap:getQuote>
   </soapenv:Body>
</soapenv:Envelope>

If you map this to the previously examined echo-proxy configuration, you will realize that this is the standard output print statement in the out sequence on the response path. That verifies the out sequence has been invoked. Another major verification from an external perspective to the UltraESB is monitoring the messages at the transport layer or in other words monitor the messages on the wire.

In this particular configuration, we are using the HTTP transport, meaning that we can use the TCP dump to verify the messages coming into and going out of the UltraESB from the client to the back end service. Normal TCP dump is a bit unreadable, but Adroitlogic SOA Toolbox addresses this issue as well and provides a readable TCP dump version apart from the raw dump. The following sub section shows, how to use the toolbox to verify the messages at the transport layer.

Using SOA Toolbox TCP dump

The TCP dump of the SOA Toolbox intercepts the message in the middle, so lets change the address of the out destination endpoint in the default configuration, to http://localhost:9001/service/EchoService, note the change in the port number from 9000 to 9001, and restart the UltraESB server for these changes to be effective.

Dynamic configuration provisioning and update

UltraESB supports dynamic configuration provisioning and update of a running server without requiring to restart. It actually has zero downtime configuration update support, which we will see in a later chapter under the Configuration and Administration. For this exercise we are restarting the server to activate the update to keep it simple for the quick start.

Once the UltraESB instance configuration update and restart is done, switch back to the Toolbox window and click on the "File" menu and select the New > TCP Dump from the cascading menu, to create a new TCP Dump instance.

Then you will get the TCP Dump pane and configure the TCP dump as follows;

  1. Check the "Listen Port" to be "9001" (this defaults to 9001, if you put some other port while updating the endpoint address put it as the listen port)
  2. Check the "Forward Host" to be "localhost" (this defaults to localhost)
  3. Check the "Forward Port" to be "9000" (this defaults to 9000, which is the actual port at which the back-end server is running)
  4. Change the radio button from "Hex" to "Text", by clicking on Text, as we want to see the messages on the wire in text format.
  5. Finally click on the "Start" button to start TCP Dump to listen on port 9001 and forward the message to the 9000 and vice-versa for the response.

If you invoke the client once again (Switch to "HTTP/S Client" tab of the Toolbox and click on the "Send") you will now be able to see something like following;

This shows the message went out from the UltraESB to the back-end server, in the upper box, and the response came into the UltraESB from the back-end server, in the lower box. This trace confirms that the message actually went into the back-end server running at http://localhost:9000/service/EchoService, and our second step in verification of the back-end service is complete.

While it has been proven that from an external point of view the UltraESB acts as expected with the above investigations, the internal operation is still not transparent for the user. Changing log level to DEBUG of the UltraESB loggers serves that apart from enabling debugging of the artifacts. In this guide we will look at how to use logging while artifact debugging will be covered in the Configuration and Administration.

Enabling logging at runtime

To get an idea of the internal message execution flow of the UltraESB, we can change the log level of its loggers to DEBUG, at runtime. While the user should selectively change log level for the specific loggers, for this exercise we will change the log level at the root logger of the UltraESB.

Debug logs and Artifact debugging

Changing log level to DEBUG from INFO gives you more and more information on what is happening inside the UltraESB on the console appender. While this is useful in pointing out issues, it is not recommended to have DEBUG logs enabled as that results in a considerable performance hit, on production deployments.

Even in case of an issue, you want to figure out the execution flow, changing log level to DEBUG has to be done selectively on the required loggers, but not on the root level. If the issue is specific to a particular artifact (configuration element, like proxy service or an endpoint) it is recommended to use the artifact debugging instead of changing the log level of the loggers. More information on this aspects will be discussed in the Configuration and Administration.

There are many options available to change the log level from INFO (which is the default log level) to DEBUG of the UltraESB, out of which straight forward way of doing this at runtime is via JMX management. We will be changing the log level of the root logger (root package name of the UltraESB) which is "org.adroitlogic.ultraesb".

JConsole (Java Management and Monitoring Console) will be used as the tool to invoke JMX management beans of the UltraESB. To open up JConsole, use the jconsole command from a command line console both in Linux and Windows operating systems.

You will see a Java swing interface to connect to the UltraESB runtime. Use the "JConsole: New Connection" window to connect to the UltraESB runtime as follows;

  1. Select "Local Processes" radio button to connect to the locally running UltraESB instance
  2. Select the name "org.adroitlogic.ultraesb.UltraServer /opt/ultraesb-1.6.0/conf" from the local processes table.
  3. Click on the "Connect" button to connect to the runtime.

Now you will see the UltraESB process JConsole pane, and open the "LoggerManagement" operations by;

  1. Select the "MBeans" tab to navigate the registered JMX management beans
  2. Expand the "org.adroitlogic.ultraesb" MBean group.
  3. Expand the "LoggerManagement" MBean view.
  4. Click on the "Operations" to open up the operation invocation pane of the LoggerManagement MBean.

Now use the "changeLogLevel" operation to change the log level of the root logger to "DEBUG".

  1. Type "org,adroitlogic.ultraesb" for the p0 argument of the "changeLogLevel" method.
  2. Type "DEBUG" for the p1 argument of the "changeLogLevel" method.
  3. Click on the "changeLogLevel" button to invoke the operation.

If the operation is successful you will see the following message box.

This invocation changed the log level of the root logger to DEBUG, and now you should see the debug logs, on the command line console, if you invoke the client back again.

2011-09-10 20:35:41,110 [-] [L-I/O dispatcher 4] DEBUG HttpNIOListener$EventLogger Connection open: 127.0.0.1:43663->127.0.0.1:8280 Total : 1
2011-09-10 20:35:41,111 [-] [L-I/O dispatcher 4] DEBUG fileCache Served a file from cache : pooled_6.tmp total cache size : 200 available pool size : 199 peak usage : 2
2011-09-10 20:35:41,111 [-] [L-I/O dispatcher 4] DEBUG RequestHandler ==> begin request entity receive
2011-09-10 20:35:41,111 [-] [L-I/O dispatcher 4] DEBUG RequestHandler ==> contentAvailable() :: transferred : 294
2011-09-10 20:35:41,111 [-] [L-I/O dispatcher 4] DEBUG RequestHandler handle() http request received
2011-09-10 20:35:41,112 [-] [L-I/O dispatcher 4] DEBUG MessageImpl Created message with UUID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054
2011-09-10 20:35:41,112 [-] [primary-7] DEBUG echo-proxy Proxy service : echo-proxy processing message with destination : /service/echo-proxy and UUID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054
2011-09-10 20:35:41,112 [-] [primary-7] DEBUG HttpNIOSender A new connection will be opened to : localhost on port : 9001
2011-09-10 20:35:41,113 [-] [primary-7] DEBUG MessageImpl Message ID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054 has completed processing under : echo-proxy Pending completion by : [[echo-proxy-inDestination]]
2011-09-10 20:35:41,114 [-] [primary-7] DEBUG echo-proxy Processing of message completed for proxy service : echo-proxy in state : Started current execution count : 0 current polling count : 0
2011-09-10 20:35:41,114 [-] [S-I/O dispatcher 4] DEBUG HttpNIOSender$EventLogger Connection open: 127.0.0.1:17229->127.0.0.1:9001
2011-09-10 20:35:41,115 [-] [S-I/O dispatcher 4] DEBUG CustomAsyncNHttpClientHandler encoder has completed - marking send as complete for : 127.0.0.1:17229->127.0.0.1:9001
2011-09-10 20:35:41,184 [-] [S-I/O dispatcher 4] DEBUG fileCache Served a file from cache : pooled_7.tmp total cache size : 200 available pool size : 198 peak usage : 2
2011-09-10 20:35:41,184 [-] [S-I/O dispatcher 4] DEBUG ResponseHandler ==> begin response entity receive
2011-09-10 20:35:41,184 [-] [S-I/O dispatcher 4] DEBUG ResponseHandler ==> contentAvailable() :: transferred : 294
2011-09-10 20:35:41,185 [-] [S-I/O dispatcher 4] DEBUG ResponseHandler handle() response received
2011-09-10 20:35:41,185 [-] [S-I/O dispatcher 4] DEBUG MessageImpl Created response message with UUID : f88f6913-314d-4989-b55b-704cf3a61164
2011-09-10 20:35:41,185 [-] [S-I/O dispatcher 4] DEBUG MessageImpl Message ID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054 has completed processing under : echo-proxy-inDestination Pending completion by : [[]]
2011-09-10 20:35:41,185 [-] [S-I/O dispatcher 4] DEBUG MessageImpl a5fd2de2-71e3-4908-9f9b-b0daa3b61054 released
2011-09-10 20:35:41,185 [-] [S-I/O dispatcher 4] DEBUG SimpleQueueWorkManager Message ID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054 has completed processing and is removed from the WIP map
2011-09-10 20:35:41,186 [-] [S-I/O dispatcher 4] DEBUG fileCache Returned file for re-use : pooled_6.tmp pool size : 199
2011-09-10 20:35:41,186 [-] [S-I/O dispatcher 4] DEBUG MessageImpl Message ID : a5fd2de2-71e3-4908-9f9b-b0daa3b61054 has completed all processing
2011-09-10 20:35:41,186 [-] [S-I/O dispatcher 4] DEBUG ClientConnectionReuseStrategy connection will be kept alive
2011-09-10 20:35:41,186 [-] [primary-8] DEBUG echo-proxy Proxy service : echo-proxy processing message with destination : null and UUID : f88f6913-314d-4989-b55b-704cf3a61164
2011-09-10 20:35:41,186 [-] [S-I/O dispatcher 4] DEBUG ConnectionManager Released a connection to host: localhost on port : 9001 to the connection pool for that host/port of size : 1
2011-09-10 20:35:41,186 [-] [primary-8] DEBUG echo-proxy-outSequence Executing sequence : echo-proxy-outSequence
Reply payload : <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soap="http://soap.services.samples/">
   <soapenv:Body>
      <soap:getQuote>
         <request>
            <symbol>ADRT</symbol>
         </request>
      </soap:getQuote>
   </soapenv:Body>
</soapenv:Envelope>
2011-09-10 20:35:41,187 [-] [primary-8] DEBUG MessageImpl Message ID : f88f6913-314d-4989-b55b-704cf3a61164 has completed processing under : echo-proxy-outSequence Pending completion by : [[echo-proxy]]
2011-09-10 20:35:41,187 [-] [primary-8] DEBUG echo-proxy-outSequence Finished executing sequence : echo-proxy-outSequence
2011-09-10 20:35:41,188 [-] [primary-8] DEBUG MessageImpl Message ID : f88f6913-314d-4989-b55b-704cf3a61164 has completed processing under : echo-proxy Pending completion by : [[echo-proxy-outDestination]]
2011-09-10 20:35:41,188 [-] [primary-8] DEBUG echo-proxy Processing of message completed for proxy service : echo-proxy in state : Started current execution count : 0 current polling count : 0
2011-09-10 20:35:41,188 [-] [L-I/O dispatcher 4] DEBUG MessageImpl Message ID : f88f6913-314d-4989-b55b-704cf3a61164 has completed processing under : echo-proxy-outDestination Pending completion by : [[]]
2011-09-10 20:35:41,189 [-] [L-I/O dispatcher 4] DEBUG MessageImpl f88f6913-314d-4989-b55b-704cf3a61164 released
2011-09-10 20:35:41,189 [-] [L-I/O dispatcher 4] DEBUG SimpleQueueWorkManager Message ID : f88f6913-314d-4989-b55b-704cf3a61164 has completed processing and is removed from the WIP map
2011-09-10 20:35:41,189 [-] [L-I/O dispatcher 4] DEBUG fileCache Returned file for re-use : pooled_7.tmp pool size : 200
2011-09-10 20:35:41,189 [-] [L-I/O dispatcher 4] DEBUG MessageImpl Message ID : f88f6913-314d-4989-b55b-704cf3a61164 has completed all processing
2011-09-10 20:35:41,189 [-] [L-I/O dispatcher 4] DEBUG HttpNIOListener$EventLogger Connection closed: 127.0.0.1:43663->127.0.0.1:8280
2011-09-10 20:36:12,188 [-] [S-I/O dispatcher 4] DEBUG HttpNIOSender$EventLogger Connection timed out: 127.0.0.1:17229->127.0.0.1:9001 socket timeout was : 30000
2011-09-10 20:36:12,188 [-] [S-I/O dispatcher 4] DEBUG ResponseHandler Finalizing context : 127.0.0.1:17229->127.0.0.1:9001
2011-09-10 20:36:12,188 [-] [S-I/O dispatcher 4] DEBUG HttpNIOSender$EventLogger Connection closed : 127.0.0.1:17229->127.0.0.1:9001

The above log gives you the information about the message starting from the transport receiving the connection from the client to, closing the connection to the client after delivering the response back. This log is very useful in pointing any issues if there are any in your execution flow.

Next section introduces UConsole and UTerm, the management interfaces available in managing/monitoring the UltraESB apart from the raw JMX (JConsole) View.

Labels
  • None