Monitoring / Analyzing WSO2 ESB 4.9.0 Performance with Java Flight Recorder ( JFR )

Sometimes there is a need that, we need to check which mediator or code segment causing the performance problem in ESB mediation. This is needed to find the root cause behind the delayed response. In this kind of situation, JFR is a tool, which can help us to analyze, which part of mediation logic causing the delay or taking time to execute.

This article explains how we can enable and monitor WSO2 ESB 4.9.0 with JFR.

What is JFR?

Java Flight Recorder ( JFR ) is a tool provided by Java from the JDK release 7u40 or above. This is a  profiler to determine which parts of your code are causing large amounts of memory allocation or causing excess CPU to be consumed. Refer [1] for more information on JFR.
[1] https://www.javacodegeeks.com/2015/01/java-flight-recorder-jfr.html

Configuring WSO2 ESB 4.9.0 to use JFR

Consider here I'm using the below Java version:

 ajanthan@ajanthan-ThinkPad-T440p:~$ java -version  
 java version "1.7.0_80"  
 Java(TM) SE Runtime Environment (build 1.7.0_80-b15)  
 Java HotSpot(TM) 64-Bit Server VM (build 24.80-b11, mixed mode)  
 ajanthan@ajanthan-ThinkPad-T440p:~$ echo $JAVA_HOME  
 /usr/lib/jvm/java-7-oracle  
 ajanthan@ajanthan-ThinkPad-T440p:~$   

1) Copy the below to wso2server.sh file

 -XX:+UnlockCommercialFeatures \  
 -XX:+FlightRecorder \  
 -XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=./tmpjfr,dumponexit=true,dumponexitpath=./ \  

Here, defaultrecording=true : Will start to capture from the start of the application.
disk=true : Continuosly write to disk
repository=./tmpjfr : A temporary folder will be created once started and write to a file inside
dumponexitpath=./ : Once the server / application stopped, then the temporary file will be moved to the root folder of that directory.

Check http://docs.oracle.com/javase/7/docs/technotes/tools/solaris/java.html for more information.

2) Updated wso2server.sh file part will be as below:

 while [ "$status" = "$START_EXIT_STATUS" ]  
 do  
   $JAVACMD \  
   -Xbootclasspath/a:"$CARBON_XBOOTCLASSPATH" \  
   -Xms256m -Xmx1024m -XX:MaxPermSize=256m \  
   -XX:+HeapDumpOnOutOfMemoryError \  
   -XX:HeapDumpPath="$CARBON_HOME/repository/logs/heap-dump.hprof" \  
   $JAVA_OPTS \  
   -Dcom.sun.management.jmxremote \  
   -classpath "$CARBON_CLASSPATH" \  
   -Djava.endorsed.dirs="$JAVA_ENDORSED_DIRS" \  
   -Djava.io.tmpdir="$CARBON_HOME/tmp" \  
   -Dcatalina.base="$CARBON_HOME/lib/tomcat" \  
   -Dwso2.server.standalone=true \  
   -Dcarbon.registry.root=/ \  
   -Djava.command="$JAVACMD" \  
   -Dcarbon.home="$CARBON_HOME" \  
   -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager \  
   -Dcarbon.config.dir.path="$CARBON_HOME/repository/conf" \  
   -Djava.util.logging.config.file="$CARBON_HOME/repository/conf/etc/logging-bridge.properties" \  
   -Dcomponents.repo="$CARBON_HOME/repository/components/plugins" \  
   -Dconf.location="$CARBON_HOME/repository/conf"\  
   -Dcom.atomikos.icatch.file="$CARBON_HOME/lib/transactions.properties" \  
   -Dcom.atomikos.icatch.hide_init_file_path=true \  
   -Dorg.apache.jasper.compiler.Parser.STRICT_QUOTE_ESCAPING=false \  
   -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true \  
   -Dcom.sun.jndi.ldap.connect.pool.authentication=simple \  
   -Dcom.sun.jndi.ldap.connect.pool.timeout=3000 \  
   -Dorg.terracotta.quartz.skipUpdateCheck=true \  
   -Djava.security.egd=file:/dev/./urandom \  
   -Dfile.encoding=UTF8 \  
   -XX:+UnlockCommercialFeatures \  
   -XX:+FlightRecorder \  
   -XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=./tmpjfr,dumponexit=true,dumponexitpath=./ \  
   -Djava.net.preferIPv4Stack=true \  
   -Dcom.ibm.cacheLocalHost=true \  
   -DworkerNode=false \  
   org.wso2.carbon.bootstrap.Bootstrap $*  
   status=$?  
 done  

3) Start the WSO2 ESB server.

4) Execute the below command ( After moving to the ESB_HOME directoty ) to check whether the JFR is running properly.

 jcmd `cat wso2carbon.pid` JFR.check  

Result:

 ajanthan@ajanthan-ThinkPad-T440p:~/wso2/blog/jfr/wso2esb-4.9.0$ jcmd `cat wso2carbon.pid` JFR.check  
 22685:  
 Recording: recording=0 name="HotSpot default" maxage=15m (running)  
 ajanthan@ajanthan-ThinkPad-T440p:~/wso2/blog/jfr/wso2esb-4.9.0$   

5) Now if we want to take dumps frequently can execute the below command:

 jcmd `cat wso2carbon.pid` JFR.dump recording=0 filename="recording-test.jfr"  

6) Here, for example I'm going to capture a dump during a load test, to check which component / mediator taking more execution time. For that I'm using the
below api.

 <api xmlns="http://ws.apache.org/ns/synapse" name="TestJFR" context="/jfr">  
   <resource methods="POST" uri-template="/jfrcall">  
    <inSequence>  
      <log level="custom">  
       <property name="STATUS" value="--------------------TestJFR API Invocation : START---------------------"/>  
      </log>  
      <script language="js">var log = mc.getServiceLog();          log.info("-----------Executing Script Mediator-------------------- ");</script>  
      <payloadFactory media-type="json">  
       <format>  {"test":"Out from Payload factory Mediator"}  </format>  
       <args/>  
      </payloadFactory>  
      <log level="custom">  
       <property name="STATUS" value="--------------------TestJFR API Invocation : END---------------------"/>  
      </log>  
      <respond/>  
    </inSequence>  
   </resource>  
 </api>  

7) Configured Jmeter as below:

7) While running the load test use the below command to take the dump.

 ajanthan@ajanthan-ThinkPad-T440p:~/wso2/blog/jfr/wso2esb-4.9.0$ jcmd `cat wso2carbon.pid` JFR.dump recording=0 filename="recording-test-2.jfr"  
 22685:  
 Dumped recording 0, 21.4 MB written to:  
 /home/ajanthan/wso2/blog/jfr/wso2esb-4.9.0/recording-test-2.jfr  
 ajanthan@ajanthan-ThinkPad-T440p:~/wso2/blog/jfr/wso2esb-4.9.0$  

8) Now we have taken the dump and need to analyze it. To do that we can use "jmc" command to open the Java Mission Control screen.

Through file -> openfile option we can open the .jfr file. Once we loaded we can do the analysis based on the screens available through JMC console.

Below are some of the screen's captured during this testing for reference.

You can refer http://blog.takipi.com/oracle-java-mission-control-the-ultimate-guide/#jfrinitial to get more on analysis screens.

9) That's all, we have successfully configured WSO2 ESB 4.9.0 with JFR for analysis.

References

[1] http://isuru-perera.blogspot.com/2015/02/java-flight-recorder-continuous-recordings.html

Accessing / Modifying the SOAP payload in a multipart/related message which is built by BinaryRelayBuilder of WSO2 ESB 4.9.0

When we use the BinaryRelayBuilder in WSO2 ESB, then there is a limitation that, we cannot access the payload during the mediation. This is because, if there is any content aware mediators in the mediation, then the message will be built as binary. Due to that even if you log the message, you will get a SOAP envelope with a binary tag and inside that you will see the Attachment and the SOAP Payload were concatenated as binary ( base64 encoded ). So if you want to do any modifications you cant use any other mediator's to process the payload.

In this article, we are going to look at a scenario, where we need to extract the SOAP Payload from the message ( Which is consist of a SOAP Payload + Attachment ) and then modify the payload during the mediation and then agian set the modified payload back to the message ( Modified SOAP Payload + Attachment ) and send it out from ESB through ExpandingMessageFormatter.

The possible component we can use here is the Synapse Handlers [1]. Through synapse handler we can extract the payload when the request reaches the Synapse Engine and then set the modified SOAP Payload back to the message when it's goes out from Synapse Engine.

What we are doing here:

1) Enable the below in axis2.xml.

 <messageBuilder contentType="multipart/related"  
             class="org.wso2.carbon.relay.BinaryRelayBuilder"/>  
 <messageFormatter contentType="multipart/related"  
             class="org.wso2.carbon.relay.ExpandingMessageFormatter"/>  

2) Build the below class and put it into ESB_HOME/repository/components/lib. Have given the pom.xml also.

 package com.custom.synapse.customhandlers.CustomHeaderExtractSynapseHandler;  
 import java.io.ByteArrayInputStream;  
 import java.io.IOException;  
 import java.io.InputStream;  
 import java.io.UnsupportedEncodingException;  
 import java.nio.charset.StandardCharsets;  
 import java.util.Iterator;  
 import java.util.Map;  
 import javax.activation.DataHandler;  
 import javax.xml.stream.XMLStreamException;  
 import javax.xml.stream.XMLStreamReader;  
 import org.apache.axiom.om.OMAbstractFactory;  
 import org.apache.axiom.om.OMElement;  
 import org.apache.axiom.om.OMNamespace;  
 import org.apache.axiom.om.OMText;  
 import org.apache.axiom.om.impl.builder.StAXBuilder;  
 import org.apache.axiom.om.util.StAXUtils;  
 import org.apache.axiom.soap.SOAPBody;  
 import org.apache.axiom.soap.SOAPEnvelope;  
 import org.apache.axiom.soap.SOAPFactory;  
 import org.apache.axiom.soap.SOAPHeader;  
 import org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder;  
 import org.apache.axis2.AxisFault;  
 import org.apache.commons.codec.binary.Base64;  
 import org.apache.commons.logging.Log;  
 import org.apache.commons.logging.LogFactory;  
 import org.apache.synapse.AbstractSynapseHandler;  
 import org.apache.synapse.MessageContext;  
 import org.apache.synapse.core.axis2.Axis2MessageContext;  
 import org.apache.synapse.transport.passthru.util.RelayConstants;  
 import org.apache.synapse.transport.passthru.util.RelayUtils;  
 import org.wso2.carbon.relay.StreamingOnRequestDataSource;  
 /*  
  * This is sample Synapse Handler to retrieve the binary message which is built by BinaryRelayBuilder in nhttp transport  
  * and converting it back to SOAP for the use of retrieving headers inside synapse engine and when the request going out from synapse engine  
  * will get the original binary payload and replace the modified SOAP Envelope and set it back to message context.  
  */  
 public class CustomHeaderExtractSynapseHandler extends AbstractSynapseHandler {  
      private static final Log log = LogFactory  
                .getLog(CustomHeaderExtractSynapseHandler.class);  
      private String originalDecodedBinaryMessage; // This will get the whole  
                                                                  // decoded payload with soap  
                                                                  // + attachment  
      private String originalDecodedEnvelope; // This will get original soap  
                                                        // envelope  
      public boolean handleRequestInFlow(MessageContext msgCtx) {  
           // First we need to build the message, as in passthrough transport  
           // message will not be build unless there is a  
           // content aware mediator  
           org.apache.axis2.context.MessageContext axis2MessageContext = ((Axis2MessageContext) msgCtx)  
                     .getAxis2MessageContext();  
           try {  
                RelayUtils.buildMessage(axis2MessageContext);  
           } catch (IOException e2) {  
                e2.printStackTrace();  
           } catch (XMLStreamException e2) {  
                e2.printStackTrace();  
           }  
           log.info("[CustomHeaderExtractSynapseHandler] handleRequestInFlow Invocation START.");  
           // This logic should only invoke to multipart/related format only  
           if (((String) ((String) ((Map) ((Map) ((Axis2MessageContext) msgCtx)  
                     .getAxis2MessageContext().getProperty("TRANSPORT_HEADERS")))  
                     .get("Content-Type"))).contains("multipart/related")) {  
                // After building by the binary builder the header and payload will  
                // be converted to binary  
                // Extract the binary section and decode  
                log.info("Message Reached Synapse Handler: " + msgCtx.getEnvelope());  
                SOAPBody soapBody = msgCtx.getEnvelope().getBody();  
                String binaryValue = soapBody.getFirstElement().getText();  
                byte[] decoded = Base64.decodeBase64(binaryValue.getBytes());  
                String multiPartWholeMessage = null;  
                try {  
                     multiPartWholeMessage = new String(decoded, "UTF-8");  
                     originalDecodedBinaryMessage = multiPartWholeMessage;  
                     log.info("Decoded String: " + originalDecodedBinaryMessage);  
                } catch (UnsupportedEncodingException e1) {  
                     e1.printStackTrace();  
                }  
                String envelopString = multiPartWholeMessage.substring(  
                          multiPartWholeMessage.indexOf("<soapenv:Envelope"),  
                          multiPartWholeMessage.indexOf("</soapenv:Envelope>")  
                                    + "</soapenv:Envelope>".length());  
                originalDecodedEnvelope = envelopString;  
                // log.info("Multipart Whole Message: " + multiPartWholeMessage);  
                // log.info("Multipart only Envelope: " + envelopString);  
                ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(  
                          envelopString.getBytes());  
                XMLStreamReader xmlReader = null;  
                try {  
                     xmlReader = StAXUtils  
                               .createXMLStreamReader(byteArrayInputStream);  
                } catch (XMLStreamException e1) {  
                     e1.printStackTrace();  
                }  
                StAXBuilder builder = new StAXSOAPModelBuilder(xmlReader);  
                SOAPEnvelope soapEnvelope = (SOAPEnvelope) builder  
                          .getDocumentElement();  
                SOAPHeader soapHeader = soapEnvelope.getHeader();  
                soapEnvelope.build();  
                OMElement omElement = soapEnvelope.getBody().getFirstElement();  
                OMElement e = msgCtx.getEnvelope().getBody().getFirstElement();  
                boolean isInserted = false;  
                if (omElement instanceof OMElement) {  
                     e.insertSiblingAfter(omElement);  
                     isInserted = true;  
                }  
                if (isInserted) {  
                     e.detach();  
                }  
                Iterator childElements = soapHeader.getChildElements();  
                while (childElements.hasNext()) {  
                     OMElement element = (OMElement) childElements.next();  
                     msgCtx.getEnvelope().getHeader().addChild(element);  
                }  
           }  
           // log.info("Original Decoded Envelope String:" +  
           // originalDecodedEnvelope);  
           log.info("[CustomHeaderExtractSynapseHandler] handleRequestInFlow Invocation END."  
                     + msgCtx.getEnvelope());  
           return true;  
      }  
      public boolean handleRequestOutFlow(MessageContext msgCtx) {  
           log.info("[CustomHeaderExtractSynapseHandler] handleRequestOutFlow Invocation START:");  
           log.info("[handleRequestOutFlow] Message Context Envelope: "  
                     + msgCtx.getEnvelope());  
           // This logic should only invoke to multipart/related format only  
           if (((String) ((String) ((Map) ((Map) ((Axis2MessageContext) msgCtx)  
                     .getAxis2MessageContext().getProperty("TRANSPORT_HEADERS")))  
                     .get("Content-Type"))).contains("multipart/related")) {  
                // Need to get the payload soap from the message context and then  
                // replace the soap envelope of original message with the latest  
                // transformed SOAP envelope  
                String transformedSOAPEnvelope = msgCtx.getEnvelope().toString();  
                // log.info("[CustomHeaderExtractSynapseHandler] Transformed Message: "  
                // + transformedSOAPEnvelope);  
                // Below replacing the xml declaration as decoded binary will not  
                // have the xml declaration and the transformed will have it. To  
                // replace we need to remove it.  
                String afterRemoveXMLDeclaration = transformedSOAPEnvelope  
                          .replaceAll("\\<\\?xml(.+?)\\?\\>", "").trim();  
                // log.info("[CustomHeaderExtractSynapseHandler] Transformed Message after Replace Declaration: "  
                // + afterRemoveXMLDeclaration);  
                String replaceOriginalPayload = originalDecodedEnvelope;  
                String latestDecodedPayloadBinaryMessage = originalDecodedBinaryMessage  
                          .replace(replaceOriginalPayload, afterRemoveXMLDeclaration);  
                // log.info("[CustomHeaderExtractSynapseHandler] Latest Going out Binary Message: "  
                // + latestDecodedPayloadBinaryMessage);  
                InputStream stream = new ByteArrayInputStream(  
                          latestDecodedPayloadBinaryMessage  
                                    .getBytes(StandardCharsets.UTF_8));  
                SOAPFactory factory = OMAbstractFactory.getSOAP12Factory();  
                SOAPEnvelope env = factory.getDefaultEnvelope();  
                if (stream != null) {  
                     OMNamespace ns = factory.createOMNamespace(  
                               RelayConstants.BINARY_CONTENT_QNAME.getNamespaceURI(),  
                               "ns");  
                     OMElement omEle = factory.createOMElement(  
                               RelayConstants.BINARY_CONTENT_QNAME.getLocalPart(), ns);  
                     StreamingOnRequestDataSource ds = new StreamingOnRequestDataSource(  
                               stream);  
                     DataHandler dataHandler = new DataHandler(ds);  
                     OMText textData = factory.createOMText(dataHandler, true);  
                     omEle.addChild(textData);  
                     env.getBody().addChild(omEle);  
                }  
                try {  
                     msgCtx.setEnvelope(env);  
                } catch (AxisFault e) {  
                     // TODO Auto-generated catch block  
                     e.printStackTrace();  
                }  
                log.info("[handleRequestOutFlow] Message Context Envelope After Append the Original: "  
                          + msgCtx.getEnvelope());  
                log.info("[CustomHeaderExtractSynapseHandler] handleRequestOutFlow Invocation END.");  
           }  
           return true;  
      }  
      public boolean handleResponseInFlow(MessageContext arg0) {  
           // TODO Auto-generated method stub  
           return true;  
      }  
      public boolean handleResponseOutFlow(MessageContext arg0) {  
           // TODO Auto-generated method stub  
           return true;  
      }  
 }  

3) Specify the handler at ESB_HOME/repository/conf/synapse-handlers.xml as below.

 <handlers>  
 <handler name="TestHandler" class="com.custom.synapse.customhandlers.CustomHeaderExtractSynapseHandler.CustomHeaderExtractSynapseHandler"/>  
 </handlers>  

4) Use the below proxy service.

 <?xml version="1.0" encoding="UTF-8"?>  
 <proxy xmlns="http://ws.apache.org/ns/synapse"  
     name="BinaryExtractorProxy"  
     transports="https,http"  
     statistics="disable"  
     trace="disable"  
     startOnLoad="true">  
   <target>  
    <inSequence>  
      <log level="custom">  
       <property name="STATUS"  
            value="-----------------BinaryExtractorProxy IN Invoked-------------------"/>  
      </log>  
      <property name="customheader" value="test new header" scope="transport"/>  
      <enrich>  
       <source type="body" clone="true"/>  
       <target type="body" action="sibling"/>  
      </enrich>  
      <send>  
       <endpoint>  
         <http uri-template="http://www.mocky.io/v2/5913129a0f00007007f858d7"/>  
       </endpoint>  
      </send>  
    </inSequence>  
    <outSequence>  
      <log level="custom">  
       <property name="STATUS"  
            value="-----------------BinaryExtractorProxy OUT Invoked-------------------"/>  
      </log>  
      <send/>  
    </outSequence>  
   </target>  
   <description/>  
 </proxy>  

5) Here in the proxy service, I'm doing a addition of a header and appending the body of the payload as another sibling.

Then send a request using SOAP UI with a SOAP Payload and attachment.

6) From the logs you can observe that the message got appended with our modifications and send back to back end.

Below is the Message Reached the ESB.

 TID: [-1] [] [2017-05-11 01:26:57,203] DEBUG {org.apache.synapse.transport.http.wire} - >> "POST /services/BinaryExtractorProxy HTTP/1.1[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,204] DEBUG {org.apache.synapse.transport.http.wire} - >> "Accept-Encoding: gzip,deflate[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,204] DEBUG {org.apache.synapse.transport.http.wire} - >> "SOAPAction: "urn:echoString"[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,204] DEBUG {org.apache.synapse.transport.http.wire} - >> "MIME-Version: 1.0[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,204] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Type: multipart/related[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,205] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Length: 23843[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,205] DEBUG {org.apache.synapse.transport.http.wire} - >> "Host: ajanthan-ThinkPad-T440p:8280[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,206] DEBUG {org.apache.synapse.transport.http.wire} - >> "Connection: Keep-Alive[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,206] DEBUG {org.apache.synapse.transport.http.wire} - >> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,206] DEBUG {org.apache.synapse.transport.http.wire} - >> "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,206] DEBUG {org.apache.synapse.transport.http.wire} - >> "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "------=_Part_6_1324973095.1494446217171[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Type: text/xml; charset=UTF-8[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Transfer-Encoding: 8bit[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-ID: <rootpart@soapui.org>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,207] DEBUG {org.apache.synapse.transport.http.wire} - >> "<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:echo="http://echo.services.core.carbon.wso2.org">[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "  <soapenv:Header>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "  <test>Test Header</test>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "  </soapenv:Header>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "  <soapenv:Body>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "   <echo:echoString>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,208] DEBUG {org.apache.synapse.transport.http.wire} - >> "     <!--Optional:-->[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "     <in>Test Message1</in>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "   </echo:echoString>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "  </soapenv:Body>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "</soapenv:Envelope>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "------=_Part_6_1324973095.1494446217171[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,209] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Type: image/x-png; name=Selection_003.png[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,210] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Transfer-Encoding: binary[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,210] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-ID: <Selection_003.png>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,210] DEBUG {org.apache.synapse.transport.http.wire} - >> "Content-Disposition: attachment; name="Selection_003.png"; filename="Selection_003.png"[\r][\n]" {org.apache.synapse.transport.http.wire}  

Below is the Message goes out from ESB.

 TID: [-1] [] [2017-05-11 01:26:57,907] DEBUG {org.apache.synapse.transport.http.wire} - << "POST /v2/5913129a0f00007007f858d7 HTTP/1.1[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "MIME-Version: 1.0[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "SOAPAction: "urn:echoString"[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "Accept-Encoding: gzip,deflate[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "customheader: test new header[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Type: multipart/related[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,908] DEBUG {org.apache.synapse.transport.http.wire} - << "Transfer-Encoding: chunked[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "Host: www.mocky.io:80[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "Connection: Keep-Alive[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "User-Agent: Synapse-PT-HttpComponents-NIO[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "1ec0[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "------=_Part_6_1324973095.1494446217171[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,909] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Type: text/xml; charset=UTF-8[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Transfer-Encoding: 8bit[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-ID: <rootpart@soapui.org>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "<soapenv:Envelope xmlns:soapenv="http://www.w3.org/2003/05/soap-envelope"><soapenv:Header><test>Test Header</test></soapenv:Header><soapenv:Body><echo:echoString xmlns:echo="http://echo.services.core.carbon.wso2.org">[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "     <!--Optional:-->[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "     <in>Test Message1</in>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "   </echo:echoString><echo:echoString xmlns:echo="http://echo.services.core.carbon.wso2.org">[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "     <!--Optional:-->[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,910] DEBUG {org.apache.synapse.transport.http.wire} - << "     <in>Test Message1</in>[\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "   </echo:echoString></soapenv:Body></soapenv:Envelope>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "------=_Part_6_1324973095.1494446217171[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Type: image/x-png; name=Selection_003.png[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Transfer-Encoding: binary[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-ID: <Selection_003.png>[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "Content-Disposition: attachment; name="Selection_003.png"; filename="Selection_003.png"[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,911] DEBUG {org.apache.synapse.transport.http.wire} - << "[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,912] DEBUG {org.apache.synapse.transport.http.wire} - << "[0xef][0xbf][0xbd]PNG[\r][\n]" {org.apache.synapse.transport.http.wire}  
 TID: [-1] [] [2017-05-11 01:26:57,912] DEBUG {org.apache.synapse.transport.http.wire} - << "[0x1a][\n]" {org.apache.sy    

[1] https://docs.wso2.com/display/ESB490/Writing+a+Synapse+Handler