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.
- Observability is not enabled by default as it impacts WSO2 API Manager's performance.
You need to get the latest product updates for your product to use this feature in the current version of WSO2 API-M. This feature is available as a product update from November 24, 2018 (11-24-2018) onwards.
Note that you can deploy updates in a production environment only if you have a valid subscription with WSO2. Read more about WSO2 Updates.
The following sections provide for more information on observability with regard to WSO2 API Manager.
Enabling observability on WSO2 API-M
Step 1 - Configure observability
Add the Log4J configurations so that a log file is created for the purpose of observability when API Manager server is started.
Add the following code to the<API-M_HOME>/repository/conf/log4j.properties
file.# correlation logs log4j.logger.correlation=INFO, CORRELATION log4j.additivity.correlation=false # Appender config for correlation logs log4j.appender.CORRELATION=org.apache.log4j.RollingFileAppender log4j.appender.CORRELATION.File=${carbon.home}/repository/logs/${instance.log}/correlation.log log4j.appender.CORRELATION.MaxFileSize=10MB log4j.appender.CORRELATION.layout=org.apache.log4j.PatternLayout log4j.appender.CORRELATION.Threshold=INFO log4j.appender.CORRELATION.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}|%X{Correlation-ID}|%t|%m%n
Note that the maximum file size of the correlation log is set to 10MB by default in the above configuration, which means that when the size of the file exceeds 10MB, a new log file is created. If required, you can change this file size.
Add the valve configurations for the purpose of deriving the correlation ID.
Add the following configurations under the<Host>
tag in the<API-M_HOME>/repository/conf/tomcat/catalina-server.xml
file.<Valve className="org.wso2.carbon.tomcat.ext.valves.RequestCorrelationIdValve" headerToCorrelationIdMapping="{'activityid':'Correlation-ID'}" queryToCorrelationIdMapping="{'RelayState':'Correlation-ID'}"/>
Add the Synapse Handler configurations to facilitate external call logging.
Add the following configurations as a handler after the<handler>
tag in the<API-M_HOME>/repository/conf/synapse-handlers.xml
file.<handler name="externalCallLogger" class="org.wso2.carbon.apimgt.gateway.handlers.LogsHandler"/>
Step 2 - Enable observability
If you want correlation logs to be enabled every time the server starts, add the following system property to the product startup script (stored in the <API-M_HOME>/bin/
directory) and set it to true.
Skip this step if you want to pass the system property to enable observability at the time of starting the WSO2 API-M server.
Step 3 - Start the WSO2 API-M server
Start the WSO2 API-M server.
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.
Types of correlation logs
The following are the types of logs that are available when working with observability in WSO2 API-M.
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:
timestamp | correlationID | threadName | duration | callType | className | methodName | methodArguments
2018-11-28 10:10:56,293|a783f7c3-647f-4d10-9b72-106faa01bba8|PassThroughMessageProcessor-3|0|METHOD|org.wso2.carbon.apimgt.gateway.handlers.security.CORSRequestHandler|handleRequest|[messageContext]
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. For more information, see Logging all methods.
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.
- Synapse global handler level external call logs
- Synapse passthrough transport level external call logs
Synapse global handler level external call logs
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:
timestamp | correlationID | threadName | duration(BE latency) | callType | apiName | apiMethod | apiContext | apiResourcePath | authHeader | orgIdHeader | SrcIdHeader | applIdHeader | uuIdHeader | requestSize | responseSize | apiResponseStatusCode | applicationName | consumerKey | responseTime
2018-11-28 10:10:56,316|a783f7c3-647f-4d10-9b72-106faa01bba8|PassThroughMessageProcessor-4|20|HTTP|admin--PizzaShackAPI:v1.0.0|GET|/pizzashack/1.0.0/menu|pizzashack/1.0.0/menu|null|null|null|null|null|71|2238|200|DefaultApplication|Fslkdjfnlsdfjiefnlsdf|21
Synapse passthrough transport level external call logs
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:
timestamp|correlationID|threadName|duration|callType|connectionName|methodType|connectionURL|httpState
2018-11-28 10:10:56,314|a783f7c3-647f-4d10-9b72-106faa01bba8|HTTPS-Sender I/O dispatcher-1|1|HTTP State Transition|http-outgoing-1|GET|https://localhost:9443/am/sample/pizzashack/v1/api/menu|RESPONSE_DONE
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.
The format for a database call log entry is as follows:
JDBC call logs
Formattimestamp | correlationID | threadID | duration | callType | startTime | methodName | query | connectionUrl
Example2018-11-28 10:10:43,202|a783f7c3-647f-4d10-9b72-106faa01bba8|PassThroughMessageProcessor-1|0|jdbc|1543380043202|executeQuery|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=?|jdbc:h2:repository/database/WSO2CARBON_DB
LDAP call logs
Formattimestamp | correlationID | threadID | duration | callType | startTime | methodName | providerUrl | principal | argsLengeth | args
Example2018-11-0514:05:18,599|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|200|ldap|1541406918591|search|ldap://localhost:10389|uid=admin,ou=system|3| uid=admin,ou=Users,dc=WSO2,dc=ORG,(&(objectClass=person)(uid=admin)),javax.naming.directory.SearchControls@548e9a48
Using the correlation logs
Follow the instructions below to check the correlation logs:
Step 1 - Setup WSO2 API-M
Enable observability with WSO2 API-M and start the WSO2 API-M server.
For more information, see Enabling observability with WSO2 API-M.
Step 2 - Invoke an API
Follow the instructions below to invoke an API.
- Create and publish an API.
For more information, see Create and Publish an API. - Subscribe to an API.
For more information, see steps 1 to 10 under Subscribe to an API. Invoke the API.
The following is based on the PhoneVerification API.
Step 3 - Check the correlation logs
- Open a terminal and navigate to the
<API-M_HOME>/repository/logs
directory where thecorrelation.log
file is saved. Isolate the logs that are correlated.
Replace<correlation_ID>
with the required value.cat correlation.log | grep "<correlation_ID>"
Reading and analyzing the correlation logs
Let's analyze the following sample correlation log.
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 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 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] 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|[] 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] 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|[] 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] 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] 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] 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] 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] 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] 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] 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 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 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 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 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 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 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 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 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] 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] 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] 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] 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] 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] 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] 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 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 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 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 relevant to the API call |
16 | HTTP State Transition for the request |
17 | Backend Latency |
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 |
Using these logs we can determine that the latency is caused by the backend call.
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.
Follow the instructions below to configure the logging of all methods.
Blacklisting threads
Blacklisting of threads is needed because some threads keep on printing unnecessary logs continuously. Therefore, by blacklisting unwanted threads from printing logs it helps in terms of readability of the logs.
Follow the instructions below to enable blacklisting of threads:
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.