Enabling log4jdbc to verify key caching funcionality in WSO2 API-Manager

1.   Configure API-Manager database (WSO2AM_DB)  of WSO2 API-Manager with MYSQL        
      (http://docs.wso2.org/display/AM160/Setting+up+with+MySQL)

2.   Place the log4j driver in <KEY_MANAGER_HOME>/repository/components/lib
      (https://log4jdbc.googlecode.com/files/log4jdbc4-1.2beta2.jar)

3.   Append the following to the <KEY_MANAGER_HOME>/repository/conf/log4j.properties file.

      ! Log all JDBC calls except for ResultSet calls 
      ! Log timing information about the SQL that is executed. 
      log4j.logger.jdbc.sqltiming=DEBUG,sqltiming 
      log4j.additivity.jdbc.sqltiming=false 
      ! the appender used for the JDBC API layer call logging above, sql timing 
      log4j.appender.sqltiming=org.apache.log4j.FileAppender 
      log4j.appender.sqltiming.File=./repository/logs/sqltiming.log 
      log4j.appender.sqltiming.Append=false 
      log4j.appender.sqltiming.layout=org.apache.log4j.PatternLayout 
      log4j.appender.sqltiming.layout.ConversionPattern=-----> %d{yyyy-MM-dd HH:mm:ss.SSS} %m%n%n                                                                                                                                         
      This configures the following:

• Log level (DEBUG) : Captures all debug level logs of package jdbc.sqltiming
• Appender (sqltiming) : Uses a FileAppender where all logs are logged in the file specified in property 'log4j.appender.sqltiming.File'
• Layout : Format to use when logging

4.   Replace the following in the WSO2AM_DB datasource of located in file :
      <KEY_MANAGER_HOME>/repository/conf/datasources/master-datasources.xml

• Append 'jdbc:log4j' to the beginning of the content of <url> element.

         <url>jdbc:log4jdbc:mysql://localhost:3306/WSO2AM_DB?relaxAutoCommit=true</url>

• Change the driver class to the following:

         <driverClassName>net.sf.log4jdbc.DriverSpy</driverClassName>

       log4jdbc driver uses log4j to log messages. When 'jdbc:log4j' is appended to the url, the service calls pass through the log4jdbc driver where they are logged and passed over to the mysql driver.

      Once the above changes are done your WSO2AM_DB datasource should look like this.

<datasource>
      <name>WSO2AM_DB</name>
      <description>Datasource for AM database</description>
      <jndiConfig>
              <name>jdbc/WSO2AM_DB</name>
      </jndiConfig>
      <definition type="RDBMS">
           <configuration>
                   <url>jdbc:log4jdbc:mysql://localhost:3306/WSO2AM_DB?relaxAutoCommit=true</url>
                   <username>wso2carbon</username>
                   <password>wso2carbon</password>
                   <driverClassName>net.sf.log4jdbc.DriverSpy</driverClassName>
                   <maxActive>50</maxActive>
                   <maxWait>60000</maxWait>
                   <testOnBorrow>true</testOnBorrow>
                   <validationQuery>SELECT 1</validationQuery>
                   <validationInterval>30000</validationInterval>
       </configuration>
       </definition>
  </datasource>

      Now logging is enabled.

To verify key manager caching :

1.  Open <KEY_MANAGER_HOME>/repository/conf/api-manager.xml file and enable/disable <EnableKeyMgtValidationInfoCache> as required.
2.  Open <GATEWAY_HOME>/repository/conf/api-manager.xml file and disable  <EnableGatewayKeyCache>
3.  Re-start both Gateway & Key Manager nodes.
4.  Copy <KEY_MANAGER_HOME>/repository/logs/sqltiming.log & save under a different name.
     cp sqltiming.log sqltiming.log.1
5.  Invoke the desired API.
6.  Take another copy of sqltiming.log and save under a new name.
     cp sqltiming.log sqltiming.log.2
7.  Verify the database calls by checking  the difference between logs.
     diff sqltiming.log.1 sqltiming.log.2

If KM caching is enabled :  The access token related database call  should be logged only once until the cache expires.
If KM caching is disabled:   The access token related database call should be logged everytime the API is invoked.
   
To verify gateway caching :

Gateway caching can be tested by verifying whether database calls are logged on the Key Manager node when gateway caching is enabled/disabled.

1.  Open <KEY_MANAGER_HOME>/repository/conf/api-manager.xml file and disable <EnableKeyMgtValidationInfoCache>
2.  Open <GATEWAY_HOME>/repository/conf/api-manager.xml file and enable/disable  <EnableGatewayKeyCache> as required.
3.  Re-start both Gateway & Key Manager nodes.
4.  Copy <KEY_MANAGER_HOME>/repository/logs/sqltiming.log & save under a different name.
     cp sqltiming.log sqltiming.log.1
5.  Invoke the desired API.
6.  Take another copy of sqltiming.log and save under a new name.
     cp sqltiming.log sqltiming.log.2
7.  Verify the database calls by checking  the difference between logs.
     diff sqltiming.log.1 sqltiming.log.2

If GW caching is enabled:  The access token related database call should be logged only once until the cache expires. (In this scenario only the first invocation hits the key manager. The sub subsequent invocations use the token related data in the gateway cache)

If GW caching is disabled:  The access token related database call should be logged everytime the API is invoked.   (In this scenario every invocation hits the key manager as token related data are not cached on the gateway)

Eg:
2014-09-30 11:49:15.013  org.wso2.carbon.apimgt.impl.d
ao.ApiMgtDAO.validateKey(ApiMgtDAO.java:541)
3. SELECT IAT.VALIDITY_PERIOD, IAT.TIME_CREATED , IAT.TOKEN_STATE, IAT.USER_TYPE, IAT.AUTHZ_USER, 
IAT.TIME_CREATED, SUB.TIER_ID, SUBS.USER_ID, SUB.SUB_STATUS, APP.APPLICATION_ID, APP.NAME, 
APP.APPLICATION_TIER, AKM.KEY_TYPE, API.API_NAME, AKM.CONSUMER_KEY, API.API_PROVIDER FROM IDN_OAUTH2_ACCESS_TOKEN 
IAT, AM_SUBSCRIPTION SUB, AM_SUBSCRIBER SUBS, AM_APPLICATION APP, AM_APPLICATION_KEY_MAPPING 
AKM, AM_API API WHERE IAT.ACCESS_TOKEN = '6ef853c12bfebc66771baea147352860' AND API.CONTEXT 
= '/echo' AND API.API_VERSION = '1.0.0' AND IAT.CONSUMER_KEY=AKM.CONSUMER_KEY AND SUB.APPLICATION_ID 
= APP.APPLICATION_ID AND APP.SUBSCRIBER_ID = SUBS.SUBSCRIBER_ID AND API.API_ID = SUB.API_ID 
AND AKM.APPLICATION_ID=APP.APPLICATION_ID  {executed in 4 msec}