Sunday, March 1, 2015

Logging JDBC activities using Log4JDBC

In general terms, logging is an activity of recording what's happening in run-time of the application. Sometimes, we need logging for JDBC activities. Log4jdbc is the best way to log the jdbc activities by a Java Application.

Logging Options

The options available in log4jdbc are
  • jdbc.sqlonly: Logs all the SQLs executed by Java Code.
  • jdbc.sqltiming: Logs time taken by each SQL to execute.
  • jdbc.audit: Logs all the activities of the JDBC (Except Result sets). 
  • jdbc.resultset: Includes the audit and plus Result set activities.
  • jdbc.connection: Connection details like opening and closing the database connections will be logged.
In addition to above, if we use log4j-jdbc-remix, it adds few more
  • jdbc.resultsettable: Prints the result set in format of a table with column names. 
  • We can configure this as a datasource.
Any of these can be added to log appenders as required.

Maven Dependencies

The following are the maven dependencies to be added to configure log4jdbc (I am using Apache log4j, you can use any others implementation - java.util, logback, jakarta logging etc as required ). 
  <!-- SLF4J API -->
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>1.6.4</version>
  </dependency>
 
  <!-- LOG4J -->
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-log4j12</artifactId>
   <version>1.6.4</version>
  </dependency>

  <!-- LOG4J for JDBC -->
  <dependency>
   <groupId>org.lazyluke</groupId>
   <artifactId>log4jdbc-remix</artifactId>
   <version>0.2.7</version>
  </dependency>

Log4J Configuration

Configure Log4j first and add the log4jdbc loggers to it. Sample log4j.properties file as below.
I am trying to print
  • SQLs
  • SQL Timing
  • Result Set tables
So the log4j.properties file looks like

# Root logger option
log4j.rootLogger=INFO, stdout
 
# Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

log4j.logger.jdbc.sqlonly=INFO
log4j.logger.jdbc.sqltiming=INFO
log4j.logger.jdbc.audit=OFF
log4j.logger.jdbc.resultset=ERROR
log4j.logger.jdbc.connection=ERROR
log4j.logger.jdbc.resultsettable=ON

Change Driver and JDBC URL

  • Change the driver from <your implementation driver> to net.sf.log4jdbc.DriverSpy 
  • Prefix the JDBC Connection URL with jdbc:log4jdbc instead of jdbc:
Example: I am using MySQL. So, I changed
  • JDBC Driver from com.mysql.jdbc.Driver to net.sf.log4jdbc.DriverSpy 
  • MySQL JDBC Connection string changed from jdbc:mysql://localhost:3306/test to jdbc:log4jdbc:mysql://localhost:3306/test
By default, log4jdbc loads all the drivers. If we want to load only the specified drivers, use the following system properties otherwise all the drivers will be loaded, and the system will pick the required driver based on the implementation.
  • -Dlog4jdbc.drivers=<driverclass>[,<driverclass>...] : To load the specific drivers
  • -Dlog4jdbc.auto.load.popular.drivers=false: To switch off loading all other drivers except mentioned by above

Log4JDBC Log

Sample Log printed with above configuration while accessing the data to/from database as below.

2015-03-01 18:07:04 INFO  Main:19 - Started
2015-03-01 18:07:05 INFO  sqlonly:236 - INSERT INTO Student VALUES(5,'Veeresham',25,'M') 
2015-03-01 18:07:05 INFO  sqltiming:357 - INSERT INTO Student VALUES(5,'Veeresham',25,'M')  {executed in 180 msec}
2015-03-01 18:07:05 INFO  sqlonly:236 - select * from Student 
2015-03-01 18:07:05 INFO  sqltiming:357 - select * from Student  {executed in 1 msec}
2015-03-01 18:07:05 INFO  resultsettable:108 - |---|----------|----|-------|
2015-03-01 18:07:05 INFO  resultsettable:108 - |id |name      |age |gender |
2015-03-01 18:07:05 INFO  resultsettable:108 - |---|----------|----|-------|
2015-03-01 18:07:05 INFO  resultsettable:108 - |1  |John      |20  |M      |
2015-03-01 18:07:05 INFO  resultsettable:108 - |2  |Lary      |28  |F      |
2015-03-01 18:07:05 INFO  resultsettable:108 - |3  |Blob      |22  |M      |
2015-03-01 18:07:05 INFO  resultsettable:108 - |5  |Veeresham |25  |M      |
2015-03-01 18:07:05 INFO  resultsettable:108 - |---|----------|----|-------|
2015-03-01 18:07:05 INFO  Main:28 - Completed

When we set SQLs to true, log will replace the placeholders with the actual arguments set to it.

Try to set and unset the parameters and see different levels of information.


Happy Learning!!!!