Welcome

Experiences with Audit Logging through Hibernate Interceptor

In  our current project, we make use of Hibernate Interceptor in order to perform auditing to track operations performed with our domain objects. We at first simply followed instructions in Hibernate In Action book. Basically,  steps are as follows;

  • Declare an Auditable interface, and methods in it for what kind of information you want to audit about your domain objects. Our domain objects should implement  that interface if they want to be auditable.
  • Define an AuditLog class that will represent audit log information about our create/update/delete operations.
  • Implement an AuditLogInterceptor and capture insert, update, and delete events, those performed with our auditable domain objects, using onSave, onFlushDirty, and onDelete callback methods respectively.
  • Finally create and insert AuditLog objects for each inserted, updated, and deleted domain object.
  • Be careful not using original hibernate session object in your Interceptor, as it is illegal to use it in Interceptor?s callback methods, so we need to employ new session to insert those AuditLog objects into our database.

So far so good; we created an audit logging mechanism based on above instructions and it seemed to be working properly until we noticed that audit logs exists for operations that involved in a rollbacked transaction. Original modified domain object is not in database as it is rollbacked, but its audit log exists in the log table! The reason for that is, if you look at below code sample for AuditLogInterceptor,  manipulated auditable domain objects are kept in three sets. On postFlush method call, which occurs during transaction commit, we create and insert audit log records according to the contents  of those sets, and finally we clear contents of those sets, for a new turn. Unfortunately, postFlush is never called if a rollback occurs, hence sets’ contents are not cleared. We got  rid of this situation with extending HibernateTransactionManager and overriding its doRollback method, and clearing those contents through calling reset method explicitly.

public class AuditLogInterceptor implements Interceptor {

            ...

            private HashSet inserts  = new HashSet();
            private HashSet updates = new HashSet();
            private HashSet deletes = new HashSet();

            public boolean onFlushDirty(Object entity,...) throws CallbackException {
                        if(entity instanceof Auditable) {
                                   updates.add(entity);
                        }
                        return false;

            }

            public boolean onSave(Object entity,...) throws CallbackException {
                        if(entity instanceof Auditable) {
                                   inserts.add(entity);
                        }
                        return false;
            }

            public boolean onDelete(Object entity,...) throws CallbackException {
                        if(entity instanceof Auditable) {
                                   deletes.add(entity);
                        }
                        return false;
            }

            public void postFlush(Iterator entities) {
                        try {
                            //perform inserting audit logs for entities those were enlisted in inserts, //updates, and deletes sets...
                        } catch(Exception e) {
                        } finally {
                                   //clear those inserts, deletes, and updates sets contents...
                                   reset();
                        }
            }

            public void reset() {
                        inserts.clear();
                        updates.clear();
                        deletes.clear();

            }
            ...
}

For the above implementation,there exists another problem. We use Spring and Hibernate together, and let Spring manage transactions. In order to make AuditLogInterceptor work, we have to set it, either at SessionFactory level or at Session level, and it is prefferable to set it on LocalSessionFactoryBean, or HibernateTransactionManager to avoid repeated configuration and provide consistent behavior in transactions. But if we set the Interceptor on those objects, it must be a singleton according to Spring documentation, and if it will be a singleton, our insert, update, delete sets will be accessible through multiple threads, consequently in multiple transactions. We might easily end with a condition, in which there happens two different transactions populating audit information in those sets, finally one commits and the other rollbacks. If rollback happens first, we will loose all of our audit log information which belong to the committing one. We can solve this problem with introducing ThreadLocal. We simply create a ThreadLocal object that will keep those set instances separately for each different thread.

public class AuditLogInterceptor implements Interceptor {
            ...
            class AuditSetWrapper {
                        public HashSet inserts  = new HashSet();
                        public HashSet updates = new HashSet();
                        public HashSet deletes = new HashSet();
            }

           

            private ThreadLocal auditSetHolder = new ThreadLocal();
            ...
            private AuditSetWrapper getAuditSetWrapper() {
                        Object o = auditSetHolder.get();
                        if(o == null) {
                                   o = new AuditSetWrapper();
                                   auditSetHolder.set(o);
                        }
                        return (AuditSetWrapper)o;
            }
            ...
}

Then we access our insert, update, delete sets through that AuditSetWrapper object, and as it is distinct for each different thread context, we successfully isolate our different concurrently running transactions? audit log information.

One another problem with auditing through Interceptor is logging differences on updates. onFlushDirty callback provides both current and previous states of our domain objects, so that we can easily get them and create our audit log record accordingly. Unfortunately, onFlushDirty method provides this useful information if our object loads and updates are performed in one single hibernate session. If we use detached objects, we will not be able to get previous state, it will simply be null.

Several solutions exist for this problem;

  • One is to employ Application Sessions (Long Sessions) instead of Session per Request pattern, so our original session will be preserved over multiple requests.
  • Another one is to use select-before-update property which is introduced in Hibernate 2.1 (simply useless for getting previous states, please look at following paragraph for an explanation.)
  • Finally, we can implement custom EntityPersister and keep track of domain objects? states.

We currently applied second choice, as it requires no additional coding overhead, and it requires no architectural change comparing to first choice, however, it introduces a performance overhead, as hibernate will first look at database before each update.

Update:

I want to excuse from people, who have been misguided with the above information. Select-before-update brings no solution for getting previous states of detached objects in onFlushDirty callback. As far as I know, there is no easy solution for this in Hibernate 2.x, unless we use application sessions, or implement our custom EntityPersister. Thankfully, in Hibernate 3.x, merge operation helps us to load previous state of entity and merge contents of current entity with them. During update, onFlushDirty and findDirty callbacks return correct previous state information because first, merge loads entity into session. If we first merge our entities before updating them in our DAO or service methods, we can get previous state information in Hibernate Interceptor.