Writing NHibernate Level 2 Cache Usage Tests

• Download source code - 20.2 KB
• See updates to this article

Motivation

It has been a long time since the last time I dropped a new entry in my blog. I was very busy with our new project, and at last, we finished coding and moved to the Acceptance Testing phase. That new project was a little bit challenging from an architectural point of view. Some challenges to name were:

• We had to develop against a legacy database.
• We had to replace an existing system with a new one, it was a slightly problematic process to introduce some new concepts.
• Our system was designed targeting a small part of the legacy database; however, that part was accessed by some external processes/systems, bringing some synchronization issues.
• We placed very strict code coverage and testing goals.

In this article, I will try to share a very specific problem, writing good tests for NHibernate Level 2 caching related functionality, what we experienced, and how we solved that problem.

Testing NHibernate Projects

I think testing NHibernate projects is a little tricky. Let me explain why this is so tricky with an example.

Since we were developing against a legacy database, we had to use a legacy Stored Procedure to retrieve some sort of data. To achieve this goal, we introduced:

• A Data Access Layer (DAL) method called RetreiveDataViaStoredProcedure.
• A data transfer object (DTO) to hold row data returned by our DAL method.
• A named query in our NHibernate mapping.

We wanted to test if our DAL method behaved the way we wanted it to. As a general Unit Testing practice, we mocked our DAL method. Actually, this method was defined on an interface and could be easily mocked, and we wrote our test. If we did not mock the DAL method, we would have to test it against the database which would conflict with the "Unit Testing best practice: Unit Tests must run in miliseconds" and would bring the "leave the database in a known state as soon as a single test is completed" challenge. At first glance, this scenario seemed a very simple one; we knew what to do and what not to do.

But I am sorry to tell you that mocking does not really test if our DAL method behaves correctly, and this may cause subtle bugs to leak into our production. Because:

• Transformer, provided by NHibernate, which is used to produce DTOs from a returned resultset, may fail due to column datatype vs. DTO property type mismatch caused by a developer bug either in the DAL method or in the Stored Procedure.
• If we change our Stored Procedure, our test must fail so that we can modify our DTO to handle the modified resultset. But, since our test calls the mocked version of our method, we would not have a failing test although our procedure was changed.
• We would not know if our named query mapping has errors.

So, the only way to test our DAL method was to design a test that runs against a test database, which is not a best practice, even not a Unit Test. The point is:

• We have to write tests which directly access a test database, since we want to test an NHibernate specific behaviour.
• We can also write real Unit Tests for the business logic related parts in our projects. For example, to test different taxing scenarios.

The Problem with Testing Level 2 Caching

In the latest phase of our project, we decided to use the Level 2 caching provided by NHibernate. We easily introduced this feature to our project by changing some configuration and mapping settings. And then, we wanted to test if we really utilized the Level 2 cache the way we wanted. We wrote some tests that looked like this one:

/// <summary>
/// This test method demonstrates the difficulties
/// of testing if an object was fetched from level2 cache
/// </summary>

[Test]
public void TheWayWeDoNotWantIt()
{
      Parent parent = new Parent();
      parent.Data = "ParentData";

      Child child = new Child();
      child.Parent = parent;
      child.Data = "ChildData";

      parent.Children.Add(child);
      _parentDao.SaveOrUpdate(parent);

      UnitOfWork.CommitCurrentAndStartNew();

      Child c1 = _childDao.Get(child.Id);
      UnitOfWork.CommitCurrentAndStartNew();

      // Instance comes from the level2 cache
      Child c2 = _childDao.Get(child.Id);
    
      // We can not determine if instance
      // comes from level2 cache with this assert
      Assert.IsTrue(c2.Id == child.Id);
}

We have a very simple domain with two entity classes, namely Parent and Child. Each parent object may have 0+ Child objects and each Child object has a Parent. The problem in the example test method is in the Assert.IsTrue(c2.Id == child.Id) call in line 26. Success of this assertion does not assure us that last call to Child c2 = _childDao.Get(child.Id) in line 23 caused a cache hit, thus we retrieved the Child object from the Level 2 cache, not the database. So, we had to find a way to test if line 23 really caused a cache hit, a bit tricky problem.

The Solution

NHibernate utilizes log4net to a great extent in order to provide very detailed runtime log messages for different levels. I used to use NHibernate log messages to trap what actually happened inside NHibernate when a data access related test fails. So, as a reflex, I checked out what was NHibernate logging when performing Level 2 cache related stuff, and I was not surprised to see that NHibernate was providing nicely formatted log messages. That was what I needed. I could trap Level 2 cache related messages logged by the NHibernate.Cache.ReadWriteCache logger and develop some utilities around this concept. The ToDo list was:

• Develop custom log4net appender and configure log4net to use this appender to catch messages provided by the NHibernate.Cache.ReadWriteCache logger.
• Decode log messages, since they are strings following some sort of predefined format, to create well structured and easily manageable cached entity info objects.
• Design an Observer class that can be used to observe caching related log messages caught by my custom appender.

CachedEntityInfo and CachedEntityInfoList

The CachedEntityInfo class is used to hold parsed log message data in a structured way. The CachedEntityInfoList class is inherited from List<CachedEntityInfo>, and is used to hold log messages decoded as CachedEntityInfo objects, and provides custom wrapper methods for querying specific kinds of log objects. Here is the code listing:

public class CachedEntityInfo
{
    public static readonly CachedEntityInfo Empty = new CachedEntityInfo();
    public string TypeName { get; set; }
    public string Id { get; set; }
    public CacheLogAppender.CacheActionType CacheAction { get; set; }

    public CachedEntityInfo(string typeName, string id, string actionName)
    {
      TypeName = typeName;
      Id = id;
      CacheAction = CacheLogAppender.ParseCacheActionTypeFromName(actionName);
    }
 
    private CachedEntityInfo(){}
    public override string ToString()
    {
      return String.Format("{0}:{1}#{2}", CacheAction, TypeName, Id);
    }
}

public class CachedEntityInfoList : List<CachedEntityInfo>
{
    public IList<CachedEntityInfo> FindMultiple(string typeName, object id, 
           CacheLogAppender.CacheActionType actionType)
    {
      string idValue = id == null ? String.Empty : id.ToString();
      return this.Where<CachedEntityInfo>(c => c.TypeName == typeName && 
            (String.IsNullOrEmpty(idValue) || c.Id == idValue ) && 
            c.CacheAction == actionType).ToList<CachedEntityInfo>();
    }

    public IList<CachedEntityInfo> FindMultiple(Type type, object id, 
           CacheLogAppender.CacheActionType actionType)
    {
      if (type == null)
        throw new NullReferenceException("type parameter is null. Can not perform FindAll.");

      return FindMultiple(type.FullName,id,actionType);
    }

    public IList<CachedEntityInfo> FindMultiple(Type type, 
           CacheLogAppender.CacheActionType actionType)
    {
      return FindMultiple(type.FullName, null, actionType);
    }

    public IList<CachedEntityInfo> FindMultiple(Type type, Type compositeIdType, 
           CacheLogAppender.CacheActionType actionType)
    {
      if (compositeIdType == null)
        throw new NullReferenceException("compositeIdType parameter is null." + 
                  " Can not perform FindMultiple.");

      return FindMultiple(type.FullName, compositeIdType.FullName, actionType);
    }

    public CachedEntityInfo FindSingle(string typeName, object id, 
           CacheLogAppender.CacheActionType actionType)
    {
      string idValue = id == null ? String.Empty : id.ToString();

      return this.SingleOrDefault<CachedEntityInfo>(c => c.TypeName == 
             typeName && (String.IsNullOrEmpty(idValue) 
             || c.Id == idValue) && c.CacheAction == actionType);
    }

    public CachedEntityInfo FindSingle(Type type, object id, 
           CacheLogAppender.CacheActionType actionType)
    {
      if (type == null)
        throw new NullReferenceException("type parameter is null." + 
                  " Can not perform FindSingle.");

      return FindSingle(type.FullName, id, actionType);
    }

    public CachedEntityInfo FindSingle(Type type, 
           CacheLogAppender.CacheActionType actionType)
    {
      return FindSingle(type.FullName, null, actionType);
    }

    public CachedEntityInfo FindSingle(Type type, Type compositeIdType, 
           CacheLogAppender.CacheActionType actionType)
    {
      if (compositeIdType == null)
        throw new NullReferenceException("compositeIdType parameter" + 
                  " is null. Can not perform FindSingle.");

        return FindSingle(type.FullName, compositeIdType.FullName, actionType);
    }
}

CacheLogAppender: A custom log4net appender

Log4Net allows us to implement custom log appenders by implementing the IAppender interface. Instead of implementing IAppender from scratch, we can also use the AppenderSkeleton abstract class as the base class for our custom appender implementation. This class has some simple responsibilities:

• Catch log messages provided by the NHibernate.Cache.ReadWriteCache logger.
• Parse log messages and create CachedEntityInfo instances.
• Notify attached observers with an event as soon as a new log message is received.

Here is the code listing for CacheLogAppender:

public delegate void CacheLogAppendDelegate(CachedEntityInfo cacheInfo);

/// <summary>
/// Log4Net appender implementation
/// </summary>
public class CacheLogAppender : AppenderSkeleton
{
    /// <summary>
    /// Cache action enumeration.
    /// </summary>
    public enum CacheActionType
    {
      Unknow,
      Invalidate,
      Release,
      Caching,
      Cached,
      CacheLookup,
      CacheMiss,
      CacheHit,
      Locked,
      Inserting,
      Inserted
    }

    private CacheLogAppendDelegate _onLogAppend;
    public event CacheLogAppendDelegate OnLogAppend
    {
      add { _onLogAppend += value; }
      remove { _onLogAppend -= value; }
    }

    /// <summary>
    /// Parse CacheActionType from name
    /// </summary>
    /// <param name="name"></param>
    /// <returns></returns>
    public static CacheActionType ParseCacheActionTypeFromName(string name)
    {
      string invariantName = name.ToLowerInvariant();
      switch (invariantName)
      {
        case "invalidating":
          return CacheActionType.Invalidate;
        case "releasing":
          return CacheActionType.Release;
        case "caching":
          return CacheActionType.Caching;
        case "cached":
          return CacheActionType.Cached;
        case "cache lookup":
          return CacheActionType.CacheLookup;
        case "cache miss":
          return CacheActionType.CacheMiss;
        case "cache hit":
          return CacheActionType.CacheHit;
        case "cached item was locked":
          return CacheActionType.Locked;
        case "inserting":
          return CacheActionType.Inserting;
        case "inserted":
          return CacheActionType.Inserted;
        default:
          return CacheActionType.Unknow;
      }
    }

    /// <summary>
    /// Append log
    /// </summary>
    /// <param name="loggingEvent"></param>
    protected override void Append(LoggingEvent loggingEvent)
    {
      if (loggingEvent.MessageObject == null)
        return;

      CachedEntityInfo cachedEntity = ParseMessageObject(loggingEvent.MessageObject);
      if(cachedEntity != null && _onLogAppend != null)
        _onLogAppend(cachedEntity);
    }

    /// <summary>
    /// Append logs
    /// </summary>
    /// <param name="loggingEvents"></param>
    protected override void Append(LoggingEvent[] loggingEvents)
    {
      base.Append(loggingEvents);
    }

    /// <summary>
    /// Parse message object to produce a CachedEntityInfo instance.
    /// </summary>
    /// <param name="messageObject"></param>
    /// <returns></returns>
    private CachedEntityInfo ParseMessageObject(object messageObject)
    {
      if (messageObject == null)
        throw new NullReferenceException("Message object is null." + 
                  " Can not parse log message object.");

      string logMessage = messageObject.ToString();

      Match m = Regex.Match(logMessage, 
                @"(?<ActionName>.*)\s*:\s*(?<TypeName>.*)\s*\#\s*(?<Id>.*)", 
                RegexOptions.IgnoreCase);
      if (!m.Success)
        throw new Exception("Log message does not match the pattern!");

      string actionName = m.Groups["ActionName"].Value;
      string typeName = m.Groups["TypeName"].Value;
      string id = m.Groups["Id"].Value;

      return new CachedEntityInfo(String.IsNullOrEmpty(typeName) ? 
             typeName : typeName.Trim(), String.IsNullOrEmpty(id) ? id : id.Trim(), 
             String.IsNullOrEmpty(actionName) ? actionName : actionName.Trim());
    }
}

CacheLogObserver

Implementation

We will use this class in our tests to inspect Level 2 caching related messages.

• Implements IDisposable that we can place our tests inside using blocks.
• Gets the CacheLogAppender instance currently instantiated, and is used by the log4net framework.
• Attaches a delegate to the CacheLogAppender OnLogAppend event.
• Stores caching related log messages in a CachedEntityInfoList instance.

Here is the code listing. The only tricky bit in CacheLogObserver is the constructor code where we get the log4net repository and get the CacheLogAppender instance instantiated and used by log4net.

public class CacheLogObserver : IDisposable
{
    private CacheLogAppender _appender = null;
    private CachedEntityInfoList _cachedEntityInfos = 
            new CachedEntityInfoList();
    public CachedEntityInfoList CachedEntityInfos
    {
      get { return _cachedEntityInfos; }
    }

    #region IDisposable Members
    private bool _disposing = false;
    public void Dispose()
    {
      if (_disposing)
        return;

        _disposing = true;
      if (_appender != null)
        _appender.OnLogAppend -= 
          new CacheLogAppendDelegate(appender_OnLogAppend);
    }
    #endregion

    public CacheLogObserver(string logRepositoryName)
    {
      ILoggerRepository loggerRepo = 
        log4net.Core.LoggerManager.GetRepository(logRepositoryName);
      _appender = loggerRepo.GetAppenders().Single<IAppender>(a => 
                      a.GetType() == typeof(CacheLogAppender)) as CacheLogAppender;
      _appender.OnLogAppend += new CacheLogAppendDelegate(appender_OnLogAppend);
    }

    /// <summary>
    /// Default constructor. Gets default log4net repository.
    /// </summary>
    public CacheLogObserver()
      : this("log4net-default-repository"){}
    private void appender_OnLogAppend(CachedEntityInfo cacheInfo)
    {
      _cachedEntityInfos.Add(cacheInfo);
    }
}

Usage

Here is our solution at work. We simply rewrite our test method to use CacheLogObserver, and change our test assertion to check if the expected Level 2 cache action (cache hit) is included in the CachedEntityInfos list of our Observer instance. Please note that we placed our test code inside a using block.

[Test]

public void TheWayWeWantIt()
{
      Parent parent = new Parent();
      parent.Data = "TestParent";
      Child child = new Child();
      child.Parent = parent;
      child.Data = "TestChild";
      parent.Children.Add(child);

      _parentDao.SaveOrUpdate(parent);
      UnitOfWork.CommitCurrentAndStartNew();

      Child c1 = _childDao.Get(child.Id);
      UnitOfWork.CommitCurrentAndStartNew();

      using (CacheLogObserver observer = new CacheLogObserver())
      {
        // Instance comes from the level2 cache
        Child c2 = _childDao.Get(child.Id);
        CachedEntityInfo cacheInfo = observer.CachedEntityInfos.FindSingle(c2.GetType(), 
                         c2.Id, CacheLogAppender.CacheActionType.CacheHit);

        Assert.IsNotNull(cacheInfo);
      }
}

Configuring our Test Project

Follow these steps to modify your test project configuration file (App.config or Web.config):

• Add a log4net section under configSections, as in line 5.
• Add CacheLogAppender under the log4net section, as in line 39 through line 42.
• Add a new logger under the log4net section, as in line 55 through line 58.

Your configuration must look like:

<?xml version="1.0" encoding="utf-8"?>

<configuration>
  <configSections>
    <section name="NHibernate.Burrow" 
      type="NHibernate.Burrow.Configuration.NHibernateBurrowCfgSection, 
            NHibernate.Burrow, Version=1.0.0.2002, Culture=neutral, 
            PublicKeyToken=null" />
    <section name="log4net" 
       type="log4net.Config.Log4NetConfigurationSectionHandler, 
             log4net, Version=1.2.10.0, Culture=neutral, 
             PublicKeyToken=1b44e1d426115821" />
    <section name="syscache" 
       type="NHibernate.Caches.SysCache.SysCacheSectionHandler,
             NHibernate.Caches.SysCache" />
  </configSections>
  <appSettings>
    <add key="ClientSettingsProvider.ServiceUri" value="" />
    <!-- Connection string used for mocking database records/classes-->
  </appSettings>

  <NHibernate.Burrow>
    <persistenceUnits>
      <add name="NHibernate.Caches.Testing" 
           nh-config-file="~\..\..\Config\NHTest.config"/>
    </persistenceUnits>
  </NHibernate.Burrow>
  <system.web>
    <membership defaultProvider="ClientAuthenticationMembershipProvider">
      <providers>
        <add name="ClientAuthenticationMembershipProvider" 
           type="System.Web.ClientServices.Providers.
                 ClientFormsAuthenticationMembershipProvider, 
                 System.Web.Extensions, Version=3.5.0.0, Culture=neutral, 
                 PublicKeyToken=31bf3856ad364e35"
           serviceUri="" />
      </providers>
    </membership>
    <roleManager defaultProvider="ClientRoleProvider" enabled="true">
      <providers>
        <add name="ClientRoleProvider" 
           type="System.Web.ClientServices.Providers.ClientRoleProvider, 
                 System.Web.Extensions, Version=3.5.0.0, Culture=neutral, 
                 PublicKeyToken=31bf3856ad364e35"
           serviceUri="" cacheTimeout="86400" />
      </providers>
    </roleManager>
  </system.web>
  <log4net debug="false">
    <!-- Define some output appenders -->
    <appender name="trace" type="log4net.Appender.TraceAppender">
      <layout type="log4net.Layout.PatternLayout">
      </layout>
    </appender>
    <appender name="CacheLogAppender" type="Tests.CacheLogAppender">
      <layout type="log4net.Layout.PatternLayout">
      </layout>
    </appender>
    <!-- Setup the root category, add the appenders and set the default priority -->
    <!-- levels: DEBUG, INFO, WARN, ERROR, FATAL -->
    <root>
      <priority value="DEBUG" />
    </root>
    <logger name="NHibernate" additivity="true">
      <level value="DEBUG"/>
      <appender-ref ref="trace"/>
    </logger>
    <logger name="NHibernate.Cache.ReadWriteCache" additivity="true">
      <level value="DEBUG"/>
      <appender-ref ref="CacheLogAppender"/>
    </logger>
  </log4net>
  <syscache>
    <cache region='NHibernate.Caches.Testing' expiration="60" priority="3" />
  </syscache>
</configuration>

Solution Structure and External Dependencies

The downloadable solution attached to this entry contains two projects:

• The Domain project is where we define our entities and mappings.
• The Tests project is where we have our tests, our log4net appender implementation, and some other NHibernate related utility classes.

The sample solution depends on:

• NHibernate.Burrow: Excellent framework implementing the SessionInView pattern, transaction management, and some other great stuff.
• NHibernate.Caches: Provides different Level 2 cache provider implementations.
• MBUnit: Unit Testing framework. You can replace MBUnit with any other Unit Testing framework with some code changes to the TestBase class.
• Log4Net

Other Possibilities and Some Speculation

You can use NHibernate log messages to perform lots of other stuff, such as the one Ayende did with the NHibernate Profiler (NHProf). I do not have any idea about the internals of NHProf, but what I understood from this document is that in order to enable NHProf in our projects, we have to setup custom NHProf appenders. But to be honest, although Ayende is a person for whom I have great respect because of the invaluable contributions he is making, I was a bit confused with the NHibernate Profiler because:

• Ayende writes in one of his posts that in order to add some features to NHProf, he had to change the NHibernate trunk. I think it is a big mistake to change a widely used Open Source project like NHibernate to support new paid features for a commercial tool like NHProf.
• What will happen if the NHibernate team changes the format of some log messages, how will Ayende control the format of the messages so that we can be sure that NHProf performs really good analysis.
• NHProf is a commercial product costing 200 Euros per seat.

Aside from these confusion points, I still appreciate the work performed on the analysis part of NHProf. Enough of that much speculation.