Hibernate / JPA SQL and JDBC logging with log4jdbc

1. Motivation
It's very common the need of a better log for our parameterized queries. Instead of seeing

INSERT INTO stock_transaction (CHANGE, CLOSE, DATE, OPEN, STOCK_ID, VOLUME)
VALUES (?, ?, ?, ?, ?, ?)

we´d like to see

INSERT INTO stock_transaction (CHANGE, CLOSE, DATE, OPEN, STOCK_ID, VOLUME)
VALUES (10.1, 1.1, '30 December 2009', 1.2, 11, 1000000)

You can get a not so practical result if you set log appenders for Hibernate (you can see here how to configure it this way). The problem is that you can't just copy and paste the SQL statement right into your SQL worksheet. It takes a lot of work and time to do it.

Hibernate: INSERT INTO stock_transaction (CHANGE, CLOSE, DATE, OPEN, STOCK_ID, VOLUME) VALUES (?, ?, ?, ?, ?, ?)
13:33:07,253 DEBUG FloatType:133 - binding '10.0' to parameter: 1
13:33:07,253 DEBUG FloatType:133 - binding '1.1' to parameter: 2
13:33:07,253 DEBUG DateType:133 - binding '30 December 2009' to parameter: 3
13:33:07,269 DEBUG FloatType:133 - binding '1.2' to parameter: 4
13:33:07,269 DEBUG IntegerType:133 - binding '11' to parameter: 5
13:33:07,269 DEBUG LongType:133 - binding '1000000' to parameter: 6

I´m going to show in this post a working example of how to log SQL queries with parameters, and some other informations, in an application that uses Spring, Hibernate, JPA and logback.

2. History of log4jdbc
It all started with the original library log4jdbc (https://code.google.com/p/log4jdbc/). Then it was improved with the log4jdbc-remix (https://code.google.com/p/log4jdbc-remix/) and finally we have the log4jdbc-log4j2 (https://code.google.com/p/log4jdbc-log4j2/) that is the version of the library that we'll use in the example.

3. The sample application
The objective here is to have an working application that serves as an example of how to configure and use log4jdbc library in the code. With that in mind I chose an application that is build during a great PluralSight course: Spring with JPA and Hibernate.You can find this version in my GitHub repository.

    Fitness Tracker log example

4. Required software
In order to have this application working in your machine, here are some requirements:

• JDK 7
• Apache Tomcat 7
• MySQL server running on default port 3306  / username: root / password: password
• Maven 3

5. The good parts
I´ll show now what takes to have JDBC parameters logged, among other things. If you have git installed, you can use the command below to see the changes I made to the original application:

    git diff v1.0.0.0 v2.0.0.0

5.1 Two new dependencies were added to the project. One is logback and the other is the log4jdbc2

	...
	<dependency>
	<groupId>org.bgee.log4jdbc-log4j2</groupId>
	<artifactId>log4jdbc-log4j2-jdbc4</artifactId>
	<version>1.16</version>
	</dependency>
	<dependency>
	<groupId>ch.qos.logback</groupId>
	<artifactId>logback-classic</artifactId>
	<version>1.1.3</version>
	</dependency>
	...

view raw pom.xml hosted with ❤ by GitHub

5.2 As the application uses Slf4j library, we need to configure the option log4jdbc.spylogdelegator.name to the value net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator. This is done by creating the file log4jdbc.log4j2.properties in the src/main/resources folder:

log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator

view raw log4jdbc.log4j2.properties hosted with ❤ by GitHub

5.3 Now we can see the change in the data source reference in jpaContext.xml point to the log4jdbc data source wrapper.

	...
	<bean id="dataSourceSpied"
	class="org.springframework.jdbc.datasource.DriverManagerDataSource">
	<property name="driverClassName" value="com.mysql.jdbc.Driver" />
	<property name="url" value="jdbc:mysql://localhost:3306/fitnessTracker?autoReconnect=true" />
	<property name="username" value="root" />
	<property name="password" value="password" />
	</bean>
	<bean id="dataSource" class="net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy">
	<constructor-arg ref="dataSourceSpied" />
	</bean>
	...

view raw jpaContext.xml hosted with ❤ by GitHub

5.4 And last, the logback with its appenders was configured.

	<configuration>
	<property name="SERVER_LOG_PATH" value="${server.logging.path:-/var/log/fitnesstracker}"/>
	...
	<appender name="SQLONLY_SERVER_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
	<file>${SERVER_LOG_PATH}/sqlonly.log</file>
	<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
	<fileNamePattern>${SERVER_LOG_PATH}/sqlonly-%d{yyyy-MM-dd}.log</fileNamePattern>
	<maxHistory>7</maxHistory>
	</rollingPolicy>
	<encoder>
	<Pattern>%d{HH:mm:ss.SSS} %-5level SQLONLY [%X{xtid}] [%logger{36}] [%thread] %msg%n%ex</Pattern>
	</encoder>
	</appender>
	...
	<logger name="jdbc.sqlonly" level="INFO" additivity="false">
	<appender-ref ref="SQLONLY_SERVER_FILE"/>
	</logger>
	...
	<root level="info">
	<appender-ref ref="STDOUT" />
	</root>
	</configuration>

view raw logback.xml hosted with ❤ by GitHub

The property SERVER_LOG_PATH may be redefined passing a new path in the server.logging.path VM property
    -Dserver.logging.path=/new/path/to/log

It was defined an appender to jdbc.sqlonly logger with additivity=false, which makes the messages be logged only in this appender. With one file per logger is easier to decide what log configuration to choose.

6. Installing and running the sample application

6.1 Start your MySQL server instance
6.2 Get the application from GitHub. From a shell where you want to have this application:

    git clone https://github.com/mroger/fitness-tracker-sql-log-example.git

6.3 Build the application

    mvn clean install

6.4 Copy the war file (FitnessTracker.war) from project's target folder  to the Tomcat's webapps folder
6.5 Start Tomcat if not already started
6.6 Access the application in the URL http://localhost:8080/FitnessTracker/index.jsp
6.6 Use the application, save some data and see how the queries are logged in the folder /var/log/fitnesstracker

8. Conclusion
Being able to copy and paste the exact query that was executed directly in a SQL tool can save a lot of time in finding performance bottlenecks or the source of errors. And log4jdbc library makes it easy to accomplish this.
Adding maven profiles to this, you can orchestrate your builds so each environment gets the correct configuration automatically.