Let's see how to use log4jdbc with WSO2 API Manager.
First, download log4jdbc driver from here. Then, copy it into <APIM_HOME>/repository/components/lib directory.
Then, change JDBC <url> and <driverClassName> of master-datasource.xml in <APIM_HOME>/repository/conf/datasources directory as shown below. Change the every datasource that you want to log. Here, I'm changing datasource of "WSO2AM_DB".
<datasource> <name>WSO2AM_DB</name> <description>The datasource used for API Manager database</description> <jndiConfig> <name>jdbc/WSO2AM_DB</name> </jndiConfig> <definition type="RDBMS"> <configuration> <url>jdbc:log4jdbc:h2:repository/database/WSO2AM_DB;DB_CLOSE_ON_EXIT=FALSE</url> <username>wso2carbon</username> <password>wso2carbon</password> <defaultAutoCommit>false</defaultAutoCommit> <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>
Note: When you are changing JDBC url, you have to add "log4jdbc" part to the url.
Then, you can add logging options to log4j.properties file of <APIM_HOME>/repository/conf directory. There are several logging options.
i. jdbc.sqlonly
If we use this log, it logs all the SQLs executed by Java Code.
If you want to enable that logs of your server, add below line to log4.properties file.
log4j.logger.jdbc.sqlonly=INFO
Then restart the server and you will see logs like below.
[2016-12-31 23:26:35,099] INFO - JMSListener Started to listen on destination : throttleData of type topic for listener Siddhi-JMS-Consumer#throttleData [2016-12-31 23:26:55,502] INFO - CarbonEventManagementService Starting polling event receivers [2016-12-31 23:27:16,213] INFO - sqlonly SELECT 1 [2016-12-31 23:27:16,214] INFO - sqlonly select * from AM_BLOCK_CONDITIONS [2016-12-31 23:27:16,214] INFO - sqlonly SELECT KEY_TEMPLATE FROM AM_POLICY_GLOBAL [2016-12-31 23:37:24,224] INFO - PermissionUpdater Permission cache updated for tenant -1234 [2016-12-31 23:37:24,316] INFO - CarbonAuthenticationUtil 'admin@carbon.super [-1234]' logged in at [2016-12-31 23:37:24,316+0530] [2016-12-31 23:37:24,587] INFO - sqlonly SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI' AND API.API_VERSION = '1.0.0' [2016-12-31 23:37:24,589] INFO - sqlonly SELECT CAST( SUM(RATING) AS DECIMAL)/COUNT(RATING) AS RATING FROM AM_API_RATINGS WHERE API_ID =2 GROUP BY API_ID [2016-12-31 23:37:24,590] INFO - sqlonly SELECT * FROM AM_API WHERE API_ID = 2 [2016-12-31 23:37:24,590] INFO - sqlonly SELECT NAME FROM AM_POLICY_SUBSCRIPTION WHERE TENANT_ID =-1234 [2016-12-31 23:37:24,593] INFO - sqlonly SELECT grp.CONDITION_GROUP_ID ,AUM.HTTP_METHOD,AUM.AUTH_SCHEME, pol.APPLICABLE_LEVEL, AUM.URL_PATTERN,AUM.THROTTLING_TIER,AUM.MEDIATION_SCRIPT,AUM.URL_MAPPING_ID FROM AM_API_URL_MAPPING AUM INNER JOIN AM_API API ON AUM.API_ID = API.API_ID LEFT OUTER JOIN AM_API_THROTTLE_POLICY pol ON AUM.THROTTLING_TIER = pol.NAME LEFT OUTER JOIN AM_CONDITION_GROUP grp ON pol.POLICY_ID = grp.POLICY_ID where API.CONTEXT= '/pizzashack/1.0.0' AND API.API_VERSION = '1.0.0' ORDER BY AUM.URL_MAPPING_ID [2016-12-31 23:37:24,596] INFO - sqlonly SELECT DISTINCT SB.USER_ID, SB.DATE_SUBSCRIBED FROM AM_SUBSCRIBER SB, AM_SUBSCRIPTION SP, AM_APPLICATION APP, AM_API API WHERE API.API_PROVIDER='admin' AND API.API_NAME='PizzaShackAPI' AND API.API_VERSION='1.0.0' AND SP.APPLICATION_ID=APP.APPLICATION_ID AND APP.SUBSCRIBER_ID=SB.SUBSCRIBER_ID AND API.API_ID = SP.API_ID AND SP.SUBS_CREATE_STATE = 'SUBSCRIBE' [2016-12-31 23:37:31,323] INFO - sqlonly SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI' AND API.API_VERSION = '1.0.0' [2016-12-31 23:37:31,327] INFO - sqlonly SELECT CAST( SUM(RATING) AS DECIMAL)/COUNT(RATING) AS RATING FROM AM_API_RATINGS WHERE API_ID =2 GROUP BY API_ID [2016-12-31 23:37:31,327] INFO - sqlonly SELECT * FROM AM_API WHERE API_ID = 2 [2016-12-31 23:37:31,327] INFO - sqlonly SELECT NAME FROM AM_POLICY_SUBSCRIPTION WHERE TENANT_ID =-1234
ii. jdbc.sqltiming
If we use this log, it logs time taken by each JDBC call.
If you want to enable that logs of your server, add below line to log4.properties file.
log4j.logger.jdbc.sqltiming=INFO
Then restart the server and you will see logs like below.
[2016-12-31 23:42:02,597] INFO - PermissionUpdater Permission cache updated for tenant -1234
[2016-12-31 23:42:02,682] INFO - CarbonAuthenticationUtil 'admin@carbon.super [-1234]' logged in at [2016-12-31 23:42:02,682+0530]
[2016-12-31 23:42:02,912] INFO - sqltiming SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI'
AND API.API_VERSION = '1.0.0'
{executed in 1 msec}
[2016-12-31 23:42:02,913] INFO - sqltiming SELECT CAST( SUM(RATING) AS DECIMAL)/COUNT(RATING) AS RATING FROM AM_API_RATINGS WHERE API_ID
=2 GROUP BY API_ID
{executed in 0 msec}
[2016-12-31 23:42:02,913] INFO - sqltiming SELECT * FROM AM_API WHERE API_ID = 2
{executed in 0 msec}
[2016-12-31 23:42:02,914] INFO - sqltiming SELECT NAME FROM AM_POLICY_SUBSCRIPTION WHERE TENANT_ID =-1234
{executed in 0 msec}
[2016-12-31 23:42:02,917] INFO - sqltiming SELECT grp.CONDITION_GROUP_ID ,AUM.HTTP_METHOD,AUM.AUTH_SCHEME, pol.APPLICABLE_LEVEL, AUM.URL_PATTERN,AUM.THROTTLING_TIER,AUM.MEDIATION_SCRIPT,AUM.URL_MAPPING_ID
FROM AM_API_URL_MAPPING AUM INNER JOIN AM_API API ON AUM.API_ID = API.API_ID LEFT OUTER JOIN
AM_API_THROTTLE_POLICY pol ON AUM.THROTTLING_TIER = pol.NAME LEFT OUTER JOIN AM_CONDITION_GROUP
grp ON pol.POLICY_ID = grp.POLICY_ID where API.CONTEXT= '/pizzashack/1.0.0' AND API.API_VERSION
= '1.0.0' ORDER BY AUM.URL_MAPPING_ID
{executed in 0 msec}
[2016-12-31 23:42:02,920] INFO - sqltiming SELECT DISTINCT SB.USER_ID, SB.DATE_SUBSCRIBED FROM AM_SUBSCRIBER SB, AM_SUBSCRIPTION SP, AM_APPLICATION
APP, AM_API API WHERE API.API_PROVIDER='admin' AND API.API_NAME='PizzaShackAPI' AND API.API_VERSION='1.0.0'
AND SP.APPLICATION_ID=APP.APPLICATION_ID AND APP.SUBSCRIBER_ID=SB.SUBSCRIBER_ID AND API.API_ID
= SP.API_ID AND SP.SUBS_CREATE_STATE = 'SUBSCRIBE'
{executed in 0 msec}
[2016-12-31 23:42:12,871] INFO - sqltiming SELECT 1
{executed in 0 msec}
[2016-12-31 23:42:12,872] INFO - sqltiming SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI'
AND API.API_VERSION = '1.0.0'
{executed in 0 msec}
[2016-12-31 23:42:12,872] INFO - sqltiming SELECT CAST( SUM(RATING) AS DECIMAL)/COUNT(RATING) AS RATING FROM AM_API_RATINGS WHERE API_ID
=2 GROUP BY API_ID
{executed in 0 msec}
[2016-12-31 23:42:12,873] INFO - sqltiming SELECT * FROM AM_API WHERE API_ID = 2
{executed in 0 msec}
[2016-12-31 23:42:12,873] INFO - sqltiming SELECT * FROM AM_POLICY_SUBSCRIPTION WHERE TENANT_ID =-1234
{executed in 0 msec}
[2016-12-31 23:42:12,874] INFO - sqltiming SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI'
AND API.API_VERSION = '1.0.0'
{executed in 0 msec}
[2016-12-31 23:42:12,875] INFO - sqltiming SELECT A.SCOPE_ID, A.SCOPE_KEY, A.NAME, A.DESCRIPTION, A.ROLES FROM IDN_OAUTH2_SCOPE AS A INNER
JOIN AM_API_SCOPES AS B ON A.SCOPE_ID = B.SCOPE_ID WHERE B.API_ID = 2
{executed in 0 msec}
[2016-12-31 23:42:12,875] INFO - sqltiming SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI'
AND API.API_VERSION = '1.0.0'
{executed in 0 msec}
[2016-12-31 23:42:12,875] INFO - sqltiming SELECT URL_PATTERN, HTTP_METHOD, AUTH_SCHEME, THROTTLING_TIER, MEDIATION_SCRIPT FROM AM_API_URL_MAPPING
WHERE API_ID = 2 ORDER BY URL_MAPPING_ID ASC
{executed in 0 msec}
[2016-12-31 23:42:12,876] INFO - sqltiming SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = 'admin' AND API.API_NAME = 'PizzaShackAPI'
AND API.API_VERSION = '1.0.0'
{executed in 0 msec}
[2016-12-31 23:42:12,876] INFO - sqltiming SELECT RS.RESOURCE_PATH, S.SCOPE_KEY FROM IDN_OAUTH2_RESOURCE_SCOPE RS INNER JOIN IDN_OAUTH2_SCOPE
S ON S.SCOPE_ID = RS.SCOPE_ID INNER JOIN AM_API_SCOPES A ON A.SCOPE_ID = RS.SCOPE_ID WHERE
A.API_ID = 2
{executed in 0 msec}
iii. jdbc.audit
If we use this log, it logs all the activities of the JDBC call.
If you want to enable that logs of your server, add below line to log4.properties file.
log4j.logger.jdbc.audit=ON
Then restart the server and you will see logs like below.
[2016-12-31 23:44:55,631] INFO - CarbonAuthenticationUtil 'admin@carbon.super [-1234]' logged in at [2016-12-31 23:44:55,631+0530] [2016-12-31 23:44:55,828] DEBUG - audit 2. Statement.new Statement returned org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:454) [2016-12-31 23:44:55,829] DEBUG - audit 2. Connection.createStatement() returned net.sf.log4jdbc.StatementSpy@44c41ca9 org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:454) [2016-12-31 23:44:55,829] DEBUG - audit 2. Statement.execute(SELECT 1) returned true org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:461) [2016-12-31 23:44:55,830] DEBUG - audit 2. Statement.close() returned org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:462) [2016-12-31 23:44:55,830] DEBUG - audit 2. PreparedStatement.new PreparedStatement returned sun.reflect.GeneratedMethodAccessor31.invoke(null:-1) [2016-12-31 23:44:55,830] DEBUG - audit 2. Connection.prepareStatement(SELECT API.API_ID FROM AM_API API WHERE API.API_PROVIDER = ? AND API.API_NAME = ? AND API.API_VERSION = ?) returned net.sf.log4jdbc.PreparedStatementSpy@396ee038 sun.reflect.GeneratedMethodAccessor31.invoke(null:-1) [2016-12-31 23:44:55,831] DEBUG - audit 2. PreparedStatement.setString(1, "admin") returned org.wso2.carbon.apimgt.impl.dao.ApiMgtDAO.getAPIID(ApiMgtDAO.java:6217) [2016-12-31 23:44:55,831] DEBUG - audit 2. PreparedStatement.setString(2, "PizzaShackAPI") returned org.wso2.carbon.apimgt.impl.dao.ApiMgtDAO.getAPIID(ApiMgtDAO.java:6218) [2016-12-31 23:44:55,831] DEBUG - audit 2. PreparedStatement.setString(3, "1.0.0") returned org.wso2.carbon.apimgt.impl.dao.ApiMgtDAO.getAPIID(ApiMgtDAO.java:6219) [2016-12-31 23:44:55,831] DEBUG - audit 2. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@1e4299fd org.wso2.carbon.apimgt.impl.dao.ApiMgtDAO.getAPIID(ApiMgtDAO.java:6220) [2016-12-31 23:44:55,831] DEBUG - audit 2. PreparedStatement.close() returned org.apache.tomcat.jdbc.pool.interceptor.StatementFinalizer.closeInvoked(StatementFinalizer.java:57) [2016-12-31 23:44:55,832] DEBUG - audit 2. Connection.getAutoCommit() returned false org.wso2.carbon.ndatasource.rdbms.ConnectionRollbackOnReturnInterceptor.invoke(ConnectionRollbackOnReturnInterceptor.java:44) [2016-12-31 23:44:55,832] DEBUG - audit 2. Connection.rollback() returned org.wso2.carbon.ndatasource.rdbms.ConnectionRollbackOnReturnInterceptor.invoke(ConnectionRollbackOnReturnInterceptor.java:45) [2016-12-31 23:44:55,832] DEBUG - audit 2. PreparedStatement.close() returned org.wso2.carbon.apimgt.impl.utils.APIMgtDBUtil.closeStatement(APIMgtDBUtil.java:175) [2016-12-31 23:44:55,833] DEBUG - audit 2. Connection.setAutoCommit(false) returned sun.reflect.GeneratedMethodAccessor32.invoke(null:-1) [2016-12-31 23:44:55,834] DEBUG - audit 2. PreparedStatement.new PreparedStatement returned sun.reflect.GeneratedMethodAccessor31.invoke(null:-1) [2016-12-31 23:44:55,834] DEBUG - audit 2. Connection.prepareStatement( SELECT CAST( SUM(RATING) AS DECIMAL)/COUNT(RATING) AS RATING FROM AM_API_RATINGS WHERE API_ID =? GROUP BY API_ID ) returned net.sf.log4jdbc.PreparedStatementSpy@70a2e307 sun.reflect.GeneratedMethodAccessor31.invoke(null:-1) [2016-12-31 23:44:55,834] DEBUG - audit 2. PreparedStatement.setInt(1, 2) returned org.wso2.carbon.apimgt.impl.dao.ApiMgtDAO.getAverageRating(ApiMgtDAO.java:3969)
If we use this log, it logs the result set of each JDBC call.
If you want to enable that logs of your server, add below line to log4.properties file.
Then restart the server and you will see logs like below.
log4j.logger.jdbc.resultset=INFO
Then restart the server and you will see logs like below.
[2016-12-31 23:47:41,386] INFO - PermissionUpdater Permission cache updated for tenant -1234 [2016-12-31 23:47:41,478] INFO - CarbonAuthenticationUtil 'admin@carbon.super [-1234]' logged in at [2016-12-31 23:47:41,478+0530] [2016-12-31 23:47:41,683] INFO - resultset 2. ResultSet.new ResultSet returned [2016-12-31 23:47:41,684] INFO - resultset 2. ResultSet.next() returned true [2016-12-31 23:47:41,684] INFO - resultset 2. ResultSet.getInt(API_ID) returned 2 [2016-12-31 23:47:41,685] INFO - resultset 2. ResultSet.close() returned [2016-12-31 23:47:41,686] INFO - resultset 2. ResultSet.new ResultSet returned [2016-12-31 23:47:41,686] INFO - resultset 2. ResultSet.next() returned false [2016-12-31 23:47:41,686] INFO - resultset 2. ResultSet.close() returned [2016-12-31 23:47:41,688] INFO - resultset 2. ResultSet.new ResultSet returned [2016-12-31 23:47:41,688] INFO - resultset 2. ResultSet.next() returned true [2016-12-31 23:47:41,688] INFO - resultset 2. ResultSet.getString(API_TIER) returned null [2016-12-31 23:47:41,688] INFO - resultset 2. ResultSet.next() returned false [2016-12-31 23:47:41,688] INFO - resultset 2. ResultSet.close() returned [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.new ResultSet returned [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.next() returned true [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.getString(NAME) returned Gold [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.getString(QUOTA_TYPE) returned requestCount [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.getString(QUOTA_TYPE) returned requestCount [2016-12-31 23:47:41,689] INFO - resultset 2. ResultSet.getInt(UNIT_TIME) returned 1 [2016-12-31 23:47:41,690] INFO - resultset 2. ResultSet.getString(TIME_UNIT) returned min [2016-12-31 23:47:41,690] INFO - resultset 2. ResultSet.getInt(QUOTA) returned 5000 [2016-12-31 23:47:41,690] INFO - resultset 2. ResultSet.getString(UUID) returned e4eee273-4eb0-4d8c-9f6d-f503b58c7dd0
v. jdbc.connection
If we use this log, it logs connection details like opening and closing the database connections.
If you want to enable that logs of your server, add below line to log4.properties file.
Then restart the server and you will see logs like below.
log4j.logger.jdbc.connection=INFO
Then restart the server and you will see logs like below.
[2016-12-31 23:55:47,521] INFO - connection 2. Connection closed [2016-12-31 23:55:47,523] INFO - connection 4. Connection closed [2016-12-31 23:55:54,447] INFO - EmbeddedRegistryService Configured Registry in 0ms [2016-12-31 23:55:54,708] INFO - connection 5. Connection opened
No comments:
Post a Comment