We recently had a requirement to do auditing in our application, complete with storing the old and new values. Previous applications had used a method that took all that information in an wrote it to the database, giving us a lot of control of what we logged and when, but it required us to call it in every needed situation or we’d lose the capability, not to mention it made reading the code horrid.
Thankfully, we’re using NHibernate for this application. I’d read here and there over the past year about how simple auditing was with NHibernate and I’d bookmarked them, knowing this requirement was working its way down the pipeline. Unfortunately, pretty much every example I could find out there was simple using simple created time stamp, modified time stamp, and user making the update fields. For our application we needed to track the old and new values in addition to these fields, along with a few other requirements that are pretty specific to our application (so I’ll leave them out here).
We’ll store these audit entries in a separate table with a primary key reference back to the entity they modified. Let’s start by defining a domain object to represent a single audit entry:
public class AuditLogEntry { public virtual int Id { get; set; } public virtual string Username { get; set; } public virtual string AuditEntryType { get; set; } public virtual string EntityFullName { get; set; } public virtual string EntityShortName { get; set; } public virtual int EntityId { get; set; } public virtual string FieldName { get; set; } public virtual string OldValue { get; set; } public virtual string NewValue { get; set; } public virtual DateTime Timestamp { get; set; } } |
Pretty self explanatory – it’ll store details related to the update, including what field was updated, the object full/short name, id of the entity, the old/new values, username that made the update, and a time stamp.
We’ll also need a simple entity to use as our test subject:
public class Employee { public virtual int Id { get; set; } public virtual string Name { get; set; } public virtual int Age { get; set; } } |
Again, nothing fancy (though note this will scale up – we’re using fairly complex objects in our domain, and while the auditing code I’ll post here isn’t the exact same, it’s not too far off, and we haven’t had a problem yet). I’ll stick with Fluent NHibernate’s auto mapping to produce the basic mappings we’ll need. There’s nothing special required there.
Now for the actual auditing code. We’ll use the newer Listener (Pre/Post Update/Insert/Delete/etc) interfaces, which replaced the generic IInterceptor. Basically, each seperate entity that’s saved will get passed into our class, allowing us to do whatever we need with it. We’ll be collecting auditing data:
public class AuditUpdateListener : IPostUpdateEventListener { private const string _noValueString = "*No Value*"; private static string getStringValueFromStateArray(object[] stateArray, int position) { var value = stateArray[position]; return value == null || value.ToString() == string.Empty ? _noValueString : value.ToString(); } public void OnPostUpdate(PostUpdateEvent @event) { if (@event.Entity is AuditLogEntry) { return; } var entityFullName = @event.Entity.GetType().FullName; if (@event.OldState == null) { throw new ArgumentNullException("No old state available for entity type '" + entityFullName + "'. Make sure you're loading it into Session before modifying and saving it."); } var dirtyFieldIndexes = @event.Persister.FindDirty(@event.State, @event.OldState, @event.Entity, @event.Session); var session = @event.Session.GetSession(EntityMode.Poco); foreach (var dirtyFieldIndex in dirtyFieldIndexes) { var oldValue = getStringValueFromStateArray(@event.OldState, dirtyFieldIndex); var newValue = getStringValueFromStateArray(@event.State, dirtyFieldIndex); if (oldValue == newValue) { continue; } session.Save(new AuditLogEntry { EntityShortName = @event.Entity.GetType().Name, FieldName = @event.Persister.PropertyNames[dirtyFieldIndex], EntityFullName = entityFullName, OldValue = oldValue, NewValue = newValue, Username = Environment.UserName, EntityId = (int)@event.Id, AuditEntryType = "Update", Timestamp = DateTime.Now }); } session.Flush(); } } |
First we inherit from IPostUpdateEventListener, which has a single OnPostUpdate method defined. We check to make sure we’re not auditing another audit entity (infinite loop, anyone?), then make sure we have the old values available, throwing if we don’t. For this system to work/be effective, you must load the entity into session, modify it, then save. In a few places, we had everything we already needed from the form (we’re working in a web environment), so we’d just set all the properties, including the entity’s id. The problem there is NHibernate’s session has no idea what the old values are, so we’ve now made it a policy to always load the entity before saving it.
On line 29, we’re delegating to NHibernate to tell us which properties in the entity are dirty, or have changed. We then loop through those properties, collect the needed values for our AuditLogEntry entity, and save it off.
As I’ve mentioned, this works just fine for most applications. The first issue we ran into was Components (in the NHibernate sense). They’re represented as a single property changed on the entity, so all you get is the ToString on the object. Fortunately there’s an easy way to see if the property is a Component (hint: @event.Persister.PropertyTypes[dirtyFieldIndex] is ComponentType before line 43), so we use reflection to loop through the properties by hand and compare them for dirtiness.
There you go, damn near complete old & new value auditing, just like mom would have always wanted. Not perfect, I’m sure, but we’ve been using a modified version of this for a while and haven’t had any problems.
In the working example, available here, I run through an edit and display the audit results in a console app using Sqlite. Give it a try, and let me know if you find this helpful at all.
September 3rd, 2009 at 9:57 am
Cool stuff! Thanks for posting this, gonna file it away on delicious in case I need to implement auditing some time.
September 8th, 2009 at 3:14 pm
Interesting. Is it possible to cancel the default processing using an event listener?
For example, suppose I’m loading a list of entities, but I want to remove some of them from the list, for example, because the current user is not authorized to access them. Is this possible?
September 9th, 2009 at 4:44 pm
@Ricardo: You mean when loading an entity, you want to cancel out of it due to security issues? Besides that not being the correct place to do it, it doesn’t look like it’s possible.
Neither the PreLoadEvent or PostLoadEvent have anything for canceling, and their respective interfaces don’t return anything from the load methods.
If you mean not auditing something due to security, if you can define a general rule that applies to all objects, you can check it in the above listener and just not create the AuditLogEntry object. We have a SkipAudittingAttribute defined for those fringe edge cases for this reason.
September 22nd, 2009 at 11:40 am
Darrell – do you have any experience using this with ASP.NET MVC? I am wanting to audit changes made by a user within the web browser, but MVC supplies me on postback with an instance of my entity completely unlinked to NHibernate. As a result, there is no OldState in the OnPostUpdate event when I call SaveOrUpdate.
How can I have NH play spot-the-difference for me?
Thanks
September 24th, 2009 at 5:53 pm
@Neil: Actually, we use it in an ASP.NET MVC app. As I mentioned above, we’ve had to make the concession of loading the needed entity first, then modifying and saving it. It most places we were already doing this for various reasons (mostly not having all the data being posted back), but a few places were we just newing up the object and setting all the properties along with the existing Id. NHibernate’s SaveOrUpdate() would take care of updating it for us. We’ve had to stop doing that for this auditing to work, but we felt it was worth it for our situation.
October 13th, 2009 at 4:34 pm
Thanks alot, nice article, exactly what I was looking for!
October 21st, 2009 at 6:03 pm
Darrell, I was playing a slightly modified version of your sample code, and I’m getting the an error described here.
http://groups.google.com/group/nhusers/browse_thread/thread/d2424b6bd02df52e
Did you run into any similar issues?
Thanks
October 23rd, 2009 at 10:18 am
@Juan,
Sorry, I’ve never had to deal with NHibernate’s queue’s like that, and I can’t think of anything from reading that post. Good luck with it, though.
January 19th, 2010 at 11:59 am
Thanks a lot. Have implemented this in my own S#arp MVC app. Works great and was exactly the type of solution my client required.
February 16th, 2010 at 7:50 pm
Thanks much for sharing! Your code saves me a lot of time.
I have been implementing the similar auditing with PreUpdate Event by following Ayende’s example, http://ayende.com/Blog/archive/2009/04/29/nhibernate-ipreupdateeventlistener-amp-ipreinserteventlistener.aspx.
However, I keep getting an error, “collection was not processed by flush()” once in a while.
I follow your example and update my auditing part. I haven’t seen the above problem so far.
May 25th, 2010 at 12:44 pm
Hi Darrell,
Your solution for auditing looks great. However the example (zip) link is broken. Could you please provide me with a working example.
Thanks
Nabeel
May 25th, 2010 at 1:41 pm
The example link is fixed. Sorry ’bout that!
May 26th, 2010 at 4:04 am
Thanks Darrell…great stuff
June 29th, 2010 at 10:27 am
Really usefull. Thank you for this piece of code.
October 16th, 2010 at 12:31 pm
Hi Darrel,
Going through your example, you used Environment.UserName to get the user name.
In a web application, how do you get the user currently logged in if using auth by FORM?
October 16th, 2010 at 6:16 pm
@William: We have an HttpContext abstraction that gets injected in for easier testing of the listener, but accessing it directly (HttpContext.Current…) should work just as well.
December 3rd, 2010 at 6:01 am
Thanks, this was really useful. Am just starting out with NHibernate and one of the benefits that I’ve used to sell it are the benefits like this that it gives us. I’ve turned it into a “PreUpdate” event so I can create the auditevent and add it to a list in the object being updated.
March 21st, 2011 at 1:32 pm
Hi Darrel,
i have @event.OldState always null… SaveOrUpdateCopy is not way.
No more idea, Thanks
March 21st, 2011 at 1:53 pm
@Jonny: Make sure you’re loading the entity before saving it again. Even if you have the entity’s id and values, you can’t just set them and save it. You’ll have to load, then modify, they save, otherwise the OldState will be null. Hope that helps.
June 29th, 2011 at 5:24 pm
Hi, very nice.
I got a problem , if i got an Enum in the model, it tries to save in the state[i] the value instead of the key. And the transaction fails because in the db, that field is a bit (they key in the enum) but as i said it puts the value… I know that the listener is the problem because if i dont register in the nhibernate cfg this listener it does it in the right way.
Thanks, keep in good work.
October 5th, 2011 at 9:37 pm
This is great — I’ve been trying to do just this!
In fact, I found IPostUpdateEventListener, and tried using it (before finding this blog), but gave up on it because @event.OldState was always null. I’m loading it through NHibernate and everything.
I’ve downloaded and tried your example, and it indeed works fine — @event.OldState apparently has the old state.
I’m now in the process of trying to figure out what’s different between your sample program and my real program. Any ideas?
Thanks!
October 5th, 2011 at 10:38 pm
I found it: if you Load your entity in one NHibernate session, and then Update it in a second NHibernate session, that works fine, but OldState will be null in the Pre/PostUpdateEventListeners.
October 6th, 2011 at 12:44 am
@Ken: Yea, the session sets the OldState when the entity is loaded, so if you save it through another session it doesn’t know what the state is. Glad this helped you out a bit!
October 28th, 2011 at 1:24 pm
OK, here’s another issue I ran into.
If I use @event.Session.GetSession(EntityMode.Poco), then whenever somebody uses a transaction (session.BeginTransaction(), etc.), it dies in NHibernate.Impl.AbstractSessionImpl.ErrorIfClosed().
As a quick hack, I’ve changed my code to simply open a new NHibernate ISession, which seems to work in light testing, but I’m not sure that’ll always be good.
Is there a better way to do this?
October 30th, 2011 at 12:16 am
@Ken: What version of NHibernate are you using? We haven’t had this problem with our transactions.
October 31st, 2011 at 4:12 pm
3.0.0.something, looks like.
November 17th, 2011 at 1:26 pm
Hy Darrell
Good Article. I want log in the OnPostInsert an OnpostDelete events too, but if the properties are of type Entity, only the proxy to it are available in the state. How i can access this entities an checks theirs properties? Is this posible?
Thanks in advance.
November 17th, 2011 at 1:50 pm
@Danyel: That’s from those entities being lazy loaded. I’m not positive, but I’m guessing they can’t be loaded that late/early in the game. You’ll have to eagerly fetch them to have the properties available.
February 27th, 2012 at 6:01 pm
Hi Darrell,
great blog post. I am currently trying to add an audit log module to our software application, which also uses NHibernate and C#. For your implementation, did you have to use a SessionManager? Cheers.
July 11th, 2012 at 5:56 pm
I wanted to let you know that this really helped me a lot with writing a good auditor. I changed it a little to log all the fields of the table regardless if the value changed or not on update. I also added listeners for insert and delete to log the state of the record as well.
I have found with what is being logged now, I have the ability fully look at a record from creation, through changes and the moment of deletion.
With a little programming I can effective make it possible to roll through data through time and restore deleted records along with roll back changes to a record back to specific time.
The level of flexibility this offers it is limitless as to what I can do with the sate of the data.
Thanks for the wonderful post. If you lived in my area, I would take you out for several beers.
October 23rd, 2012 at 7:10 pm
Hi!
Hope you can still get that message:
So in case for a delete of a entity that will cascade delete other entities… if I config all entities with audit using listeners then would all the entities deleted by cascade be logged auidted as well?
I will test to see anyway but if you have an answer would be nice.
cheers!
October 24th, 2012 at 5:28 am
@Flavio: I’m fairly certain all the cascades will get called with the auditor as well, as they’re each individual deletes. Its been a while since I’ve worked with this though, so please let me know what you find!