Working with Observability

Product observability enables rapid debugging of product issues. The ESB profile of WSO2 Enterprise Integrator (WSO2 EI) enables observability using correlation logs. Correlation logs allow you to monitor individual HTTP requests from the point that a message is received by the ESB until the corresponding response message is sent back to the original message sender. That is, the complete round trip of an HTTP message (client → ESB → back-end → ESB → client) can be tracked and anlyzed using a log file.

When correlation logs are enabled for the ESB server, a separate log file named correlation.log is created in the <EI_HOME>/repository/logs/ directory. Every HTTP message that flows through the ESB and between the ESB and external clients undergoes several state changes. A new log entry is created in the correlation.log file corresponding to the state changes in the round trip of a single HTTP request. A correlation ID assigned to the incoming HTTP request is assigned to all the log entries corresponding to the request. Therefore, you can use this correlation ID to easily locate the logs relevant to the round trip of a specific HTTP request and, thereby, analyze the behaviour of the message flow.

See the following topics for details:

Configuring correlation logs

Follow the steps given below to configure correlation logs in the ESB server.

Add the following parameters to the log4j2.properties file (stored in the <EI_HOME>/conf/ directory):

Define a log appender like below.

# Appender config to put correlation Log.
appender.CORRELATION.type = RollingFile
appender.CORRELATION.name = CORRELATION
appender.CORRELATION.fileName =${sys:carbon.home}/repository/logs/correlation.log
appender.CORRELATION.filePattern =${sys:carbon.home}/repository/logs/correlation-%d{MM-dd-yyyy}-%i.log.gz
appender.CORRELATION.layout.type = PatternLayout
appender.CORRELATION.layout.pattern = %d{yyyy-MM-dd HH:mm:ss,SSS}|%X{Correlation-ID}|%t|%m%n
appender.CORRELATION.policies.type = Policies
appender.CORRELATION.policies.time.type = TimeBasedTriggeringPolicy
appender.CORRELATION.policies.time.interval = 1
appender.CORRELATION.policies.time.modulate = true
appender.CORRELATION.policies.size.type = SizeBasedTriggeringPolicy
appender.CORRELATION.policies.size.size=10MB
appender.CORRELATION.strategy.type = DefaultRolloverStrategy
appender.CORRELATION.strategy.max = 20
appender.CORRELATION.filter.threshold.type = ThresholdFilter
appender.CORRELATION.filter.threshold.level = INFO

Define a logger like below.

logger.CORRELATION.name = correlation
logger.CORRELATION.level = INFO
logger.CORRELATION.appenderRef.CORRELATION.ref = CORRELATION
logger.CORRELATION.additivity = false

Add your appender name into the section called "list of all appenders" as following manner.

# list of all appenders
#add entry "syslog" to use the syslog appender
appenders = CARBON_CONSOLE, CARBON_LOGFILE, AUDIT_LOGFILE, ATOMIKOS_LOGFILE, CARBON_TRACE_LOGFILE, osgi, SERVICE_LOGFILE, ERROR_LOGFILE, CORRELATION

Add your logger name into the section called “loggers” as following manner.

loggers = AUDIT_LOG, SERVICE_LOGGER, trace-messages, org-apache-coyote, com-hazelcast, Owasp-CsrfGuard, \
     org-apache-axis2-wsdl-codegen-writer-PrettyPrinter, org-apache-axis2-clustering, org-apache-catalina, \
     org-apache-tomcat, org-wso2-carbon-apacheds, org-apache-directory-server-ldap, \
     org-apache-directory-server-core-event, com-atomikos, org-quartz, org-apache-jackrabbit-webdav, org-apache-juddi, \
     org-apache-commons-digester-Digester, org-apache-jasper-compiler-TldLocationsCache, org-apache-jasper-servlet-TldScanner, org-apache-qpid, \
     org-apache-qpid-server-Main, qpid-message, qpid-message-broker-listening, ca-uhn-hl7v2, org-apache-tiles, \
     org-apache-commons-httpclient, org-apache-solr, me-prettyprint-cassandra-hector-TimingLogger, \
     org-apache-axis-enterprise, org-apache-directory-shared-ldap, org-apache-directory-server-ldap-handlers, \
     org-apache-directory-shared-ldap-entry-DefaultServerAttribute, org-apache-directory-server-core-DefaultDirectoryService, \
     org-apache-directory-shared-ldap-ldif-LdifReader, org-apache-directory-server-ldap-LdapProtocolHandler, \
     org-apache-directory-server-core, org-apache-directory-server-ldap-LdapSession, DataNucleus, Datastore, Datastore-Schema, \
     JPOX-Datastore, JPOX-Plugin, JPOX-MetaData, JPOX-Query, JPOX-General, JPOX-Enhancer, org-apache-hadoop-hive, hive, ExecMapper, \
     ExecReducer, net-sf-ehcache-config-ConfigurationFactory, axis2Deployment, equinox, tomcat2, StAXDialectDetector, \
     org-apache-synapse, org-apache-synapse-transport, org-apache-axis2, org-apache-axis2-transport, org-wso2-carbon, synapse-transport-http-access, correlation

Once the logs are configured, correlation logging should be enabled in the ESB as following manner.

Navigate to the <EI_HOME>/repository/logs/ directory where the correlation.log file is saved.

Note that the maximum file size of the correlation log is set to 10MB in the above configuration. That is, when the size of the file exceeds 10MB, a new log file is created. If required, you can change this file size.
If required, you can change the default HTTP header (which is 'activity_id') that is used to carry the correlation ID by adding the following property to the passthru-http.properties file (stored in the <EI_HOME>/conf/ directory). Replace <correlation_id> with a value of your choice.
```
correlation_header_name=<correlation_id>
```

Once the logs are configured, correlation logging should be enabled in the ESB as explained in the next section.

Enabling correlation logs in the ESB

You can enable correlation logging by passing a system property.

If you want correlation logs to be enabled every time the server starts, add the following system property to the product start-up script (stored in the <EI_HOME>/bin/ directory) and set it to true.
```
-DenableCorrelationLogs=true \
```
Alternatively, you can pass the system property at the time of starting the server by executing the following command:
On Linux/MacOS/CentOS sh integrator.sh -DenableCorrelationLogs=true
On Windows integrator.bat -DenableCorrelationLogs=true

Now when you start the ESB server, the correlation.log file is created in the <EI_HOME>/repository/logs/ directory.

Sending an HTTP request with a correlation ID

When the client sends an HTTP request to the ESB, a correlation ID for the request can be passed using the correlation header that is configured in the ESB. By default, the correlation header is 'activity_id'. If you want to change the default correlation header, wee the topic on configuring correlation logs. If the client does not pass a correlation ID in the request, the ESB will generate an internal value and assign it to the request. The correlation ID assigned to the incoming request is assigned to all the log entries that are related to the same request.

Shown below is the POST request that is sent using the CURL client in the /wiki/spaces/EI6xx/pages/49610764. Note that the correlation ID is set in this request.

curl -X POST --data @request.json http://localhost:8280/healthcare/categories/surgery/reserve -H "Content-Type:application/json" -H "activityid:correlationID"

Accessing the correlation logs

If you know the correlation ID of the HTTP request that you want to analyze, you can isolate the relevant logs as explained below.

Open a terminal and navigate to the <EI_HOME>/repository/logs/ directory where the correlation.log file is saved.
Execute the following command with the required correlation ID. Replace <correlation_ID> with the required value.
```
cat correlation.log | grep "<correlation_ID>"
```

Shown below is an example of correlation log entries corresponding to the round trip of a single HTTP request.

2018-11-30 15:27:27,262|correlationID|HTTP-Listener I/O dispatcher-5|0|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|REQUEST_HEAD
2018-11-30 15:27:27,262|correlationID|HTTP-Listener I/O dispatcher-5|0|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|REQUEST_BODY
2018-11-30 15:27:27,263|correlationID|HTTP-Listener I/O dispatcher-5|1|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|REQUEST_DONE
2018-11-30 15:27:27,265|correlationID|HTTP-Sender I/O dispatcher-4|42173|HTTP State Transition|http-outgoing-4|POST|http://localhost:9090/grandoaks/categories/surgery/reserve|REQUEST_HEAD
2018-11-30 15:27:27,265|correlationID|HTTP-Sender I/O dispatcher-4|0|HTTP State Transition|http-outgoing-4|POST|http://localhost:9090/grandoaks/categories/surgery/reserve|REQUEST_DONE
2018-11-30 15:27:27,267|correlationID|HTTP-Sender I/O dispatcher-4|2 |HTTP|sourhttp://localhost:9090/grandoaks/categories/surgery/reserve|BACKEND LATENCY
2018-11-30 15:27:27,267|correlationID|HTTP-Sender I/O dispatcher-4|2|HTTP State Transition|http-outgoing-4|POST|http://localhost:9090/grandoaks/categories/surgery/reserve|RESPONSE_HEAD
2018-11-30 15:27:27,267|correlationID|HTTP-Sender I/O dispatcher-4|0|HTTP State Transition|http-outgoing-4|POST|http://localhost:9090/grandoaks/categories/surgery/reserve|RESPONSE_BODY
2018-11-30 15:27:27,267|correlationID|HTTP-Sender I/O dispatcher-4|0|HTTP State Transition|http-outgoing-4|POST|http://localhost:9090/grandoaks/categories/surgery/reserve|RESPONSE_DONE
2018-11-30 15:27:27,269|correlationID|HTTP-Listener I/O dispatcher-5|6|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|RESPONSE_HEAD
2018-11-30 15:27:27,269|correlationID|HTTP-Listener I/O dispatcher-5|0|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|RESPONSE_BODY
2018-11-30 15:27:27,269|correlationID|HTTP-Listener I/O dispatcher-5|0|HTTP State Transition|http-incoming-17|POST|/healthcare/categories/surgery/reserve|RESPONSE_DONE
2018-11-30 15:27:27,269|correlationID|HTTP-Listener I/O dispatcher-5|7|HTTP|http-incoming-17|POST|/healthcare/categories/surgery/reserve|ROUND-TRIP LATENCY

Reading correlation logs

The pattern/format of a correlation log is shown below along with an example log entry.

The detail recorded in a log entry is described below.

Time Stamp	The time at which the log is created. Example 2018-10-26 17:34:40,464
Correlation ID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send the correlation ID in the header of the HTTP request. If this correlation ID is missing in the incoming request, the ESB will generate one for the request. The HTTP header that carries the correlation ID is configured in the ESB. Example de461a83-fc74-4660-93ed-1b609ecfac23
Thread name	The identifier of the thread. Example HTTP-Listener I/O dispatcher-3
Duration	The duration (given in milliseconds) depends on the type of log entry: If the state in the log entry is ROUND-TRIP LATENCY, the duration corresponds to the time gap between the REQUEST_HEAD state and the ROUND-TRIP LATENCY state. That is, the total time of the round trip. If the state in the log entry is BACKEND LATENCY, the duration corresponds to the total time taken by the backend to process the message. For all other log entries, the duration corresponds to the time gap between the current log entry and the immediately previous log entry. That is, the time taken for the HTTP request to move from one state to another. Example 535
Call type	There are two possible call types: HTTP call type identifies logs that correspond to either back-end latency or round-trip latency states. That is, in the case of an individual request, one log will be recorded to identify back-end latency, and another log for round-trip latency. Since these logs relate to HTTP calls between the ESB and external clients, these logs are categorized using the HTTP call type. HTTP State Transition call type identifies logs that correspond to the state transitions in the HTTP transport related to a particular message.
Connection name	This is a name that is generated to identify the connection between the ESB and the external client (back-end or message sender). Example http-incoming-3
Method type	The HTTP method used for the request. Example GET
Connection URL	The connection URL of the external client with which the message is being communicated. For example, if the message is being read from the client, the connection URL corresponds to the client sending the message. However, if the message is being written to the backend, the URL corresponds to the backend client. Example /api/querydoctor/surgery
HTTP state	Listed below are the state changes that a message goes through when it flows through the ESB, and when the message flows between the ESB and external clients. Typically, a new log entry is generated for each of the states. However, there can be two separate log entries created for one particular state (except for BACKEND LATENCY and ROUND-TRIP LATENCY) depending on whether the message is being read or written. You can identify the two separate log entries from the connection URL explained above. REQUEST_HEAD: All HTTP headers in the incoming request are being read/or being written to the backend. REQUEST_BODY: The body of the incoming request is being read/or being written to the backend. REQUEST_DONE: The request is completely read (content decoded)/ or is completely written to the backend. BACKEND LATENCY: The response message is received by the ESB. This status corresponds to the time total time taken by the backend to process the message. RESPONSE_HEAD: All HTTP headers in the response message are being read/or being written to the client. RESPONSE_BODY: The body of the response message is being read/or being written to the client. RESPONSE_DONE: The response is completely read/ or completely written to the client. ROUND-TRIP LATENCY: The response message is completely written to the client. This status corresponds to the total time taken by the HTTP request to compete the round trip (from the point of receiving the HTTP request from a client until the response message is sent back to the client)

On Linux/MacOS/CentOS	`sh integrator.sh` `-DenableCorrelationLogs=true`
On Windows	`integrator.bat` `-DenableCorrelationLogs=true`