

Working with Observability¶

Observability in WSO2 API Manager (WSO2 API-M) is really important to debug issues in a short period. WSO2 API-M facilitates observability by logging the following important points of the system with the time taken to achieve them.

Method Calls
External Calls (HTTP/HTTPS)
Database Calls (JDBC and LDAP)

Furthermore, when observability is enabled in WSO2 API-M, a random correlation ID is generated within the WSO2 API-M for each transaction allowing you to correlate the latter three types of calls. Thereby, the requests and the responses that correspond to a specific API call will be logged under one correlation ID making it easier to analyze the information. If required, you can provide a unique correlation ID by adding the activityid in the header to the request sent to WSO2 API-M.

Note

Observability is not enabled by default as it slightly impacts WSO2 API Manager's performance.

Enabling observability on WSO2 API-M¶

Enabling observability is simple in the new API Manager. All that needs to be done is to find the following system property in the product startup script (stored in the <API-M_HOME>/bin/ directory) and set it to true. By default, this is set to false.

-DenableCorrelationLogs=true

Tip

Alternatively, observability can be enabled at the time of starting the WSO2 API-M server as follows:

Linux/Mac OS

sh wso2server.sh -DenableCorrelationLogs=true start

Windows

wso2server.bat --run -DenableCorrelationLogs=true start

Note

When observability is enabled in WSO2 API Manager, a separate log file named correlation.log is created in the <API-M_HOME>/repository/logs directory.

Method call logs¶

When correlation logging is enabled, the API Manager logs the time taken to execute certain important methods of the following modules.

org.wso2.carbon.apimgt.gateway
org.wso2.carbon.apimgt.keymgt
org.wso2.carbon.apimgt.impl

In API Manager, by default the important methods are marked with the @MethodStats annotation, and this annotation can be found at both the method level and the class level. All the methods of the respective class are included for logging for the classes that have the latter mentioned annotation. The format of a method log entry is as follows:

Format

Example

Click here for more details on the method call log entry.

Field	Description
timestamp	The time at which the log is created. Example: `2018-11-28 10:10:56,293`
correlationID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send a unique correlation ID in the `activityID` header of the HTTP request. If this correlation ID is missing in the incoming request, WSO2 API-M will generate a random correlation ID for the request. Example: `a783f7c3-647f-4d10-9b72-106faa01bba8`
threadName	The identifier of the thread. Example: `PassThroughMessageProcessor-3`
duration	The time gap (in milliseconds) between two states of the message. Example: `0`
callType	METHOD - The call type is METHOD in order to indicate that it is a method level log.
className	Class name of the method which was invoked.
methodName	Name of the method which was invoked.
methodArguments	Parameters of the method that was invoked.

Tip

By default, we log only certain methods we suspect that can introduce a latency. If you need to log all the methods that correspond to a package, you need to specify the package name as the value of the logAllMethods system property. This is further explained lateron.

External call logs¶

You can enable correlation logs in WSO2 API-M to track the complete round trip of an individual HTTP message, which means the monitoring of individual HTTP requests from the point that a message is received by WSO2 API-M until the corresponding response message is sent back to the original message sender (client → API-M → back-end → API-M → client). Thereby, you can use the correlation log file to monitor and analyze external calls in detail. The following are the two types of external call logs that can be tracked via observability in WSO2 API-M.

External call logs with APIM specific information¶

All external calls done by the API Manager is logged via this category. Note that this does not include DB calls. This is done via a Synapse Global Handler that logs the important information of the external calls. The format for a Synapse global handler level external call log entry is as follows:

Format

Example

Click here for more details on the Synapse global handler level external call log entry.

Field	Description
timestamp	The time at which the log is created. Example: `2018-11-28 10:10:56,293`
correlationID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send a unique correlation ID in the `activityID` header of the HTTP request. If this correlation ID is missing in the incoming request, WSO2 API-M will generate a random correlation ID for the request. Example: `a783f7c3-647f-4d10-9b72-106faa01bba8`
threadName	The identifier of the thread. Example: `PassThroughMessageProcessor-4`
duration (BE Latency)	The time gap (in milliseconds) between two states of the message. Example: `0`
callType	HTTP - The call type identifies logs that correspond to either back-end latency or round-trip latency states. Thereby, in the case of an individual request, one log will be recorded to identify back-end latency, and another log for the round-trip latency. These logs are categorized using the HTTP call type because these logs relate to HTTP calls between WSO2 API-M and external clients.
apiName	Name of the API that was invoked. Example: `admin--PizzaShackAPI:v1.0.0`
apiMethod	HTTP method utilized. Example: `GET`
apiContext	The API context which was invoked.
apiResourcePath	Resource path of the API that was invoked. Example: `/pizzashack/1.0.0/menu`
authHeader	Logs the Authorization header.
orgIdHeader	Logs the organization-id header.
SrcIdHeader	Logs the source-id header.
applIdHeader	Logs the application-id header.
uuIdHeader	Logs the uuid header.
requestSize	Size of the request payload. Example: `71`
responseSize	Size of the response payload. Example: `2238`
apiResponseStatusCode	Status code of the response. Example: `200`
applicationName	Name of the application that was used to subscribe to the API. Example: `DefaultApplication`
consumerKey	This refers to the consumer key that you get when you generate keys for your production and sandbox environments. Example: `AwlPOz2aDf2i1gZFWgITEgf4oPsa`
responseTime	Roundtrip time of the request. Example: `21`

External call logs with transport level information¶

In contrast to the information provided by the Synapse global handler level, the passthrough transport level gives certain additional data such as, the Synapse internal state of the request. The format for a Synapse passthrough transport level external call log entry is as follows:

Format

Example

Click here for more details on the Synapse passthrough transport level external call log entry.

Field	Description
timestamp	The time at which the log is created. Example: `2018-11-28 10:10:56,314`
correlationID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send a unique correlation ID in the `activityID` header of the HTTP request. If this correlation ID is missing in the incoming request, WSO2 API-M will generate a random correlation ID for the request. Example: `a783f7c3-647f-4d10-9b72-106faa01bba8`
threadName	The identifier of the thread. Example: `HTTPS-Sender I/O dispatcher-1`
duration	The time gap (in milliseconds) between two states of the message. Example: `1`
callType	The following are the two possible call types: HTTP - This call type identifies logs that correspond to either back-end latency or round-trip latency states. Thereby, in the case of an individual request, one log will be recorded to identify back-end latency, and another log for the round-trip latency. These logs are categorized using the HTTP call type because these logs relate to HTTP calls between WSO2 API-M and external clients. HTTP State Transition - This call type idenfities logs that correspond to the state transition in the HTTP transport related to a particular message.
connectionName	This is a name that is generated to identify the connection between WSO2 API-M and the external client (back-end or message sender). Example: `http-outgoing-1`
methodType	The HTTP method used for the request. Example: `GET`
connectionURL	The connection URL of external client to which the message is passed from WSO2 API-M. Example: `https://localhost:9443/am/sample/pizzashack/v1/api/menu`
httpState	Listed below are the state changes that a message goes through when it flows through WSO2 API-M, and when the message flows between WSO2 API-M and exernal clients. A new log is generated for the message to record each of the following states. REQUEST_HEAD: All HTTP headers in the incoming request are being written to the backend. REQUEST_BODY: The body of the incoming request is being written to the backend. REQUEST_DONE: The request is completely received (content decoded) and written to the backend. BACKEND LATENCY: The response message is received by WSO2 API-M. 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 written to the client. RESPONSE_BODY: The body of the response message is being written to the client. RESPONSE_DONE: The response is completely received and written to the client. ROUND-TRIP LATENCY: The response message is completely writtent 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).

Database call logs¶

The database call logging for observability includes two types of DB calls, namely LDAP calls and JDBC calls. This will help to track down any latencies caused by a database calls in an instance.

JDBC call logs¶

Format

Example

Click here for more details on the the JDBC call log entry.

Field	Description
timestamp	The time at which the log is created. Example: `2018-11-28 10:10:43,202`
correlationID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send a unique correlation ID in the `activityID` header of the HTTP request. If this correlation ID is missing in the incoming request, WSO2 API-M will generate a random correlation ID for the request. Example: `a783f7c3-647f-4d10-9b72-106faa01bba8`
threadName	The identifier of the thread. Example: `PassThroughMessageProcessor-1`
duration	The time gap (in milliseconds) between two states of the message. Example: `0`
callType	jdbc - This indicates JDBC level logs
startTime	Time in milliseconds at which the query started. Example: `1543380043202`
methodName	SQL statement method type that was called. Example: `executeQuery`
query	SQL query. Example: `SELECT REG_NAME, REG_VALUE FROM REG_PROPERTY P, REG_RESOURCE_PROPERTY RP WHERE P.REG_ID=RP.REG_PROPERTY_ID AND RP.REG_VERSION=? AND P.REG_TENANT_ID=RP.REG_TENANT_ID AND RP.REG_TENANT_ID=?`
connectionUrl	Database connection URL. Example: `jdbc:h2:repository/database/WSO2CARBON_DB`

LDAP call logs¶

Format

Example

Click here for more details on the the LDAP call log entry.

Field	Description
timestamp	The time at which the log is created. Example: `2018-11-0514:05:18,599`
correlationID	Each log contains a correlation ID, which is unique to the HTTP request. A client can send a unique correlation ID in the `activityID` header of the HTTP request. If this correlation ID is missing in the incoming request, WSO2 API-M will generate a random correlation ID for the request. Example: `a783f7c3-647f-4d10-9b72-106faa01bba8`
threadName	The identifier of the thread. Example: `http-nio-9443-exec-8`
duration	The time gap (in milliseconds) between two states of the message. Example: `200`
callType	ldap - Determines the LDAP level logs.
startTime	Time in milliseconds at which the query started. Example: `1541406918591`
methodName	LDAP method type that was called. Example: `search`
providerUrl	LDAP connection URL. Example: `ldap://localhost:10389`
principal	Login name of the user. Example: `uid=admin,ou=system`
argsLength	Length of arguments. Example: `3`
args	Arguments in the LDAP query. Example: `uid=admin,ou=Users,dc=WSO2,dc=ORG,(&(objectClass=person)(uid=admin)),javax.naming.directory.SearchControls@548e9a48`

Using the correlation logs to track a specific request¶

Follow the instructions below to check the correlation logs of a specific request sent:

Step 1 - Setup WSO2 API-M¶

Enable observability with WSO2 API-M and start the WSO2 API-M server as explained above.

Step 2 - Invoke an API¶

If you don't have an API to access, follow the following links:

Use the following command to invoke the API.

curl -k "Authorization :Bearer <access-token>" -H "activityid:<example-correlation-ID>" --data "<payload>" <api_url>

Note

If curl is not available, you can use any tool to invoke the API. But make sure the add the activityid header

Step 3 - Check the correlation logs¶

Open a terminal and navigate to the <API-M_HOME>/repository/logs directory where the correlation.log file is saved.
Isolate the logs that are correlated.
Replace <correlation_ID> with the <example-correlation-ID> given above.

cat correlation.log | grep "<correlation_ID>"

Reading and analyzing the correlation logs¶

Let's analyze the following sample correlation log.

1 `2018-11-29 15:19:13,859|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|1|HTTP State Transition|http-incoming-2|GET|/testing/1|REQUEST_HEAD`
2 `2018-11-29 15:19:13,859|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|0|HTTP State Transition|http-incoming-2|GET|/testing/1|REQUEST_DONE`
3 `2018-11-29 15:19:13,862|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.CORSRequestHandler|handleRequest|[messageContext]`
4 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.APIKeyValidator|getResourceCache|[]`
5 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.APIKeyValidator|getResourceAuthenticationScheme|[synCtx]`
6 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.AuthenticationContext|getCallerToken|[]`
7 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.oauth.OAuthAuthenticator|authenticate|[synCtx]`
8 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.APIAuthenticationHandler|handleRequest|[messageContext]`
9 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.throttling.ThrottleHandler|doThrottle|[messageContext]`
10 `2018-11-29 15:19:13,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.analytics.APIMgtUsageHandler|handleRequest|[mc]`
11 `2018-11-29 15:19:13,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.analytics.APIMgtGoogleAnalyticsTrackingHandler|handleRequest|[msgCtx]`
12 `2018-11-29 15:19:13,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.ext.APIManagerExtensionHandler|mediate|[messageContext, direction]`
13 `2018-11-29 15:19:13,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-17|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.ext.APIManagerExtensionHandler|handleRequest|[messageContext]`
14 `2018-11-29 15:19:13,984||pool-10-thread-1|0|jdbc|1543484953984|executeQuery|SELECT REG_PATH, REG_USER_ID, REG_LOGGED_TIME, REG_ACTION, REG_ACTION_DATA FROM REG_LOG WHERE REG_LOGGED_TIME>? AND REG_LOGGED_TIME<? AND REG_TENANT_ID=? ORDER BY REG_LOGGED_TIME DESC|jdbc:h2:repository/database/WSO2CARBON_DB`
15 `2018-11-29 15:19:13,984||pool-10-thread-1|0|jdbc|1543484953984|executeQuery|SELECT UM_ID, UM_DOMAIN_NAME, UM_EMAIL, UM_CREATED_DATE, UM_ACTIVE FROM UM_TENANT ORDER BY UM_ID|jdbc:h2:repository/database/WSO2CARBON_DB`
16 `2018-11-29 15:19:14,031|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Sender I/O dispatcher-3|3|HTTP State Transition|http-outgoing-3|GET|http://0.0.0.0:10080/hello/sayHello|REQUEST_DONE`
17 `2018-11-29 15:19:14,863|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Sender I/O dispatcher-3|832 |HTTP|http://0.0.0.0:10080/hello/sayHello|BACKEND LATENCY`
18 `2018-11-29 15:19:14,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Sender I/O dispatcher-3|832|HTTP State Transition|http-outgoing-3|GET|http://0.0.0.0:10080/hello/sayHello|RESPONSE_HEAD`
19 `2018-11-29 15:19:14,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Sender I/O dispatcher-3|1|HTTP State Transition|http-outgoing-3|GET|http://0.0.0.0:10080/hello/sayHello|RESPONSE_BODY`
20 `2018-11-29 15:19:14,864|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Sender I/O dispatcher-3|0|HTTP State Transition|http-outgoing-3|GET|http://0.0.0.0:10080/hello/sayHello|RESPONSE_DONE`
21 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|1003|HTTP|admin--test:v1|GET|/testing/1/*|testing/1|null|null|null|null|null|71|73|200|DefaultApplication|AwlPOz2aDf2i1gZFWgITEgf4oPsa|1005`
22 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.CORSRequestHandler|handleResponse|[messageContext]`
23 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.APIAuthenticationHandler|handleResponse|[messageContext]`
24 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.throttling.ThrottleHandler|handleResponse|[messageContext]`
25 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.analytics.APIMgtUsageHandler|handleResponse|[mc]`
26 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.analytics.APIMgtGoogleAnalyticsTrackingHandler|handleResponse|[arg0]`
27 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.ext.APIManagerExtensionHandler|mediate|[messageContext, direction]`
28 `2018-11-29 15:19:14,868|ff0c8866-d8a8-4189-930d-016b9d92f1e8|PassThroughMessageProcessor-18|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.ext.APIManagerExtensionHandler|handleResponse|[messageContext]`
29 `2018-11-29 15:19:14,870|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|1011|HTTP State Transition|http-incoming-2|GET|/testing/1|RESPONSE_HEAD`
30 `2018-11-29 15:19:14,871|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|1|HTTP State Transition|http-incoming-2|GET|/testing/1|RESPONSE_BODY`
31 `2018-11-29 15:19:14,871|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|0|HTTP State Transition|http-incoming-2|GET|/testing/1|RESPONSE_DONE`
32 `2018-11-29 15:19:14,871|ff0c8866-d8a8-4189-930d-016b9d92f1e8|HTTP-Listener I/O dispatcher-2|1012|HTTP|http-incoming-2|GET|/testing/1|ROUND-TRIP LATENCY`

Line No	Description
1-2	HTTP State Transition when receiving the request
3-13	Methods invoked in Gateway handlers in the request path
14-15	Database calls irrelevant to the API call
16	HTTP State Transition for the request
17	Backend Latency Here the backend latency log have reflected the 800ms delay that was added to the backend for this example.
18-20	HTTP State Transition for response
21	Synapse global handler level for the backend call log
22-28	Methods invoked in the Gateway handlers in the response path
29-31	HTTP State Transition for dispatching response
32	HTTP Roundtrip Latency

Narrowing down a bottleneck using Observability¶

Scenario: A request sent to the API Manager takes a lot of time to respond back¶

This can happen due to several reasons,

Due to an programming error
Due to a backend service call taking time
Due to a database/ ldap call taking time

Follow the following steps to pinpoint the bottleneck,

You can list the times consumed by the code level, using the following command. This will help you to pinpoint method level latencies.

cat correlation.log | grep “|METHOD|” | cut -d “|” -f4 | sort -n

This will give the time consumed by each method in ascending order. If a method with a high time consumption is identified, then take the 5 most time consuming service and database calls, with the same correlation ID of the method logs, and find out the unusually time consuming call.

cat correlation.log | grep “correlationID” | grep “|HTTP” | cut -d “|” -f4 | sort -n
cat correlation.log | grep “correlationID” | grep “|jdbc|” | cut -d “|” -f4 | sort -n
cat correlation.log | grep “correlationID” | grep “|ldap|” | cut -d “|” -f4 | sort -n

Note

If a method with a high time consumption cannot be identified, but still a high latency is observed, the following command can be executed to find the highest time recorded.

cat correlation.log | cut -d “|” -f4 | sort -n

Then the entry that bears the highest duration can be found by serching the file for this time.

cat correlation.log | grep "<highest_time>"

Tip

Alternatively a log analyzing tool can be used as well to derive these information.

Advanced Use Cases¶

The following are the advanced use cases that you may run into when working with observability in WSO2 API-M.

Logging all methods¶

Currently, when using method logging, it only logs special methods that are suspected to give latencies, because logging all methods can pose performance issues. There can be instances where you may need to log other methods too.

In order to configure the logging of all methods, add the following configuration as a system property to the APIM startup script. This will log all methods executied in the given package.

Format

-DlogAllMethods=<package_name>

Example

For example, let's consider that you need to log all the methods for the gateway package.

-DlogAllMethods=org.wso2.carbon.apimgt.gateway

Note

Make sure to add it before org.wso2.carbon.bootstrap.Bootstrap $*.

Blacklisting threads¶

Blacklisting of threads is needed because some threads keep on printing unnecessary jdbc logs continuously. Therefore, by blacklisting these unwanted threads from printing logs, it helps to reduce the cluttering of the logs.

In order to enable blacklisting of threads, add the following configuration as a system property to the the APIM startup script.

Format

-Dorg.wso2.CorrelationLogInterceptor.BlacklistedThreads=<threadName1>,<threadName2>

Example

For example, let's assume you need to blacklist threads: pool-10-thread-1 and metrics-jdbc-reporter-1-thread-1

-Dorg.wso2.CorrelationLogInterceptor.BlacklistedThreads=pool-10-thread-1,metrics-jdbc-reporter-1-thread-1

Note

Make sure to add it before org.wso2.carbon.bootstrap.Bootstrap $*.

If the above configuration is not added, by default the MessageDeliveryTaskThreadPool thread will be blacklisted as it is found to print a considerable amount for messages for API-M instances. However, if the above configuration is added the default value will be overridden.

Blacklisting of threads is not needed by default, as all unnecessary threads are already blacklisted.

Top