Page Comparison

...

Configuring Product Observability

Note

By default, product observability is not enabled as it impacts on the product's performance.

In order to use this feature, apply the WUM update for WSO2 IS 5.5.0 released on 2018-11-28.

Warning
If you want to deploy a WUM update into production, you need to have a paid subscription. If you do not have a paid subscription, you can use this feature with the next version of WSO2 Identity Server when it is released. For more information on updating WSO2 Identity Server using WUM, see Getting Started with WUM in the WSO2 Administration Guide.

Auitabs

direction	horizontal

Auitabspage

title

Let's explore the following topics to learn more:

Table of Contents

maxLevel	3
minLevel	3

Configuring product observability

The configurations are two-fold

...

:

Enabling Observability

Table of Content Zone

location	top

log4j configs

Follow the steps below to

setup

set up the correlation logs related to the database calls.

Open the log4j.properties file in the <IS_HOME>/repository/conf directory.

Add the following code to it.

Code Block

# Appender config to put correlation Log.
log4j.logger.correlation=INFO, CORRELATION
log4j.additivity.correlation=false
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.

Value Configs

ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}|%X{Correlation-ID}|%t|%m%n

Tomcat valve configs

Follow the steps below to

setup

set up the correlation ID mapping between the request database call and the response database call.

Open the catalina-server.xml file in the <IS_HOME>/repository/conf/tomcat directory.
Add the following value under the <Host> tag.

Auitabspage

title

Code Block

<Valve className="org.wso2.carbon.tomcat.ext.valves.RequestCorrelationIdValve"
                       headerToCorrelationIdMapping="{'activityid':'Correlation-ID'}" queryToCorrelationIdMapping="{'RelayState':'Correlation-ID'}"/>

Note
This should be the first valve under the `<Host>` tag.

Enabling observability

Follow the steps below to enable product observability.

Navigate to the <IS_HOME>/bin directory on the command prompt.
Code Block
cd <IS_HOME>/bin

To set the -DenableCorrelationLogs property to true, execute the following command.

Code Block
For Mac/Linux --> sh wso2server.sh -DenableCorrelationLogs=true start For Windows --> wso2server.bat -DenableCorrelationLogs=true start

Note
By default, this property is set to `false`.

Navigate to

...

the <IS_HOME>/repository/logs

...

directory.
Code Block
cd <IS_HOME>/repository/logs
Notice that a separate log file

...

called correlation.log

...

is created.
Image Added

Now you are ready to test the product observability of WSO2 IS.

Tip

In order to test product observability, make sure you create a service provider and generate client key and

cilent

client secret, with which you can perform a secure database call. For more information on creating service providers, see Adding a Service Provider.

Auitabspage

title

Log

...

patterns

Following are the log patterns that support product observability.

verticalJDBC Format

Table of Content Zone

location	top
direction	vertical

JDBC database call logging

Format:

Example:

LDAP Format

Code Block
timestamp \| correlationID \| threadID \| duration \| callType \| startTime \| methodName \| query \| connectionUrl

Example:

Code Block

Eg:
2018-10-22 17:54:46,869|cf57a4a6-3ba7-46aa-8a2b-f02089d0172c|http-nio-9443-exec-2|4|jdbc|1540211086865|executeQuery|SELECT ID, TENANT_ID, IDP_ID, PROVISIONING_CONNECTOR_TYPE, IS_ENABLED, IS_BLOCKING  FROM IDP_PROVISIONING_CONFIG WHERE IDP_ID=?|jdbc:mysql://localhost:13306/apimgtdb?autoReconnect=true&useSSL=false

LDAP database call logging

Format:

Code Block
timestamp \| correlationID \| threadID \| duration \| callType \| startTime \| methodName \| providerUrl \| principal \| argsLengeth \| args

Example:

Request Beginning

Code Block

2018-10-2310:55:02,279|c4eaede8-914d-4712-b630-73f6534b8def|http-nio-9443-exec-18|19|ldap|1540272302260|search|ldap://localhost:10392|uid=admin,ou=system| ou=Users,dc=wso2,dc=org,(&(objectClass=person)(uid=admin)),javax.naming.directory.SearchControls@6359ae3a

Beginning of the request call

Main:

Code Block
timestamp \| correlationID \| threadID \| duration \| HTTP-In-Request \| startTime \| methodName \| requestQuery \| requestPath

Example:

Request Ending

Code Block
2018-11-0514:57:06,757\|f884a93d-e3a3-431f-a1ea-f6973e125cb6\|http-nio-9443-exec-28\|0\|HTTP-In-Request\|1541410026757\|GET\|null\|/carbon/admin/images/favicon.ico

Ending of the request call

Format:

Code Block
timestamp \| correlationID \| threadID \| totalDurationForRequest \| HTTP-In-Response \| startTime \| methodName \| requestQuery \| requestPath

Example:

title

Auitabspage
Code Block
2018-11-05 14:57:06,764\|f884a93d-e3a3-431f-a1ea-f6973e125cb6\|http-nio-9443-exec-28\|7\|HTTP-In-Response\|1541410026764\|GET\|null\|/carbon/admin/images/favicon.ico

Reading the

...

logs

Let's analyze the following sample log lines to find if there are any timing delays for the JDBC or LDAP calls.

Code Block

linenumbers	true

2018-11-0514:05:18,427|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|HTTP-In-Request|1541406918427|POST|null|/carbon/admin/login_action.jsp

Code Block

firstline	2
linenumbers	true

2018-11-0514:05:18,581|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|jdbc|1541406918581|executeQuery|SELECT * FROM IDN_RECOVERY_DATA WHERE USER_NAME = ? AND USER_DOMAIN = ? AND TENANT_ID = ?|jdbc:h2:./repository/database/WSO2CARBON_DB

Code Block

firstline	3
linenumbers	true

2018-11-0514:05:18,591|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|7|ldap|1541406918584|initialization|ldap://localhost:10389|uid=admin,ou=system|0|empty

Code Block

firstline	4
linenumbers	true

2018-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

Code Block

firstline	5
linenumbers	true

2018-11-0514:05:18,610|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|jdbc|1541406918610|executeQuery|SELECT DATA_KEY, DATA_VALUE FROM IDN_IDENTITY_USER_DATA WHERE TENANT_ID = ? AND USER_NAME = ?|jdbc:h2:./repository/database/WSO2CARBON_DB

Code Block

firstline	6
linenumbers	true

2018-11-0514:05:18,632|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|16|ldap|1541406918616|initialization|ldap://localhost:10389|uid=admin,ou=system|0|empty

Code Block

firstline	7
linenumbers	true

2018-11-0514:05:18,641|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|jdbc|1541406918641|executeQuery|SELECT UM_ROLE_NAME, UM_RESOURCE_ID, UM_IS_ALLOWED, UM_ACTION, UM_DOMAIN_NAME FROM UM_PERMISSION, UM_ROLE_PERMISSION, UM_DOMAIN WHERE UM_ROLE_PERMISSION.UM_PERMISSION_ID=UM_PERMISSION.UM_ID AND UM_ROLE_PERMISSION.UM_DOMAIN_ID=UM_DOMAIN.UM_DOMAIN_ID AND UM_PERMISSION.UM_TENANT_ID=? AND UM_ROLE_PERMISSION.UM_TENANT_ID=?|jdbc:h2:./repository/database/WSO2CARBON_DB

Code Block

firstline	8
linenumbers	true

2018-11-0514:05:18,642|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|jdbc|1541406918642|executeQuery|SELECT UM_USER_NAME, UM_RESOURCE_ID, UM_IS_ALLOWED, UM_ACTION FROM UM_PERMISSION, UM_USER_PERMISSION WHERE UM_USER_PERMISSION.UM_PERMISSION_ID=UM_PERMISSION.UM_ID AND UM_PERMISSION.UM_TENANT_ID=? AND UM_USER_PERMISSION.UM_TENANT_ID=?|jdbc:h2:./repository/database/WSO2CARBON_DB

Code Block

firstline	9
linenumbers	true

2018-11-0514:05:18,696|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|0|jdbc|1541406918696|executeQuery|SELECT UM_RESOURCE_ID FROM UM_PERMISSION WHERE UM_ACTION=? AND UM_TENANT_ID=?|jdbc:h2:./repository/database/WSO2CARBON_DB

Code Block

firstline	10
linenumbers	true

2018-11-0514:05:18,715|86b56b19-7872-4e2f-84f3-5a14f92e18c1|http-nio-9443-exec-8|480|HTTP-In-Response|1541406918715|POST|null|/carbon/admin/login_action.jsp

Line 1 is

...

the http-in-request.
Line 10 is

...

the http-in-response, which shows that the total time taken for the cycle

...

is 480 ms. This is almost close to half a second. With that we can assume that there is a delay with either an LDAP or JDBC call.
When we carefully analyze each line, we can see that all JDBC calls have taken less

...

than 5 ms.
Line 4 however, indicates an LDAP call that has

...

taken 200 ms, which can be a possible reason for this issue.

...

title	Advance Scenarios

Advanced scenarios

Following are a few advance scenarios that are related to product observability in WSO2 IS.

Table of Content Zone

location	top
direction	vertical

Blacklisting the

Threads

threads

Certain threads continuously print

unneccessary

unnecessary logs. Blacklisting prevents the unwanted threads from printing logs thereby improving the

readibility

readability of the logs.

Follow the steps below to configure thread blacklisting.

Open either of the following files in the <IS_HOME>/bin directory on a command prompt.
1. For Mac/Linux: wso2server.sh file
2. For Windows: wso2server.bat file
Add the following configuration as a system property.
Code Block
-Dorg.wso2.CorrelationLogInterceptor.BlacklistedThreads=threadName1,threadName2 \
Tip
Make sure to add it before the org.wso2.carbon.bootstrap.Bootstrap $* line.
Note
This configuration is not required by default, as all

unneccesary

unnecessary threads are already blacklisted by the MessageDeliveryTaskThreadPool thread. If the above configuration is added, the default value will be overridden.
Restart the WSO2 IS server.
Code Block

Single Header Configs

sh wso2server.sh -DenableCorrelationLogs=true stop
sh wso2server.sh -DenableCorrelationLogs=true start

Single header configs

By default, RequestCorrelationIdValve in the catalina-server.xml file in the <IS_HOME>/repository/conf/tomcat directory is configured to map to the value sent by the activityid header as the Correlation ID. You can change this by editing the RequestCorrelationIdValve by replacing the activityid with any other headerName that you will be sending.

Let's consider an authentication request that is sent with a new header configuration.

Change the RequestCorrelationIdValve in the cataline-server.xml file to the value given below.

Code Block

<Valve className="org.wso2.carbon.tomcat.ext.valves.RequestCorrelationIdValve"
                      headerToCorrelationIdMapping="{'customHeader':'Correlation-ID'}" queryToCorrelationIdMapping="{'RelayState':'Correlation-ID'}"/>

Restart the WSO2 IS Server.

Code Block
sh wso2server.sh -DenableCorrelationLogs=true stop sh wso2server.sh -DenableCorrelationLogs=true start

To send the authentication request, execute the following cURL command.

Code Block

curl -v -k -X POST --basic -u <CLIENT_KEY>:<CLIENT_SECRET> -H "Content-Type: application/x-www-form-urlencoded;charset=UTF-8" -H "customHeader:correlationvalue" -d "grant_type=client_credentials" https://localhost:9443/oauth2/token

Tip
Use the `client key` and `client secret` of the service provider you created after enabling product observability

Open the correlation.log on a command prompt and notice the related logs.
Code Block

Multiple Header Configs

tail -f ../repository/logs/correlation.log

Image Added

Multiple header configs

Even though the default configuration maps a single header to a single Correlation ID, it is possible to add multiple headers and map them to multiple Correlation IDs.

Let's consider an authentication request that is sent with multiple headers.

Change the RequestCorrelationIdValve in the cataline-server.xml file to the value given below.

Code Block

language	java

<Valve className="org.wso2.carbon.tomcat.ext.valves.RequestCorrelationIdValve"
                      headerToCorrelationIdMapping="{'customHeader1':'Correlation-ID', 'customHeader2':'Second-Correlation-ID'}" queryToCorrelationIdMapping="{'RelayState':'Correlation-ID'}"/>

Change the log4j.appender.CORRELATION.layout.ConversionPattern appender in the log4j.properties file in the <IS_HOME>/repository/conf/ directory as follows.
Code Block
log4j.appender.CORRELATION.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}|%X{Correlation-ID}|%X{Second-Correlation-ID}|%t|%m%n

Restart the WSO2 IS server.

Code Block
sh wso2server.sh -DenableCorrelationLogs=true stop sh wso2server.sh -DenableCorrelationLogs=true start

To send the authentication request, execute the following cURL command.

Code Block

curl -v -k -X POST --basic -u <CLIENT_KEY>:<CLIENT_SECRET> -H "Content-Type: application/x-www-form-urlencoded;charset=UTF-8" -H "customHeader1:correlationvalue1" -H "customHeader2:correlationvalue2" -d "grant_type=client_credentials" https://localhost:9443/oauth2/token

Tip
Use the `client key` and `client secret` of the service provider you created after enabling product observability

Open the correlation.log on a command prompt and notice the related logs.
Code Block
tail -f ../repository/logs/correlation.log
Image Added

Versions Compared

Old Version 9

New Version 10

Key

Configuring product observability

log4j configs

Tomcat valve configs

Enabling observability

Log

patterns

JDBC database call logging

LDAP database call logging

Beginning of the request call

Ending of the request call

Reading the

logs

Advanced scenarios

Blacklisting the

threads

Single header configs

Multiple header configs