Utilizing Improved Observability of WSO2 API Manager
Observability is an important aspect of a system. The observability of a software system is really important to debug issues in a short period of time. To address this concern, the WSO2 API Manager have implemented a solution to log different important points of the system, with the time taken to achieve them. This solution will consist of three types points that will be logged.
- Method Calls
- External Calls (HTTP/HTTPS)
- Database Calls (JDBC and LDAP)
In our effort to provide observability, we have given the users the facility to correlate these three types of calls with the help of a correlationID.
A random correlation id is generated within the api manager for each transaction. A unique correlation id can be provided by adding the header, “activityid” to the request sent to the API Manager.
Observability features can be activated by simply adding a system property named enableCorrelationLogs with the value true. This system property can be added to the wso2server script file as shown below,
-DenableCorrelationLogs=true
The log file can be found in the following path:
<CARBON_HOME>/repository/logs/correlation.log.
1. Method Calls
Once correlation logging is enabled, the api manager logs the time taken to execute certain important methods of the modules, gateway, keymgt and impl. These important methods are marked with an annotation, @MethodStats. This annotation can be found in both method level and class level. If this annotation is given to a class, all the methods of the respective class are included for logging. If all methods of a package are required to be logged, the package name needs to be given as the value of the system property, logAllMethods. The format of the method logging is given below,
timestamp | correlationID | threadName | duration | callType | className | methodName | methodArguments
2. External Calls
The observability feature offers two types of external call logging.
Synapse global handler level
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 the synapse global handler level external call logging can be found below,
timestamp | correlationID | threadName | duration(BE latency) | callType | apiName | apiMethod | apiContext | apiResourcePath | authHeader | orgIdHeader | SrcIdHeader | applIdHeader | uuIdHeader | requestSize | responseSize | apiResponseStatusCode | applicationName | consumerKey | responseTime
Synapse passthrough transport level
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 the synapse passthrough transport level external call logging can be found below,
timestamp|correlationID|threadName|duration|callType|connectionName|methodType|connectionURL|httpState
3. Database Calls
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.
The format for database call logging is given below,
JDBC
timestamp | correlationID | threadID | duration | callType | startTime | methodName | query | connectionUrl
LDAP
timestamp | correlationID | threadID | duration | callType | startTime | methodName | providerUrl | principal | argsLengeth | args
Utilizing these logs to gather information
Now that we have gone through the theory :), let’s focus on how to utilize these logs in a practical scenario.
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 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. Then if there is no noticeably significant time consumption by some method, take the five methods with the largest time consumption, and pick the method with the unusually high time consumption.
2. If a clear method with a high time consumption cannot be identified, 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 “|DB_CALL|” | cut -d “|” -f4 | sort -n
Observability features are now available for WSO2 API Manager 2.1.0, 2.5.0 and 2.6.0, via the latest wum updates, and also in our git repository (https://github.com/wso2/product-apim/tree/2.x). When obtaining these features with wum updates, please make sure to follow the instructions available in the update summary.
A demonstration video of the observability features is available via the following link, https://youtu.be/qWlXHNRyHBE
I really hope that this article would have helped you to setup observability for the WSO2 API Manager.
