NHibernate Forge
The official new home for the NHibernate community

Creating an Audit Log using NHibernate Events

Page Details

First published by:
bunceg
on 02-28-2009
Last revision by:
bunceg
on 02-28-2009
4 people found this article useful.
Article
Comments (6)
History (7)
100% of people found this useful

Creating an Audit Log using NHibernate Events

Filed under: , , [Edit Tags]

Scenario

You want to create an audit table so that changes to business entities are tracked with a timestamp. You want this do be done automatically by NHibernate.

Options

There are a number of ways of doing this, using IInterceptor or the NHibernate 2.0 Event model. As the event model is fairly new, there isn't a lot of information or examples about how to use it therefore most examples deal with IInterceptor.The Audit logging itself can be recorded via multiple tables per class, single table to cover all classes, track all changes, track latest change etc.

Solution

This solution uses the Event model, a single table for all classes and track latest change only. It also depends on the database key being a GUID, not an integer. When a class is deleted, the audit information is also removed. This might not be appropriate for your scenario.

Background

The solution operates within a repository pattern (nielson, Domain Driven Design) design where there is a single repository wrapping the NHibernate Session. This repository exposes an Interface that is defined in the business layer that the NHibernate Repository implements. Therefore the repository depends on the domain, not the domain depends on the repository. An IoC product (Spring.NET, Unity etc.) is used to wire these together.

The Domain has no reference to anything to do with NHibernate but, to ease development; each business entity inherits from the abstract Entity class and implements the IEntity interface. It is the Entity class that tracks the audit information for the business class that inherits from it.

Entity Id's are GUID's as opposed to integers. The entity Id maps to the database primary key.

Classes

The abstract Entity class is as follows

[Serializable]
public abstract class Entity : IEntity
{
private const string UnknownUser = "Unknown";

private Guid _id;
private byte[] _version;
private DateTime _createdTimestamp;
private string _createdBy;
private DateTime _updatedTimestamp;
private string _updatedBy;

[Snip: Property declarations removed for brevity]

public Entity()
{
_id = Guid.Empty;
_version = new byte[8];
_createdBy = string.IsNullOrEmpty(Thread.CurrentPrincipal.Identity.Name) ? UnknownUser : Thread.CurrentPrincipal.Identity.Name;
_createdTimestamp = DateTime.Now;
_entityName = this.GetType().FullName;
}
}

Each business class extends this however is appropriate.

Mappings

An example mapping file for a class that extends the entity class might be:

<?xml version="1.0" encoding="utf-8"?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" namespace="Sample.Domain" assembly="Sample.Domain" default-access="field.camelcase-underscore" default-lazy="true">
<class name="Task" proxy="Sample.Domain.Interfaces.ITask, Sample.Domain.Interfaces" table="Task">
<id name="Id" column="Id" unsaved-value="00000000-0000-0000-0000-000000000000" access="property">
<generator class="guid.comb" />
</id>
<version name="Version" column="Version" type="binary" unsaved-value="null" generated="always"/>

<property name="Lookup" type="string" length="50" not-null="true" />
<property name="Description" type="string" length="255" not-null="true" />

<join table="Audit">
<key column="EntityId" />
<property name="EntityName" />
<property name="CreatedBy" />
<property name="CreatedTimestamp" />
<property name="UpdatedBy" />
<property name="UpdatedTimestamp"/>
</join>
</class>
</hibernate-mapping>

Implementation

From the mapping we can see that the Task class uses an Interface (ITask) for its proxy generation (though virtual methods are just as acceptable) but more importantly that the Task class is populated from a join between the Audit table and the Task table. The join column is the Entity ID which, like the Id in the task table is a GUID. As GUID's are almost guaranteed to be unique there is very little likelihood of the being a key collision between the Task table and (e.g.) a Group table each storing their ID in the same column. Unfortunatley this is not the case for a HiLo key generation mechanism.

Therefore this Join element is telling NHibernate to do a SQL join on the Id of the primary table (Task) with the Entity ID of the Audit table. In effect, its the same as multi table inheritence but without the inheritence.

The power of this is that Nhibernate automatically keeps the two tables in line... an add to Task results in two SQL inserts (Task and Audit), a delete of Task results in two deletes etc. If you wish to retain audit information, but not the business data, in the case of a delete then this solution is not for you, though you could consider the "pre-delete" event to deal with retaining the audit information somehow.

Wiring into the NHibernate Event model

The NHibernate 2.0 Event model can be implemented a number of ways, inherit from a base class or implement an interface. This solution uses an interface as it allows a single listener class to deal with both updates and inserts.

The best events to use for Auditing in this scenario are "pre-update" and "pre-insert". First we write a listener class that implements two interfaces IPreUpdateEventListener and IPreInsertEventListener. This class needs to ensure that the "state" of the object to be written is updated prior to NHibernate writing out the class information. Unfortunately this state information is held in a string array and cannot be accessed in a TypeSafe manner.

internal class AuditEventListener : IPreUpdateEventListener, IPreInsertEventListener
{
public bool OnPreUpdate(PreUpdateEvent e)
{
UpdateAuditTrail(e.State, e.Persister.PropertyNames, (IEntity)e.Entity);
return false;
}
public bool OnPreInsert(PreInsertEvent e)
{
UpdateAuditTrail(e.State, e.Persister.PropertyNames, (IEntity)e.Entity);
return false;
}
private void UpdateAuditTrail(object[] state, string[] names, IEntity entity)
{
var idx = Array.FindIndex(names, n => n == "UpdatedBy");
state[idx] = string.IsNullOrEmpty(Thread.CurrentPrincipal.Identity.Name) ? "Unknown" : Thread.CurrentPrincipal.Identity.Name;
entity.UpdatedBy = state[idx].ToString();
idx = Array.FindIndex(names, n => n == "UpdatedTimestamp");
DateTime now = DateTime.Now;
state[idx] = now;
entity.UpdatedTimestamp = now;
}
}

Don't ask me why we return false in the implemented methods.... I'm not sure yet, but it works :)

So now when an object is written (the presumption is that all objects written implement the business IEntity interface) Nhibernate will run the listener, find the audit properties in the current NHibernate State and update them.To ensure the object itself also has the latest values, we update the entity instance as well.

Hooking NHibernate into the Listener

This is the easy bit - add the following to the hibernate.cfg.xml file (within the SessionFactory element) and you're done!

<event type="pre-update">
<listener class="Sample.Repository.NHibernate.AuditEventListener, Sample.Repository.NHibernate" />
</event>
<event type="pre-insert">
<listener class="Sample.Repository.NHibernate.AuditEventListener, Sample.Repository.NHibernate" />
</event>

 

Recent Comments

By: isuruceanu Posted on 02-11-2010 8:14

   I did the same things but I get and stackoverflow exception. It enters recursively in the PerformSaveOrUpdate overrided method. After I’m setting createdBy it call PerformSaveOrUpdate one more time, and logically enters into recursion.

   The only difference from yours code is that CreatedBy and ModifiedBy are User object and Mapped to Users table as Reference.

   Have you such problem? Could you change a bit you code and test with references to User instead of having string, please?

By: bunceg Posted on 10-28-2009 10:23

Sorry all, just noticed these comments.

MacX.

Hmm.. nope, there is nothing I'm aware of in NHibernate to do this for you out of the box. NH is a ORM not an audit log tool (see Sean's last comment re: Responsibility for an idea of of what I mean).

MattF:

Sorry, I don't use ActiveRecord so I can't comment about that. I know NH doesn't fire two events though so AR is a potential culprit. Sorry I couldn't help.

Sean:

I sort of agree with you about responsibility. What I would say though is that its semantics as to whether this is a persistance layer or a domain layer responsibility.

For me, its domain layer in that its a business rule that every change should be logged. I have worked on plenty of apps where auditing is not a requirement and plenty of apps (e.g. financial) where is most definitely is. Does this mean it is business logic? I can be persuaded either way, but I think its a stronger case for business logic than, say, logging.

That's why I slapped it into the domain layer but, unfortunately we are stuck needing to with a way of intercepting each entity at the point of save. The only way I know of doing that when using NH is via interceptors/events. Its not clean at all, but it does work.

If you feel that auditing is not domain logic at all, then that's fine as well. Just remove all the public properties from the entity but, as far as I can remember, you will need something (private variables) that NH can hook into via its mapping file to save back to the DB.

tbh, I originally posted this as, at the time, I had no idea how to use interceptors and events in NH especially since events are not widely documented.

By: MacX Posted on 07-06-2009 4:53

Hi there,

first of all, thanks for this how-to. Regarding to this how-to, i have a question if it's possible without implementing the logic by myself to track the changes made within the entity to create a detailed audit-log?

Regards, Maik

By: MattF Posted on 06-05-2009 23:21

i am auditing changes using an IPostUpdateEventListener.

in my audit i am logging each colulmn & table which changed (including the old value and new value)

e.g.

Table              column    oldvalue    newvalue      timestamp

----------------------------------------------------------------------------------

table_name     Version        1               2             12:00pm

however my model is a joined-subclass, so that when it is updated, two tables change (which is fine).

my problem is that OnPostUpdate fires twice for each time i call update (i'm using ActiveRecord, so i don't know what the equivalent method is for NH)

is this a bug? because i can't see any difference between the parameters passed to the OnPostUpdate for each of the different calls.

so at the moment it is logging twice for each update.

so i am getting:

p.s. i have a feeling it may have been firing twice even when i had a simple model with one table (but i would have to double check)

Table    column    oldvalue    newvalue       timestamp

--------------------------------------------------------------------------

base     Version        1               2            12:00pm

sub           X             3               4          12:00pm

base     Version        1               2            12:00pm

sub           X             3               4          12:00pm

p.s. this could be a bug in ActiveRecord and not NH

By: Sean Posted on 04-24-2009 0:11

I don't mean to be too negative in my above comment: I found your article useful.

It's just that NHibernate + Interceptors doesn't quite do all I think it should do.

View All
Powered by Community Server (Commercial Edition), by Telligent Systems