Logging using Interceptors

One of the most popular uses of Interceptors is to log object creations/insertions and deletions. Interceptors allow you to transparently log these state changes and manage the audit trail for an entity.
I decided to implement a simple interceptor that audits all creations of the Entity class to the database. The Entity class is as below:

public class Entity {
    private String name;
    private Integer id;
//setter-getters
}

The audit class below writes a simple string to the database at the time of creation.

public class Audit {
    private Integer id;
    private String log;
       //setter-getters
}

The interceptor to capture the action is as below:

public class AuditInterceptor extends EmptyInterceptor {

    private static final Logger logger = Logger
            .getLogger(AuditInterceptor.class);

    private Set<Entity> savedEntities = new HashSet<Entity>();
    private  Session session;
    
    public void setSession(Session session) {
        this.session = session;
    }

    @Override
    public boolean onSave(Object object, Serializable id, Object[] state,
            String[] propertyNames, Type[] types) {
        if (object instanceof Entity) {
            Entity entity = (Entity) object;
            logger.info("Saving new Entity with data " + entity.getName());
            savedEntities.add(entity);
        }        
        return super.onSave(object, id, state, propertyNames, types);
    }
    
    @Override
    public void postFlush(@SuppressWarnings("rawtypes") Iterator entities) {        
        super.postFlush(entities);
        for (Entity entity : savedEntities) {
            logger.info("Logging about saved entity  " + entity.getName());
            Audit audit = new Audit();
            audit.setLog("Saved entity with data " + entity.getName() 

                + " for id " + entity.getId() + " at time " + new Date());
            session.save(audit);
        }

        savedEntities.clear();
    }

}

Whenever the save call is made in a session, the new (Entity class only) object found in the session are added to a set. The object is not logged here as the identifier of the entity may not be known yet. Hibernate guarantees that the flush method will set the identifiers. Hence we intercept the post flush workflow. At this point all the entities in our set have the identifiers set. We simply iterate the set and create the log trail for the same. I executed the below test code :

public static void testCreate() {
    final AuditInterceptor customInterceptor = new AuditInterceptor();
    Session session = sessionFactory.openSession(customInterceptor);
    customInterceptor.setSession(session);
    Transaction transaction = session.beginTransaction();
    Entity entity = new Entity();
    entity.setName("121");
    session.save(entity);
    transaction.commit();
    session.close();
}

The logs indicate the audit trail formation

3297 [main] INFO  com.interceptor.audit.AuditInterceptor  - Saving new Entity wi
th data 121
    insert 
    into
        INTERCEPT_ENTITY
        (NAME, MASTER_ID) 
    values
        (?, ?)
3734 [main] INFO  com.interceptor.audit.AuditInterceptor  - Logging about saved 
entity  121
3750 [main] DEBUG org.hibernate.event.def.DefaultSaveOrUpdateEventListener  - sa
ving transient instance
3750 [main] DEBUG org.hibernate.SQL  - 
    insert 
    into
        AUDIT_ENTITY
        (LOG) 
    values
        (?)
3765 [main] DEBUG org.hibernate.impl.SessionImpl  - after transaction completion
3765 [main] DEBUG org.hibernate.impl.SessionImpl  - closing session

The database shows the two new records

 As can be seen the log was saved with details of the entity and the time-stamp for the operation.
Although the above code worked fine, there is a big bug in it. Taken verbatim from the book Java Persistence With Hibernate

It is illegal to invoke the Hibernate session from an interceptor callback.The session is in a fragile state during interceptor calls.

Thus we cannot use this session in our code. The workaround would be to create a temporary session and use that to save our audit records. The modifications to the interceptor is as below:

private SessionFactory sessionFactory; 
    
public void setSessionFactory(SessionFactory sessionFactory) {
    this.sessionFactory = sessionFactory;
}
    
@Override
public void postFlush(@SuppressWarnings("rawtypes") Iterator entities) {        
    super.postFlush(entities);
    Session tempSession = sessionFactory.openSession(session.connection());
    for (Entity entity : savedEntities) {
        logger.info("Logging about saved entity  " + entity.getName());
        Audit audit = new Audit();
        audit.setLog("Saved entity with data " + entity.getName() 

             + " for id " + entity.getId() + " at time " + new Date());
        tempSession.save(audit);
    }
    savedEntities.clear();
    tempSession.flush();
    tempSession.close();
}

As the temporary session also executes in the same transactional context, all rules of commit apply here too i.e. in case of any rollback, the audit records will also be roll backed.