& Continuous Learning

Through the years I've encountered a recurring requirement. Partners 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