Hibernate Logging

Through the years I’ve encountered a recurring requirement. Clients need to log changes to the database for auditing and legal purposes. To satisfy this requirement you could add logging to every save/update/delete call in your code. Or better yet, you could create an aspect that wraps these calls. While these would certainly work Hibernate provides a convenient interceptor.

In this article I will show you how to add a simple logger to Hibernate.

Start with a Test

As an avid TDD practitioner I will of coarse start with a test. Here is the final version of the test that I used to drive my code.

package com.sourceallies.logging;
 
import static org.junit.Assert.assertEquals;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
 
import java.util.Date;
import java.util.List;
 
import javax.annotation.Resource;
 
import org.apache.commons.logging.Log;
import org.hibernate.Criteria;
import org.hibernate.SessionFactory;
import org.hibernate.classic.Session;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
import org.springframework.transaction.annotation.Transactional;
 
import com.sourceallies.Person;
 
@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration
public class HibernateInterceptorTest {
 
	@Resource
	private SessionFactory sessionFactory;
 
	@Resource
	private HibernateInterceptor hibernateInterceptor;
 
	private Session currentSession;
 
	private Log logger;
 
	private static final Date NOW = new Date();
 
	@Before
	public void setUp(){
		logger = mock(Log.class);
		currentSession = sessionFactory.getCurrentSession();
		hibernateInterceptor.setLogger(logger);
	}
 
	@Test
	@Transactional
	public void testSaveLogging(){
		saveOrUpdate(createPerson());
 
		assertEquals(1, findAll().size());
 
		verify(logger).info("Saving Person [firstName=testFirst, lastName=testLast, birthDate=" + NOW + "].");
		verifyNoMoreInteractions(logger);
	}
 
	@Test
	@Transactional
	public void testUpdateLogging(){
		saveOrUpdate(createPerson());
 
		List<Person> people = findAll();
 
		assertEquals(1, people.size());
 
		Person firstPerson = people.get(0);
		firstPerson.setFirstName("testFirst2");
 
		saveOrUpdate(firstPerson);
 
		currentSession.flush();
 
		verify(logger).info("Saving Person [firstName=testFirst, lastName=testLast, birthDate=" + NOW + "].");	
		verify(logger).info("Updating Person [firstName=testFirst2, lastName=testLast, birthDate=" + NOW + "].");	
		verifyNoMoreInteractions(logger);
	}
 
	@Test
	@Transactional
	public void testDeleteLogging(){
		saveOrUpdate(createPerson());
 
		List<Person> people = findAll();
 
		assertEquals(1, people.size());
 
		Person firstPerson = people.get(0);
 
		delete(firstPerson);
 
		currentSession.flush();
 
		verify(logger).info("Saving Person [firstName=testFirst, lastName=testLast, birthDate=" + NOW + "].");	
		verify(logger).info("Deleting Person [firstName=testFirst, lastName=testLast, birthDate=" + NOW + "].");	
		verifyNoMoreInteractions(logger);
	}
 
	@Transactional
	public void saveOrUpdate(Person person) {
		currentSession.saveOrUpdate(person);
		currentSession.flush();
	}
 
	@Transactional
	public void delete(Person person) {
		currentSession.delete(person);
	}
 
	@SuppressWarnings("unchecked")
	private List<Person> findAll() {
		Criteria criteria = currentSession.createCriteria(Person.class);
		List<Person> people = criteria.list();
		return people;
	}
 
 
	private Person createPerson() {
		Person person = new Person("testFirst", "testLast", NOW);
		return person;
	}
}

I used a mock logger to gather information from the interceptor.

Spring Configuration

Here is the configuration required for the interceptor.

 
	<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
                ...
		<property name="dataSource" ref="dataSource" />
		<property name="entityInterceptor" ref="hibernateInterceptor"/>
	</bean>
 
	<bean id="transactionManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
		<property name="sessionFactory" ref="sessionFactory" />
	</bean>
         ...	
	<context:component-scan base-package="com.sourceallies" />
        ...

The ‘entityInterceptor’ property on the ‘sessionFactory’ takes a Hibernate interceptor.

Entity

@Entity
public class Person {
 
	@Id
	@GeneratedValue(strategy=GenerationType.AUTO)
	private Long id = -1L;
 
	@Column
	private String firstName;
 
	@Column
	private String lastName;
 
	@Column
	private Date birthDate;
...
	@Override
	public String toString() {
		return "Person [firstName=" + firstName + ", lastName="
				+ lastName + ", birthDate=" + birthDate + "]";
	}
}

For this example you need to implement the ‘toString’ method on the entity being logged.

Interceptor

Here is the interceptor code.

package com.sourceallies.logging;
 
import java.io.Serializable;
 
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.hibernate.EmptyInterceptor;
import org.hibernate.type.Type;
import org.springframework.stereotype.Component;
 
@Component
public class HibernateInterceptor extends EmptyInterceptor {
 
	private static final long serialVersionUID = 1L;
	private Log logger = LogFactory.getLog(HibernateInterceptor.class);
 
	@Override
	public void onDelete(Object entity, Serializable id, Object[] state,
			String[] propertyNames, Type[] types) {
		log("Deleting", id, entity);
		super.onDelete(entity, id, state, propertyNames, types);
	}
 
	@Override
	public boolean onFlushDirty(Object entity, Serializable id,
			Object[] currentState, Object[] previousState,
			String[] propertyNames, Type[] types) {
		log("Updating", id, entity);
		return super.onFlushDirty(entity, id, currentState, previousState,
				propertyNames, types);
	}
 
	@Override
	public boolean onSave(Object entity, Serializable id, Object[] state,
			String[] propertyNames, Type[] types) {
		log("Saving", id, entity);
		return super.onSave(entity, id, state, propertyNames, types);
	}
 
	protected void setLogger(Log logger) {
		this.logger = logger;
	}
 
	private void log(String action, Serializable id, Object entity) {
		logger.info(action + " " + entity + ".");
	}
}

While the ‘onSave’ and ‘onDelete’ methods are clearly named the ‘onUpdate’ method appears to be missing. With a little research it quickly becomes obvious that ‘onFlushDirty’ is used for updates.

Logging database activity is this simple.

Here is the complete code. Hibernate Logging Zip

5 comments

  1. What’s Going down i’m new to this, I stumbled upon this I have found It absolutely useful and it has helped me out loads. I’m hoping to give a contribution & assist other customers like its aided me. Good job.

  2. Good day I am so glad I found your website, I really found you by mistake, while I was searching on Google for something else, Anyhow I am here now and would just like to say cheers for a incredible post and a all round entertaining blog (I also love the theme/design), I don’t have time to read through it all at the minute but I have bookmarked it and also included your RSS feeds, so when I have time I will be back to read a lot more, Please do keep up the fantastic job.

Comments are closed.