Welcome to Hibernate Log4j Logging example. Hibernate 4 uses JBoss logging rather than slf4j in older hibernate versions. Today we will look into how to configure log4j in a hibernate application.
Hibernate Log4j Logging
Create a maven project in the Eclipse or your favorite IDE, final project structure will look like below image.
Let’s look into each of the components one by one.
Hibernate Log4j Maven Dependencies
We need hibernate-core, mysql driver and log4j dependencies in our project, our final pom.xml file looks like below.
<project xmlns="https://maven.apache.org/POM/4.0.0" xmlns:xsi="https://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="https://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>com.journaldev.hibernate</groupId>
<artifactId>HibernateLog4JExample</artifactId>
<version>0.0.1-SNAPSHOT</version>
<dependencies>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-core</artifactId>
<version>4.3.5.Final</version>
</dependency>
<dependency>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
<version>1.2.16</version>
</dependency>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>5.0.5</version>
</dependency>
</dependencies>
</project>
Log4j Configuration File
I am using XML based log4j configuration, we can also use property file based configuration.
log4j.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="https://jakarta.apache.org/log4j/"
debug="false">
<!-- A time/date based rolling appender -->
<appender name="FILE" class="org.apache.log4j.RollingFileAppender">
<param name="File" value="logs/system.log" />
<param name="Append" value="true" />
<param name="ImmediateFlush" value="true" />
<param name="MaxFileSize" value="200MB" />
<param name="MaxBackupIndex" value="100" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %d{Z} [%t] %-5p (%F:%L) - %m%n" />
</layout>
</appender>
<appender name="journaldev-hibernate" class="org.apache.log4j.RollingFileAppender">
<param name="File" value="logs/project.log" />
<param name="Append" value="true" />
<param name="ImmediateFlush" value="true" />
<param name="MaxFileSize" value="200MB" />
<param name="MaxBackupIndex" value="50" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %d{Z} [%t] %-5p (%F:%L) - %m%n" />
</layout>
</appender>
<logger name="com.journaldev.hibernate" additivity="false">
<level value="DEBUG" />
<appender-ref ref="journaldev-hibernate" />
</logger>
<logger name="org.hibernate" additivity="false">
<level value="INFO" />
<appender-ref ref="FILE" />
</logger>
<root>
<priority value="INFO"></priority>
<appender-ref ref="FILE" />
</root>
</log4j:configuration>
This file needs to be placed at the root folder, so that our main class can access it. Notice the location of log4j log files, our application generated logs will go into project.log whereas hibernate logs will go into system.log file.
Hibernate Configuration File
Our hibernate configuration xml looks like below.
hibernate.cfg.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration SYSTEM "classpath://org/hibernate/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
<session-factory>
<property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="hibernate.connection.password">pankaj123</property>
<property name="hibernate.connection.url">jdbc:mysql://localhost/TestDB</property>
<property name="hibernate.connection.username">pankaj</property>
<property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="hibernate.current_session_context_class">thread</property>
<property name="hibernate.show_sql">true</property>
<mapping class="com.journaldev.hibernate.model.Employee" />
<mapping class="com.journaldev.hibernate.model.Address" />
</session-factory>
</hibernate-configuration>
Hibernate SessionFactory utility class
package com.journaldev.hibernate.util;
import org.apache.log4j.Logger;
import org.hibernate.SessionFactory;
import org.hibernate.boot.registry.StandardServiceRegistryBuilder;
import org.hibernate.cfg.Configuration;
import org.hibernate.service.ServiceRegistry;
public class HibernateUtil {
private static SessionFactory sessionFactory;
private static Logger logger = Logger.getLogger(HibernateUtil.class);
private static SessionFactory buildSessionFactory() {
try {
// Create the SessionFactory from hibernate.cfg.xml
Configuration configuration = new Configuration();
configuration.configure("hibernate.cfg.xml");
logger.info("Hibernate Configuration loaded");
ServiceRegistry serviceRegistry = new StandardServiceRegistryBuilder().applySettings(configuration.getProperties()).build();
logger.info("Hibernate serviceRegistry created");
SessionFactory sessionFactory = configuration.buildSessionFactory(serviceRegistry);
return sessionFactory;
}
catch (Throwable ex) {
logger.error("Initial SessionFactory creation failed." + ex);
ex.printStackTrace();
throw new ExceptionInInitializerError(ex);
}
}
public static SessionFactory getSessionFactory() {
if(sessionFactory == null) sessionFactory = buildSessionFactory();
return sessionFactory;
}
}
Notice that I am using log4j Logger for logging purpose, since this class is part of our application, the logs should go into project.log file.
Model Classes
We have two model classes – Employee and Address. I am using the same database setup as in HQL Example, so you can check that tutorial to look into database setup and model classes. Both of these classes are simple java beans with hibernate annotation based mapping.
Hibernate Log4j Logging Test Class
Our main class looks like below.
package com.journaldev.hibernate.main;
import java.util.List;
import org.apache.log4j.Logger;
import org.apache.log4j.xml.DOMConfigurator;
import org.hibernate.Query;
import org.hibernate.Session;
import org.hibernate.SessionFactory;
import org.hibernate.Transaction;
import com.journaldev.hibernate.model.Employee;
import com.journaldev.hibernate.util.HibernateUtil;
public class HibernateLog4jExample {
static{
System.out.println("Before log4j configuration");
DOMConfigurator.configure("log4j.xml");
System.out.println("After log4j configuration");
}
private static Logger logger = Logger.getLogger(HibernateLog4jExample.class);
@SuppressWarnings("unchecked")
public static void main(String[] args) {
//Prep work
SessionFactory sessionFactory = HibernateUtil.getSessionFactory();
Session session = sessionFactory.getCurrentSession();
//Get All Employees
Transaction tx = session.beginTransaction();
Query query = session.createQuery("from Employee");
List<Employee> empList = query.list();
for(Employee emp : empList){
logger.info("List of Employees::"+emp.getId()+","+emp.getAddress().getCity());
}
tx.commit();
sessionFactory.close();
logger.info("DONE");
}
}
Notice that we don’t need to do anything to plugin log4j logging. Obviously we would need to configure it first before using it, that’s why I am using static block to make sure log4j is configured before we start using it. I am using org.apache.log4j.xml.DOMConfigurator because our log4j configuration is XML based, if you have property file based configuration, you should use org.apache.log4j.PropertyConfigurator class.
Now when we execute above program, we get following data in log4j files.
project.log
2014-06-05 20:00:11,868 -0700 [main] INFO (HibernateUtil.java:20) - Hibernate Configuration loaded
2014-06-05 20:00:11,936 -0700 [main] INFO (HibernateUtil.java:23) - Hibernate serviceRegistry created
2014-06-05 20:00:12,698 -0700 [main] INFO (HibernateLog4jExample.java:37) - List of Employees::1,San Jose
2014-06-05 20:00:12,698 -0700 [main] INFO (HibernateLog4jExample.java:37) - List of Employees::2,Santa Clara
2014-06-05 20:00:12,698 -0700 [main] INFO (HibernateLog4jExample.java:37) - List of Employees::3,Bangalore
2014-06-05 20:00:12,698 -0700 [main] INFO (HibernateLog4jExample.java:37) - List of Employees::4,New Delhi
2014-06-05 20:00:12,712 -0700 [main] INFO (HibernateLog4jExample.java:42) - DONE
Notice that above log file contains only entries generated by our program, this way we can separate our application logs from hibernate logs.
system.log
2014-06-05 22:49:58,415 -0700 [main] INFO (JavaReflectionManager.java:66) - HCANN000001: Hibernate Commons Annotations {4.0.4.Final}
2014-06-05 22:49:58,423 -0700 [main] INFO (Version.java:54) - HHH000412: Hibernate Core {4.3.5.Final}
2014-06-05 22:49:58,426 -0700 [main] INFO (Environment.java:239) - HHH000206: hibernate.properties not found
2014-06-05 22:49:58,427 -0700 [main] INFO (Environment.java:346) - HHH000021: Bytecode provider name : javassist
2014-06-05 22:49:58,446 -0700 [main] INFO (Configuration.java:2073) - HHH000043: Configuring from resource: hibernate.cfg.xml
2014-06-05 22:49:58,447 -0700 [main] INFO (Configuration.java:2092) - HHH000040: Configuration resource: hibernate.cfg.xml
2014-06-05 22:49:58,491 -0700 [main] INFO (Configuration.java:2214) - HHH000041: Configured SessionFactory: null
2014-06-05 22:49:58,557 -0700 [main] WARN (DriverManagerConnectionProviderImpl.java:93) - HHH000402: Using Hibernate built-in connection pool (not for production use!)
2014-06-05 22:49:58,560 -0700 [main] INFO (DriverManagerConnectionProviderImpl.java:166) - HHH000401: using driver [com.mysql.jdbc.Driver] at URL [jdbc:mysql://localhost/TestDB]
2014-06-05 22:49:58,561 -0700 [main] INFO (DriverManagerConnectionProviderImpl.java:175) - HHH000046: Connection properties: {user=pankaj, password=****}
2014-06-05 22:49:58,561 -0700 [main] INFO (DriverManagerConnectionProviderImpl.java:180) - HHH000006: Autocommit mode: false
2014-06-05 22:49:58,562 -0700 [main] INFO (DriverManagerConnectionProviderImpl.java:102) - HHH000115: Hibernate connection pool size: 20 (min=1)
2014-06-05 22:49:58,699 -0700 [main] INFO (Dialect.java:145) - HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
2014-06-05 22:49:58,706 -0700 [main] INFO (LobCreatorBuilder.java:97) - HHH000423: Disabling contextual LOB creation as JDBC driver reported JDBC version [3] less than 4
2014-06-05 22:49:58,828 -0700 [main] INFO (TransactionFactoryInitiator.java:62) - HHH000399: Using default transaction strategy (direct JDBC transactions)
2014-06-05 22:49:58,832 -0700 [main] INFO (ASTQueryTranslatorFactory.java:47) - HHH000397: Using ASTQueryTranslatorFactory
2014-06-05 22:49:59,207 -0700 [main] INFO (DriverManagerConnectionProviderImpl.java:281) - HHH000030: Cleaning up connection pool [jdbc:mysql://localhost/TestDB]
Since our hibernate logs level is set to INFO mode, there are not many logs. If you will change it to debug, even this simple program generates more than 1400 lines of log. Analyzing these logs are sometime crucible in understanding how hibernate works internally and to debug issues related to hibernate.
Also, we got following logs generated in console.
Before log4j configuration
After log4j configuration
Hibernate: select employee0_.emp_id as emp_id1_1_, employee0_.emp_name as emp_name2_1_, employee0_.emp_salary as emp_sala3_1_ from EMPLOYEE employee0_
Hibernate: select address0_.emp_id as emp_id1_0_0_, address0_.address_line1 as address_2_0_0_, address0_.city as city3_0_0_, address0_.zipcode as zipcode4_0_0_, employee1_.emp_id as emp_id1_1_1_, employee1_.emp_name as emp_name2_1_1_, employee1_.emp_salary as emp_sala3_1_1_ from ADDRESS address0_ left outer join EMPLOYEE employee1_ on address0_.emp_id=employee1_.emp_id where address0_.emp_id=?
Hibernate: select address0_.emp_id as emp_id1_0_0_, address0_.address_line1 as address_2_0_0_, address0_.city as city3_0_0_, address0_.zipcode as zipcode4_0_0_, employee1_.emp_id as emp_id1_1_1_, employee1_.emp_name as emp_name2_1_1_, employee1_.emp_salary as emp_sala3_1_1_ from ADDRESS address0_ left outer join EMPLOYEE employee1_ on address0_.emp_id=employee1_.emp_id where address0_.emp_id=?
Hibernate: select address0_.emp_id as emp_id1_0_0_, address0_.address_line1 as address_2_0_0_, address0_.city as city3_0_0_, address0_.zipcode as zipcode4_0_0_, employee1_.emp_id as emp_id1_1_1_, employee1_.emp_name as emp_name2_1_1_, employee1_.emp_salary as emp_sala3_1_1_ from ADDRESS address0_ left outer join EMPLOYEE employee1_ on address0_.emp_id=employee1_.emp_id where address0_.emp_id=?
Hibernate: select address0_.emp_id as emp_id1_0_0_, address0_.address_line1 as address_2_0_0_, address0_.city as city3_0_0_, address0_.zipcode as zipcode4_0_0_, employee1_.emp_id as emp_id1_1_1_, employee1_.emp_name as emp_name2_1_1_, employee1_.emp_salary as emp_sala3_1_1_ from ADDRESS address0_ left outer join EMPLOYEE employee1_ on address0_.emp_id=employee1_.emp_id where address0_.emp_id=?
Notice that Hibernate is printing SQL queries to the console log, this is happening from org.hibernate.engine.jdbc.spi.SqlStatementLogger class logStatement method, code snippet is:
if (this.logToStdout)
System.out.println("Hibernate: " + statement);
This is controlled by hibernate.show_sql property in hibernate.cfg.xml file. Actually if you are using log4j, then you should turn it off because they will also be part of log files if logging level is set to DEBUG mode. Having it in log files make more sense that getting it printed on console.
That’s all for hibernate log4j logging example, as you can see it’s very easy to plugin and all we need is to configure log4j properly. You can download the project from below link.