Aug 31
Auditing with NHibernate Listeners
icon1 Darrell Mozingo | icon2 NHibernate | icon4 August 31st, 2009| icon332 Comments »

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.

Aug 19
When’s the best time to write tests?
icon1 Darrell Mozingo | icon2 Testing | icon4 August 19th, 2009| icon31 Comment »

I often hear people get apathetic about testing, especially on brown field applications. “There’s already so much untested code,” they say, or “we’ll get to it when we start this next portion of the application, we swear.” Obviously this gets put off to the start of the next feature, and the next, and the next, ad infinitum. All the while, there’s more untested code piling up, helping their first argument, and the code base on a whole is becoming more rigid and jumbled up, almost guaranteeing they’ll never have the time to untangle it and add tests after the fact.

Fear not, though, I have the perfect answer! It’s actually a simple, definitive, mathematical proof. For a given application A, that has x lines of code and has been in development for n months with a client base of C clients, we derive the best time to start writing tests, wt as thus:

Right time to test equation

What’d I say? Simple.

Ok, ok, a little sarcastic. Seriously though, there’s never a better time then right now, this very moment. Even a huge UI & database interacting integration test using something like WaitN. It’s better than nothing. Like I said, the longer you wait, the more untested code you accumulate, the harder/scary it is to change things, and the more code you’ll need to eventually test. Even if it’s only a portion of your app that you’ve put off testing (for us, it’d be the UI and controllers/services) – just do it. They might not look pretty at first, but you can refine that later. They’ll expose pain points that need refactoring in the classes you’re testing, and the tests themselves might even require some object builders, helper methods, or base test classes, but it’s all worth it.

Don’t wait for tomorrow, the next iteration, or the next big version. Do it right now!