The Message Execution Flow

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 mis-behaviours of the flow. Further UltraESB is designed to run at INFO level logging at production.

External Analysis

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.1 200 OK
port: 9000
Content-Type: text/xml;charset=UTF-8
Date: Mon, 15 Aug 2016 10:04:53 GMT
Server: UltraESB/2.6.1
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 in destination endpoint in the default configuration for "echo-proxy" in the ultra-unit.xml, to http://localhost:9001/service/EchoService as shown below, note the change in the port number from 9000 to 9001, and restart the UltraESB server for these changes to be effective.

<u:proxy id="echo-proxy">
    <u:transport id="http-8280"/>
    <u:target>
        <!-- Note the change here -->
        <u:inDestination>
            <u:address>http://localhost:9001/service/EchoService</u:address>
        </u:inDestination>
        <u:outSequence>
            <u:java><![CDATA[
                    System.out.println("Reply payload : " + mediation.readPayloadAsString(msg));
                ]]></u:java>
        </u:outSequence>
        <u:outDestination>
            <u:address type="response"/>
        </u:outDestination>
    </u:target>
</u:proxy>
Dynamic configuration provisioning and update
UltraESB supports dynamic deployment unit 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.

toolbox tcpdump menu

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.

toolbox tcp dump server

It is necessary to start the Jetty server on port 9000 via the tool box as explained in Sending a Message through UltraESB. Actually what happens  is that the message is forwarded to port 9001. The TCP Dump listening at 9001 will forward it to the back-end EchoService at port 9000. The following figure clearly depicts the scenario.

drawing intercepting

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;

toolbox tcp dump server trace

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.

$ jconsole

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-2.6.1/conf" from the local processes table.

  3. Click on the "Connect" button to connect to the runtime.

jconsole connect

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.

jconsole logger operations pane

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

  1. Type "org.adroitlogic.ultraesb.transport.http.HttpNIOListener" 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.

jconsole invoke changeLogLevel

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

jconsole info message

This invocation changed the log level of the "org.adroitlogic.ultraesb.transport.http.HttpNIOListener" to DEBUG, and now you should see the debug logs, on the command line console, if you invoke the client back again.

2016-08-19T12:38:30,487 [-] [RMI TCP Connection(9)-127.0.0.1] [system] [000000I]  INFO LoggerUtilsManager Changing the log level of the logger : org.adroitlogic.ultraesb.transport.http.HttpNIOListener, into level : DEBUG
2016-08-19T12:38:43,003 [-] [L-I/O-dispatcher-1] [system] [000000I] DEBUG HttpNIOListener Connection open: http-incoming-1 Total connections : 1
2016-08-19T12:38:43,004 [-] [L-I/O-dispatcher-1] [system] [000000I] DEBUG HttpNIOListener IP Connection: http-incoming-1 origin => 127.0.0.1:13422
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>
2016-08-19T12:38:43,050 [-] [L-I/O-dispatcher-1] [system] [000000I] DEBUG HttpNIOListener Connection closed: http-incoming-1

The above log gives you the information about HttpNIOListener operation. These kinds of debug logs are very useful in figuring out any issues if there are any in your execution flow.

UltraESB 2.6.1 uses log4j2 Starting from 2.6.1 UltraESB now used "log4j2" which is uses async logging where logging operation occurs in a separate thread, so there will only a very small overhead for actual processing.

What’s more interesting is that unlike log4j 1.x, Log4j 2 has built-in support for JMX. The StatusLogger, ContextSelector, and all LoggerContexts, LoggerConfigs and Appenders are instrumented with MBeans and can be remotely monitored and controlled. In jconsole you would see a log4j2 entry in the name "org.apache.logging.log4j". If you expand "org.apache.logging.log4j" entry and then the sub-entry "Loggers" you can see root level loggers defined in log4j2.xml as shown below.

jconsole log4j change1

Now you can edit the entry "Level" as you prefer it will be reflected realtime in UltraESB. Here we have set the "org.adroitlogic" root logger level to "DEBUG".

jconsole log4j change2

Please note that when debugging it might be easy to change log levels of respective entities you are interested in rather that changing the root level loggers as changing root level loggers may sometimes offer too much information.

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

In this topic
In this topic
Contact Us