Monitoring Message Round Trip¶
Product observability enables rapid debugging of product issues. The WSO2 Micro Integrator enables observability using correlation logs. Correlation logs allow you to monitor individual HTTP requests from the point that a message is received by the Micro Integrator until the corresponding response message is sent back to the original message sender. That is, the complete round trip of an HTTP message (client → Micro Integrator → back-end → Micro Integrator → client) can be tracked and analyzed using a log file.
When correlation logs are enabled for the Micro Integrator server, a separate log
correlation.log is created in the
MI_HOME/repository/logs/ directory. Every HTTP
message that flows through the ESB and between the Micro Integrator and external
clients undergoes several state changes. A new log entry is created in
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.
Enabling correlation logs¶
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
MI_HOME/bin/directory) and set it to
Alternatively, you can pass the system property at the time of starting the server by executing the following command:
- On Linux/MacOS/CentOS:
sh micro-integrator.sh -DenableCorrelationLogs=true
- On Windows:
- On Linux/MacOS/CentOS:
Now when you start the Micro Integrator, the
correlation.log file is created in the
Sending an HTTP request with a correlation ID¶
When the client sends an HTTP request to the Micro Integrator, a correlation ID for the request can be passed using the correlation header that is configured in the Micro Integrator. By default, the correlation header is 'activity_id'. If you want to change the default correlation header, see the topic on configuring correlation logs. If the client does not pass a correlation ID in the request, the Micro Integrator 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. 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
MI_HOME/repository/logs/directory where the
correlation.logfile 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.
Time Stamp|Correlation ID|Thread name|Duration|Call type|Connection name|Method type|Connection URL|HTTP state
2018-10-26 17:34:40,464|de461a83-fc74-4660-93ed-1b609ecfac23|HTTP-Listener I/O dispatcher-3|535|HTTP|http-incoming-3|GET|/api/querydoctor/surgery|ROUND-TRIP LATENCY
The detail recorded in a log entry is described below.
The time at which the log is created.
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.
The identifier of the thread.
The duration (given in milliseconds) depends on the type of log entry:
There are two possible call types:
This is a name that is generated to identify the connection between the ESB and the external client (back-end or message sender).
The HTTP method used for the request.
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.
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 (e xcept 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.
Configuring correlation logs (Optional)¶
See the configuring correlation logs section for details.Top