Sample NHibernate IInterceptor implementation

Introduction

Audit logging is an important issue while building enterprise systems. The simplest form of audit logging is recording who created/updated an object or a record in the database respectively and when it was done. We perform four basic operations on a domain object. These are:

• Load
• Update
• Save
• Delete

Data access layer is a good place to perform automated audit logging whenever one of the operations above is executed. NHibernate provides us with the IInterceptor interface plus ILifecylce interface. You can read this article for more information about NHibernate entity lifecycle management.

In this article we will try to perform simple logging that meets the following minimal requirements:

1. We will log who performed insert/update and when this operation was performed
2. Log data will be written to the same database and table as our domain object

Class Model

We have three interfaces directly related to audit logging and IInterceptor implementation, one interface (IVersionedEntity ) which is in the model just for conceptual completeness and is used to indicate that we want to utilize NHibernate managed versioning, one base DomainObject from which all our domain objects inherit and finally three implementation classes that implement IInsertLoggable, IModifyLoggable and IUpdateLoggable interfaces.

public abstract class InsertLoggableDomainObject : 
            DomainObject,IVersionedEntity, IInsertLoggable
{
  #region IVersionedEntity Members

  private long _version = 0;
  public long Version
  {
    get { return _version; }
  }

  #endregion

  #region IInsertLogable Members

  private DateTime? _sysCreatedOn = null;
  public DateTime? SysCreatedOn
  {
    get { return _sysCreatedOn; }
    set { _sysCreatedOn = value; }
  }

  private int? _sysCreatedBy = null;
  public int? SysCreatedBy
  {
    get { return _sysCreatedBy; }
    set { _sysCreatedBy = value; }
  }
  #endregion
}

public abstract class UpdateLoggableDomainObject : 
            DomainObject, IVersionedEntity, IUpdateLoggable
{
  #region IVersionedEntity Members

  private long _version = 0;
  public long Version
  {
    get { return _version; }
  }

  #endregion

  #region IUpdateLogable Members

  private DateTime? _sysLastUpdatedOn = null;
  public DateTime? SysLastUpdatedOn
  {
    get { return _sysLastUpdatedOn; }
    set { _sysLastUpdatedOn = value; }
  }

  private int? _sysLastUpdatedBy = null;
  public int? SysLastUpdatedBy
  {
    get { return _sysLastUpdatedBy; }
    set { _sysLastUpdatedBy = value; }
  }
  #endregion
}

public abstract class ModifyLoggableDomainObject : 
            DomainObject, IVersionedEntity, IModifyLogable
{
  #region IVersionedEntity Members

  private long _version = 0;
  public long Version
  {
    get { return _version; }
  }

  #endregion

  #region IModifyLogable Members

  private DateTime? _sysCreatedOn = null;
  public DateTime? SysCreatedOn
  {
    get { return _sysCreatedOn; }
    set { _sysCreatedOn = value; }
  }

  private int? _sysCreatedBy = null;
  public int? SysCreatedBy
  {
    get { return _sysCreatedBy; }
    set { _sysCreatedBy = value; }
  }

  private DateTime? _sysLastUpdatedOn = null;
  public DateTime? SysLastUpdatedOn
  {
    get { return _sysLastUpdatedOn; }
    set { _sysLastUpdatedOn = value; }
  }

  private int? _sysLastUpdatedBy = null;
  public int? SysLastUpdatedBy
  {
    get { return _sysLastUpdatedBy; }
    set { _sysLastUpdatedBy = value; }
  }
  #endregion
}

If we want our domain objects to be audit logged by our NHibernate IInterceptor instead of solely inheriting from DomainObject, we may inherit our domain objects from one of the loggable domain object implementations (InsertLoggableDomainObject, UpdateLoggableDomainObject, ModifyLoggableDomainObject).

NHibernate Setup

Inheriting our domain objects from one of the base loggable classes does not provide us
full logging support.

NHibernate Mappings

As any other NHibernate utilization needs some mapping work this sample also needs some NHibernate mapping.
All our loggable domain objects must include the following mapping information:

<?xml version='1.0' encoding='utf-8'?>
<hibernate-mapping
    xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'
    xmlns:xsd='http://www.w3.org/2001/XMLSchema' 
                xmlns='urn:nhibernate-mapping-2.0'>
  <class
      name='Fully Qualified Class name comes here'
      table='Table name'>
    <id name='Identity field name'
        column='Identity column to which identity field maps'
        unsaved-value='0'>
      <generator class='identity'/>
    </id>
    <!--Managed versioning support. Defined in IVersionedEntity interface -->
    <version name='_version' column='Version' access='field' 
                    unsaved-value='0' type='Int64'/>

    <!--Log field mappings -->
    <property name='SysCreatedOn' column='SysCreatedOn' 
            type='NHibernate.Nullables2.NullableDateTimeType, 
            NHibernate.Nullables2'/>
    <property name='SysCreatedBy' column='SysCreatedBy' 
            type='NHibernate.Nullables2.NullableInt32Type, 
            NHibernate.Nullables2'/>
    <property name='SysLastUpdatedOn' column='SysLastUpdatedOn' 
            type='NHibernate.Nullables2.NullableDateTimeType, 
            NHibernate.Nullables2'/>
    <property name='SysLastUpdatedBy' column='SysLastUpdatedBy' 
            type='NHibernate.Nullables2.NullableInt32Type, 
            NHibernate.Nullables2'/>
    <!-- Some other field, relation, subclass and other kind of mappings 
                        from this point on-->
  </class>
</hibernate-mapping>

We use NHibernate.Nullables2 (found in NHibernate Contributions) for type definitions of our log data fields.
We can omit this reference and usage of nullables by simply changing interface field definitions and their implementations from int? to int and DateTime? to DateTime. But be warned that SysCreatedBy and SysLastUpdatedBy columns are defined as foreign keys to another table in the database, say Person. Thus making these fields non-nullable may cause constraint violations on the database side.

NHibernate Session Initialization

This step is simple. Either you directly manage NHibernate sessions from your own code
or you use simple but yet very powerful NHSessionManager singleton. You have to use ISession ISessionFactory.OpenSession(IInterceptor interceptor)
overload from NHibernate assembly to open a session. IInterceptor interceptor< parameter here is an instance of our IInterceptor implementation.

IInterceptor Implementation

You can think of an interceptor as a hook utility to the data access layer. IInterceptor implementation will look like this:

public class MyAuditLogger:IInterceptor
{
  #region IInterceptor Members

  public int[] FindDirty(object entity, object id, 
            object[] currentState, object[] previousState, 
            string[] propertyNames, 
            global::NHibernate.Type.IType[] types)
  {
      return null;
  }

  public object Instantiate(Type type, object id)
  {
      return null;                
  }

  public object IsUnsaved(object entity)
  {
      return null;
  }

  public void OnDelete(object entity, object id, object[] state, 
    string[] propertyNames, global::NHibernate.Type.IType[] types)
  {
  }

  public bool OnFlushDirty(object entity, object id, object[] currentState, 
        object[] previousState, string[] propertyNames, 
        global::NHibernate.Type.IType[] types)
  {
      if (entity is IUpdateLogable)
      {
          SetUpdateLoggableValues(currentState, propertyNames);
          return true;
      }
      else if (entity is IModifyLogable)
      {
          SetModifyLoggableValues_OnUpdate(currentState, propertyNames);
          return true;
      }
      else
      {
          return true;
      }
  }

  public bool OnLoad(object entity, object id, object[] state, 
    string[] propertyNames, global::NHibernate.Type.IType[] types)
  {
      return true;
  }

  public bool OnSave(object entity, object id, object[] state, 
    string[] propertyNames, global::NHibernate.Type.IType[] types)
  {
      if (entity is IInsertLogable)
      {
          SetInsertLoggableValues(state, propertyNames);
          return true;
      }
      else if (entity is IModifyLogable)
      {
          SetModifyLoggableValues_OnInsert(state, propertyNames);
          return true;
      }
      else
      {
          return true;
      }
  }

  public void PostFlush(System.Collections.ICollection entities)
  {

  }

  public void PreFlush(System.Collections.ICollection entities)
  {

  }

  private Hashtable GetInsertLoggablePropertyIndexes(string[] Properties)
  {
      Hashtable result = new Hashtable();
      int propCounter = 0;
      for (int i = 0; i < Properties.Length; i++)
      {
          if (Properties[i].ToLower() == "syscreatedby")
          {
              propCounter++;
              result.Add("syscreatedby", i);
          }
          else if (Properties[i].ToLower() == "syscreatedon")
          {
              propCounter++;
              result.Add("syscreatedon", i);
          }

          if (propCounter == 2)
          {
              break;
          }
      }
      return result;  
  }

  private Hashtable GetUpdateLoggablePropertyIndexes(string[] Properties)
  {
      Hashtable result = new Hashtable();
      int propCounter = 0;
      for (int i = 0; i < Properties.Length ; i++)
      {
          if (Properties[i].ToLower() == "syslastupdatedby")
          {
              propCounter++;
              result.Add("syslastupdatedby", i);
          }
          else if (Properties[i].ToLower() == "syslastupdatedon")
          {
              propCounter++;
              result.Add("syslastupdatedon", i);
          }

          if (propCounter == 2)
          {
              break;
          }
      }
      return result;
  }

  private Hashtable GetModifyLoggablePropertyIndexes(string[] Properties)
  {
      Hashtable result = new Hashtable();
      int propCounter = 0;
      for (int i = 0; i < Properties.Length; i++)
      {
          if (Properties[i].ToLower() == "syscreatedby")
          {
              propCounter++;
              result.Add("syscreatedby", i);
          }
          else if (Properties[i].ToLower() == "syscreatedon")
          {
              propCounter++;
              result.Add("syscreatedon", i);
          }
          else if (Properties[i].ToLower() == "syslastupdatedby")
          {
              propCounter++;
              result.Add("syslastupdatedby", i);
          }
          else if (Properties[i].ToLower() == "syslastupdatedon")
          {
              propCounter++;
              result.Add("syslastupdatedon", i);
          }

          if (propCounter == 4)
          {
              break;
          }
      }
      return result;
  }

  private void SetInsertLoggableValues(object[] state, string[] Properties)
  {
      Hashtable indexes = GetInsertLoggablePropertyIndexes(Properties);
      if (indexes.Count != 2)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
                        Indexes not found!");
      }

      int index = -1;
      
      if(indexes["syscreatedby"] == null)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
            Index value for SysCreatedBy does not exist!");            
      }
      index = (int)indexes["syscreatedby"];
      state[index] = ContextManager.Instance.ActivePersonID;

      if (indexes["syscreatedon"] == null)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
            Index value for SysCreatedOn does not exist!");
      }
      index = (int)indexes["syscreatedon"];
      state[index] = DateTime.Now;

  }

  private void SetUpdateLoggableValues(object[] state, string[] Properties)
  {
      Hashtable indexes = GetUpdateLoggablePropertyIndexes(Properties);
      if (indexes.Count != 2)
      {
          throw new Exception("Can't log IUpdateLoggable entity. 
                            Indexes not found!");
      }

      int index = -1;

      if (indexes["syslastupdatedby"] == null)
      {
          throw new Exception("Can't log IUpdateLoggable entity. 
            Index value for SysLastUpdatedBy does not exist!");
      }
      index = (int)indexes["syslastupdatedby"];
      state[index] = ContextManager.Instance.ActivePersonID;

      if (indexes["syslastupdatedon"] == null)
      {
          throw new Exception("Can't log IUpdateLoggable entity. 
            Index value for SysLastUpdatedOn does not exist!");
      }
      index = (int)indexes["syslastupdatedon"];
      state[index] = DateTime.Now;

  }

  private void SetModifyLoggableValues_OnInsert(object[] state, 
                            string[] Properties)
  {
      Hashtable indexes = GetModifyLoggablePropertyIndexes(Properties);
      if (indexes.Count != 4)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
                            Indexes not found!");
      }

      int index = -1;

      if (indexes["syscreatedby"] == null)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
            Index value for SysCreatedBy does not exist!");
      }
      index = (int)indexes["syscreatedby"];
      state[index] = ContextManager.Instance.ActivePersonID;

      if (indexes["syscreatedon"] == null)
      {
          throw new Exception("Can't log IInsertLoggable entity. 
            Index value for SysCreatedOn does not exist!");
      }
      index = (int)indexes["syscreatedon"];
      state[index] = DateTime.Now;

  }

  private void SetModifyLoggableValues_OnUpdate(object[] state, 
                            string[] Properties)
  {
      Hashtable indexes = GetModifyLoggablePropertyIndexes(Properties);
      if (indexes.Count != 4)
      {
          throw new Exception("Can't log IModifyLogable entity. 
                            Indexes not found!");
      }

      int index = -1;

      if (indexes["syslastupdatedby"] == null)
      {
          throw new Exception("Can't log IModifyLogable entity. 
            Index value for SysLastUpdatedBy does not exist!");
      }
      index = (int)indexes["syslastupdatedby"];
      state[index] = ContextManager.Instance.ActivePersonID;

      if (indexes["syslastupdatedon"] == null)
      {
          throw new Exception("Can't log IModifyLogable entity. 
            Index value for SysLastUpdatedOn does not exist!");
      }
      index = (int)indexes["syslastupdatedon"];
      state[index] = DateTime.Now;
  }
  
  #endregion
}

Actually we only implemented OnFlushDirty and OnSave methods of the IInterceptor and left other the interface methods to return null or empty. The following methods are utility methods that help us to find out the domain object type and fill the appropriate log data:

Property validation methods

These methods simply loop through domain object properties, already supported by NHibernate, to determine if log fields (SysCreatedBy, SysLastUpdatedBy, SysCreatedOn, SysLastUpdatedOn) have NHibernate mapping definitions. If NHibernate mapping definitions do not exist for these fields, an exception is thrown by the interceptor.

• GetInsertLoggablePropertyIndexes
• GetUpdateLoggablePropertyIndexes
• GetModifyLoggablePropertyIndexes

Log data setters

These methods simply set log data (SysCreatedBy, SysLastUpdatedBy, SysCreatedOn, SysLastUpdatedOn) based on the loggable interface implemented by the domain object.

• SetInsertLoggableValues
• SetUpdateLoggableValues
• SetModifyLoggableValues_OnInsert
• SetModifyLoggableValues_OnUpdate

Remarks and Future Work Suggestions

The sample implementation was one of my first experiences with NHibernate. So it may not sound very efficient to you. But I believe this sample will be a good starting point.

I've read about some difficulties and tips about performing interceptor operations and logging using the NHibernate session that the interceptor is already attached to.

Further work can focus on logging to different databases by defining loggable domain object
implementations as reusable domain objects with their own mappings.