Download NHibernate.Caches.Testing.zip (24.75 kb)
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 Acceptance Testing phase. That new project was a little bit challenging from 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 little bit problematic process to introduce some new concepts
- Our system was designed targeting a small part of the legacy database, hovewer that part was accessed by some external processes/systems bringing some synchronization issues.
- We placed very strict code coverage and testing goals
In this blog entry I will try to share a very specific problem, writing good tests for NHibernate Level2 caching related functionality, we experienced and how we solved that problem.
Testing NHibernate Projects
I think testing NHibernate projects is a little bit tricky task. Let me explain why this is so tricky with an example
Think that since we are developing against a legacy database we have to use a legacy stored procedure to retreive some sort of data. To achieve this goal we introduce
- Data Access Layer (DAL) method called RetreiveDataViaStoredProcedure
- We introduce a data transfer object (DTO) to hold row data returned by our DAL method
- We define a named query in our NHibernate mapping
We want to test if our DAL method behaves the way we want it to. As a general unit testing practice we mock our DAL method, actually this method was defined on an interface and can be easily mocked, and we write our test. If we did not mocked the DAL method we would have to test it against the database which would conflict with "unit testing best practice:unit tests must run in miliseconds" and would bring "leave the database in a known state as soon as a single test is completed" challenge. At first glance this scenario seems very simple one; we know 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 DTO's from the returned resultset, may fail due to column datatype vs DTO property type mismatch caused by a developer bug either in 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 modified resultset. But since our test calls 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 is 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 NHibernate specific behaviour
- We can also write real unit tests for bussiness logic related parts in our projects. For example to test different taxing scenarios.
The Problem with testing Level2 Caching
In the latest phase of our project we decided to use Level2 caching provided by NHibernate. We easly introduced this feature to our project by changing some configuration and mapping settings. And then we wanted to test if we realy utilized Level2 cache the way we wanted. We wrote some tests that look like this one
001 /// <summary>
002 /// This test method demonstrates the difficulties of testing if an object was fetched from level2 cache
003 /// </summary>
004 [Test]
005 public void TheWayWeDoNotWantIt()
006 {
007 Parent parent = new Parent();
008 parent.Data = "ParentData";
009
010 Child child = new Child();
011 child.Parent = parent;
012 child.Data = "ChildData";
013 parent.Children.Add(child);
014
015 _parentDao.SaveOrUpdate(parent);
016 UnitOfWork.CommitCurrentAndStartNew();
017
018 Child c1 = _childDao.Get(child.Id);
019 UnitOfWork.CommitCurrentAndStartNew();
020
021 // Instance comes from the level2 cache
022 Child c2 = _childDao.Get(child.Id);
023
024 // We can not determine if instance comes from level2 cache with this assert
025 Assert.IsTrue(c2.Id == child.Id);
026
027 }
We have very simple domain wth 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 retreived the Child object from the Level2 cahce not the database. So we have to find a way to test if line 23 really caused a cache hit, a little bit tricky problem.
The Solution
NHibernate utilizes log4net to a great extent in order to provide a 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 Level2 cache related stuff and I was not suprised to see that NHibernate was providing nicely formatted log messages. That was what I needed, I could trap level2 cache related messages logged by NHibernate.Cache.ReadWriteCache logger and develop some utilities around this concept. ToDo list was
- Develop custom log4net appender and configure log4net to use this appender to cacth messages provided by NHibernate.Cache.ReadWriteCache logger
- Decode log messages, since they are strings following some sort of predefined format, to create well structured and easly managable 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
CachedEntityInfo class is used to hold a parsed log message data in a structered way. 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 kind of log objects. Here is the code listing
001public class CachedEntityInfo
002 {
003 public static readonly CachedEntityInfo Empty = new CachedEntityInfo();
004
005 public string TypeName { get; set; }
006 public string Id { get; set; }
007 public CacheLogAppender.CacheActionType CacheAction { get; set; }
008
009 public CachedEntityInfo(string typeName, string id, string actionName)
010 {
011 TypeName = typeName;
012 Id = id;
013 CacheAction = CacheLogAppender.ParseCacheActionTypeFromName(actionName);
014 }
015
016 private CachedEntityInfo()
017 {
018 }
019
020 public override string ToString()
021 {
022 return String.Format("{0}:{1}#{2}", CacheAction, TypeName, Id);
023 }
024 }
025
001public class CachedEntityInfoList : List<CachedEntityInfo>
002 {
003 public IList<CachedEntityInfo> FindMultiple(string typeName, object id, CacheLogAppender.CacheActionType actionType)
004 {
005 string idValue = id == null ? String.Empty : id.ToString();
006 return this.Where<CachedEntityInfo>(c => c.TypeName == typeName && (String.IsNullOrEmpty(idValue) || c.Id == idValue ) && c.CacheAction == actionType).ToList<CachedEntityInfo>();
007 }
008
009 public IList<CachedEntityInfo> FindMultiple(Type type, object id, CacheLogAppender.CacheActionType actionType)
010 {
011 if (type == null)
012 throw new NullReferenceException("type parameter is null. Can not perform FindAll.");
013
014 return FindMultiple(type.FullName,id,actionType);
015 }
016
017 public IList<CachedEntityInfo> FindMultiple(Type type, CacheLogAppender.CacheActionType actionType)
018 {
019 return FindMultiple(type.FullName, null, actionType);
020 }
021
022 public IList<CachedEntityInfo> FindMultiple(Type type, Type compositeIdType, CacheLogAppender.CacheActionType actionType)
023 {
024 if (compositeIdType == null)
025 throw new NullReferenceException("compositeIdType parameter is null. Can not perform FindMultiple.");
026 return FindMultiple(type.FullName, compositeIdType.FullName, actionType);
027 }
028
029 public CachedEntityInfo FindSingle(string typeName, object id, CacheLogAppender.CacheActionType actionType)
030 {
031 string idValue = id == null ? String.Empty : id.ToString();
032 return this.SingleOrDefault<CachedEntityInfo>(c => c.TypeName == typeName && (String.IsNullOrEmpty(idValue) || c.Id == idValue) && c.CacheAction == actionType);
033 }
034
035 public CachedEntityInfo FindSingle(Type type, object id, CacheLogAppender.CacheActionType actionType)
036 {
037 if (type == null)
038 throw new NullReferenceException("type parameter is null. Can not perform FindSingle.");
039
040 return FindSingle(type.FullName, id, actionType);
041 }
042
043 public CachedEntityInfo FindSingle(Type type, CacheLogAppender.CacheActionType actionType)
044 {
045 return FindSingle(type.FullName, null, actionType);
046 }
047
048 public CachedEntityInfo FindSingle(Type type, Type compositeIdType, CacheLogAppender.CacheActionType actionType)
049 {
050 if (compositeIdType == null)
051 throw new NullReferenceException("compositeIdType parameter is null. Can not perform FindSingle.");
052 return FindSingle(type.FullName, compositeIdType.FullName, actionType);
053 }
054 }
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 AppenderSkeleton abstract class as the base class for our custom appender implementation. This class has some simple responsibilities
- Catch catch log messages provided by NHibernate.Cache.ReadWriteCache logger.
- Parse log messagesand create CachedEntityInfo instances
- Notify attached observers withn an eventas soon as a new log message is received.
Here is code listing for CacheLogAppender.
001public delegate void CacheLogAppendDelegate(CachedEntityInfo cacheInfo);
002 /// <summary>
003 /// Log4Net appender implementation
004 /// </summary>
005 public class CacheLogAppender : AppenderSkeleton
006 {
007 /// <summary>
008 /// Cache action enumeration.
009 /// </summary>
010 public enum CacheActionType
011 {
012 Unknow,
013 Invalidate,
014 Release,
015 Caching,
016 Cached,
017 CacheLookup,
018 CacheMiss,
019 CacheHit,
020 Locked,
021 Inserting,
022 Inserted
023 }
024
025 private CacheLogAppendDelegate _onLogAppend;
026 public event CacheLogAppendDelegate OnLogAppend
027 {
028 add { _onLogAppend += value; }
029 remove { _onLogAppend -= value; }
030 }
031
032 /// <summary>
033 /// Parse CacheActionType from name
034 /// </summary>
035 /// <param name="name"></param>
036 /// <returns></returns>
037 public static CacheActionType ParseCacheActionTypeFromName(string name)
038 {
039 string invariantName = name.ToLowerInvariant();
040 switch (invariantName)
041 {
042 case "invalidating":
043 return CacheActionType.Invalidate;
044 case "releasing":
045 return CacheActionType.Release;
046 case "caching":
047 return CacheActionType.Caching;
048 case "cached":
049 return CacheActionType.Cached;
050 case "cache lookup":
051 return CacheActionType.CacheLookup;
052 case "cache miss":
053 return CacheActionType.CacheMiss;
054 case "cache hit":
055 return CacheActionType.CacheHit;
056 case "cached item was locked":
057 return CacheActionType.Locked;
058 case "inserting":
059 return CacheActionType.Inserting;
060 case "inserted":
061 return CacheActionType.Inserted;
062 default:
063 return CacheActionType.Unknow;
064 }
065 }
066
067 /// <summary>
068 /// Append log
069 /// </summary>
070 /// <param name="loggingEvent"></param>
071 protected override void Append(LoggingEvent loggingEvent)
072 {
073 if (loggingEvent.MessageObject == null)
074 return;
075
076 CachedEntityInfo cachedEntity = ParseMessageObject(loggingEvent.MessageObject);
077 if(cachedEntity != null && _onLogAppend != null)
078 _onLogAppend(cachedEntity);
079 }
080
081 /// <summary>
082 /// Append logs
083 /// </summary>
084 /// <param name="loggingEvents"></param>
085 protected override void Append(LoggingEvent[] loggingEvents)
086 {
087 base.Append(loggingEvents);
088 }
089
090 /// <summary>
091 /// Parse message object to produce a CachedEntityInfo instance.
092 /// </summary>
093 /// <param name="messageObject"></param>
094 /// <returns></returns>
095 private CachedEntityInfo ParseMessageObject(object messageObject)
096 {
097 if (messageObject == null)
098 throw new NullReferenceException("Message object is null. Can not parse log message object.");
099
100 string logMessage = messageObject.ToString();
101
102 Match m = Regex.Match(logMessage, @"(?<ActionName>.*)\s*:\s*(?<TypeName>.*)\s*\#\s*(?<Id>.*)", RegexOptions.IgnoreCase);
103 if (!m.Success)
104 throw new Exception("Log message does not match the pattern!");
105
106 string actionName = m.Groups["ActionName"].Value;
107 string typeName = m.Groups["TypeName"].Value;
108 string id = m.Groups["Id"].Value;
109
110 return new CachedEntityInfo(String.IsNullOrEmpty(typeName) ? typeName : typeName.Trim()
111 , String.IsNullOrEmpty(id) ? id : id.Trim()
112 , String.IsNullOrEmpty(actionName) ? actionName : actionName.Trim());
113 }
114 }
CacheLogObserver
Implementation
We will use this class in our tests to inspect level2 caching related messages.
- Implements IDisposable that we can placeour tests inside using blocks.
- Gets the CacheLogAppender instance currently instantiated and is used by log4net framework
- Attaches delegate to CacheLogAppender OnLogAppend event.
- Stores caching related log messages in a CachedEntityInfoList instance
Here is the code listing, The only tricky bit in CacheLogObserver is cosntructor cod, where we get the log4net repository and get CacheLogAppender instance instantiated and used by log4net.
001public class CacheLogObserver : IDisposable
002 {
003 private CacheLogAppender _appender = null;
004 private CachedEntityInfoList _cachedEntityInfos = new CachedEntityInfoList();
005 public CachedEntityInfoList CachedEntityInfos
006 {
007 get { return _cachedEntityInfos; }
008 }
009
010 #region IDisposable Members
011
012 private bool _disposing = false;
013 public void Dispose()
014 {
015 if (_disposing)
016 return;
017 _disposing = true;
018
019 if (_appender != null)
020 _appender.OnLogAppend -= new CacheLogAppendDelegate(appender_OnLogAppend);
021 }
022 #endregion
023
024 public CacheLogObserver(string logRepositoryName)
025 {
026 ILoggerRepository loggerRepo = log4net.Core.LoggerManager.GetRepository(logRepositoryName);
027 _appender = loggerRepo.GetAppenders().Single<IAppender>(a => a.GetType() == typeof(CacheLogAppender)) as CacheLogAppender;
028 _appender.OnLogAppend += new CacheLogAppendDelegate(appender_OnLogAppend);
029 }
030
031 /// <summary>
032 /// Default constructor. Gets default log4net repository.
033 /// </summary>
034 public CacheLogObserver()
035 : this("log4net-default-repository")
036 {
037
038 }
039
040
041 private void appender_OnLogAppend(CachedEntityInfo cacheInfo)
042 {
043 _cachedEntityInfos.Add(cacheInfo);
044 }
045 }
Usage
Here is our solition at work. We simply rewrote our test method to use CacheLogObserver and changed our test assertion to check if expected level2 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.
001[Test]
002 public void TheWayWeWantIt()
003 {
004 Parent parent = new Parent();
005 parent.Data = "TestParent";
006
007 Child child = new Child();
008 child.Parent = parent;
009 child.Data = "TestChild";
010 parent.Children.Add(child);
011
012 _parentDao.SaveOrUpdate(parent);
013 UnitOfWork.CommitCurrentAndStartNew();
014
015 Child c1 = _childDao.Get(child.Id);
016 UnitOfWork.CommitCurrentAndStartNew();
017
018 using (CacheLogObserver observer = new CacheLogObserver())
019 {
020 // Instance comes from the level2 cache
021 Child c2 = _childDao.Get(child.Id);
022
023 CachedEntityInfo cacheInfo = observer.CachedEntityInfos.FindSingle(c2.GetType(), c2.Id, CacheLogAppender.CacheActionType.CacheHit);
024 Assert.IsNotNull(cacheInfo);
025 }
026 }
Configuring our test project
Follow these steps to modify your test project configuration file (App.config or Web.config)
- Add log4net section to under configSections as in Line 5.
- Add CacheLogAppender under log4net section as in Line 39 through Line 42
- Add new logger under log4net section Line 55 through Line 58
Your configuration must look like
001<?xml version="1.0" encoding="utf-8"?>
002<configuration>
003 <configSections>
004 <section name="NHibernate.Burrow" type="NHibernate.Burrow.Configuration.NHibernateBurrowCfgSection, NHibernate.Burrow, Version=1.0.0.2002, Culture=neutral, PublicKeyToken=null" />
005 <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net, Version=1.2.10.0, Culture=neutral, PublicKeyToken=1b44e1d426115821" />
006 <section name="syscache" type="NHibernate.Caches.SysCache.SysCacheSectionHandler,NHibernate.Caches.SysCache" />
007 </configSections>
008 <appSettings>
009 <add key="ClientSettingsProvider.ServiceUri" value="" />
010 <!-- Connection string used for mocking database records/classes-->
011 </appSettings>
012
013 <NHibernate.Burrow>
014 <persistenceUnits>
015 <add name="NHibernate.Caches.Testing" nh-config-file="~\..\..\Config\NHTest.config"/>
016 </persistenceUnits>
017 </NHibernate.Burrow>
018 <system.web>
019 <membership defaultProvider="ClientAuthenticationMembershipProvider">
020 <providers>
021 <add name="ClientAuthenticationMembershipProvider" type="System.Web.ClientServices.Providers.ClientFormsAuthenticationMembershipProvider, System.Web.Extensions, Version=3.5.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" serviceUri="" />
022 </providers>
023 </membership>
024 <roleManager defaultProvider="ClientRoleProvider" enabled="true">
025 <providers>
026 <add name="ClientRoleProvider" type="System.Web.ClientServices.Providers.ClientRoleProvider, System.Web.Extensions, Version=3.5.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" serviceUri="" cacheTimeout="86400" />
027 </providers>
028 </roleManager>
029 </system.web>
030
031 <log4net debug="false">
032 <!-- Define some output appenders -->
033
034 <appender name="trace" type="log4net.Appender.TraceAppender">
035 <layout type="log4net.Layout.PatternLayout">
036 </layout>
037 </appender>
038
039 <appender name="CacheLogAppender" type="Tests.CacheLogAppender">
040 <layout type="log4net.Layout.PatternLayout">
041 </layout>
042 </appender>
043
044 <!-- Setup the root category, add the appenders and set the default priority -->
045 <!-- levels: DEBUG, INFO, WARN, ERROR, FATAL -->
046
047 <root>
048 <priority value="DEBUG" />
049 </root>
050
051 <logger name="NHibernate" additivity="true">
052 <level value="DEBUG"/>
053 <appender-ref ref="trace"/>
054 </logger>
055 <logger name="NHibernate.Cache.ReadWriteCache" additivity="true">
056 <level value="DEBUG"/>
057 <appender-ref ref="CacheLogAppender"/>
058 </logger>
059 </log4net>
060 <syscache>
061 <cache region='NHibernate.Caches.Testing' expiration="60" priority="3" />
062 </syscache>
063 </configuration>
Solution Structure And External Dependencies
Downloadable solution attached to this entry contains two projects.
- Domain project is where we define our entities and mappings
- 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 SessionInView pattern, transaction management and some other great stuff
- NHibernate.Caches: Provides different Level2 cache provider implementations
- MBUnit: Unit testing framework. You can replace MBUnit with any other unit testing framework with some little code changes to TestBase class.
- Log4Net
Download NHibernate.Caches.Testing.zip (24.75 kb)
Other Possibilities and Some Speculation
You can use NHibernate log messages to perform lots of other stuff, such as the one Ayende did with 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 invaluable contributions he is making, I was a bit confused with 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 widely used open source project like NHibernate to support new paid features for a commercial tool like NHProf
- What will happen if NHibernate team changes format of some log messages, how will Ayende control the format of the messages so that we can be sure that NHProf performs realy good analysis.
- NHProf is a commercial product with cost of 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.
Update
In codeprojet forums one of the readers mentioned that CompositeEntity object can not be found in the database. You can execute the following T-SQL script to create CompositeEntity table in your database.