Skip to content

Work with Product Observability

Product observability enables rapid debugging of product issues. WSO2 Identity Server (MWARE IAM) facilitates product observability by logging the time taken for LDAP and JDBC database calls. This helps to track down any latencies caused by database calls in an instance. The request calls and response calls are correlated via a correlation ID that is sent in the request call.

Correleation ID

Note

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

Configure product observability

log4j configs

Follow the steps below to set up the correlation logs related to the database calls.

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

  2. Append the appender CORRELATION to the list of all appenders as follows.

    appenders = CARBON_CONSOLE, CARBON_LOGFILE, AUDIT_LOGFILE, ATOMIKOS_LOGFILE, CARBON_TRACE_LOGFILE, 
DELETE_EVENT_LOGFILE, TRANSACTION_LOGFILE, osgi, CORRELATION
    3. Append the loggger correlation for list of all loggers as follows. 

    loggers = AUDIT_LOG, trace-messages, org-apache-coyote, com-hazelcast, Owasp-CsrfGuard, 
org-apache-axis2-wsdl-codegen-writer-PrettyPrinter, org-apache-axis2-clustering, org-apache-catalina, 
org-apache-tomcat, org-wso2-carbon-apacheds, org-apache-directory-server-ldap, org-apache-directory-server-core-event, com-atomikos, org-quartz, org-apache-jackrabbit-webdav, org-apache-juddi, org-apache-commons-digester-Digester, org-apache-jasper-compiler-TldLocationsCache, org-apache-qpid, org-apache-qpid-server-Main, qpid-message, qpid-message-broker-listening, org-apache-tiles, org-apache-commons-httpclient, org-apache-solr, me-prettyprint-cassandra-hector-TimingLogger, org-apache-axis-enterprise, org-apache-directory-shared-ldap, org-apache-directory-server-ldap-handlers, org-apache-directory-shared-ldap-entry-DefaultServerAttribute, org-apache-directory-server-core-DefaultDirectoryService, org-apache-directory-shared-ldap-ldif-LdifReader, org-apache-directory-server-ldap-LdapProtocolHandler, org-apache-directory-server-core, org-apache-directory-server-ldap-LdapSession, DataNucleus, Datastore, Datastore-Schema, JPOX-Datastore, JPOX-Plugin, JPOX-MetaData, JPOX-Query, JPOX-General, JPOX-Enhancer, org-apache-hadoop-hive, hive, ExecMapper, ExecReducer, net-sf-ehcache, axis2Deployment, equinox, tomcat2, StAXDialectDetector, org-apache-directory-api, org-apache-directory-api-ldap-model-entry, TRANSACTION_LOGGER, DELETE_EVENT_LOGGER, org-springframework, org-opensaml-xml-security-credential-criteria, org-wso2-carbon-user-core, org-wso2-carbon-identity, org-wso2-carbon-identity-sso-saml, correlation
    4. Following are the default correlation appender configuration. You can change any of these values using the log4j2 .properties. 

    appender.CORRELATION.type = RollingFile
appender.CORRELATION.name = CORRELATION
appender.CORRELATION.fileName =${sys:carbon.home}/repository/logs/correlation.log
appender.CORRELATION.filePattern =${sys:carbon.home}/repository/logs/correlation-%d{MM-dd-yyyy}.log
appender.CORRELATION.layout.type = PatternLayout
appender.CORRELATION.layout.pattern = %d{yyyy-MM-dd HH:mm:ss,SSS}|%X{Correlation-ID}|%t|%mm%n
appender.CORRELATION.policies.type = Policies
appender.CORRELATION.policies.time.type = TimeBasedTriggeringPolicy
appender.CORRELATION.policies.time.interval = 1
appender.CORRELATION.policies.time.modulate = true
appender.CORRELATION.policies.size.type = SizeBasedTriggeringPolicy
appender.CORRELATION.policies.size.size=10MB
appender.CORRELATION.strategy.type = DefaultRolloverStrategy
appender.CORRELATION.strategy.max = 20
appender.CORRELATION.filter.threshold.type = ThresholdFilter
appender.CORRELATION.filter.threshold.level = INFO

Enable observability

Follow the steps below to enable product observability.

  1. Navigate to the <IS_HOME>/bin directory on the command prompt.

    cd <IS_HOME>/bin

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

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

    Note

    By default, this property is set to false .

  3. Navigate to the <IS_HOME>/repository/logs directory.

    cd <IS_HOME>/repository/logs

    Notice that a separate log file called correlation.log is created.

    Correlation.log

Now you are ready to test the product observability of MWARE IAM.

Tip

In order to test product observability, make sure you create a service provider and generate client key and client secret, with which you can perform a secure database call.

Log patterns

Following are the log patterns that support product observability.

JDBC database call logging

Format 

timestamp | correlationID | threadID | duration | callType | startTime | methodName | query | connectionUrl

Example 

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 

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

Example 

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

Format 

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

Example 

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 

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

Example 

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

Read the logs

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

  1. 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
  2. 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
  3. 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
  4. 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
  5. 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
  6. 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
  7. 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
  8. 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
  9. 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
  10. 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.

Advanced scenarios

Following are a few advance scenarios that are related to product observability in MWARE IAM.

Define denylists for the threads

Certain threads continuously print unnecessary logs. Defining denylists prevents the unwanted threads from printing logs thereby improving the readability of the logs.

Follow the steps below to configure denylists for threads.

  1. 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

  2. Add the following configuration as a system property.

    -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 unnecessary threads are already a part of the denylist in the MessageDeliveryTaskThreadPool thread. If the above configuration is added, the default value will be overridden.

  3. Restart the MWARE IAM server.

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

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

    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.

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

    tail -f https://iam-docs.m-ware.eu/en/6.1.0/repository/logs/correlation.log

    Correlation log screenshot

Top