Abstract:
The student said to his zen master: "What time is it?"
"It is TimeWarper.Now", the master replied.
"What time is that?", asked the student.
"It is whatever time I need it to be.", said the master.
And the student was enlightened.
Quite often you'll want your application to save a timestamp of when something occured. Due to the nature of time this presents a special set of challenges when it comes to testing.
Let's look at an example for logging exceptions.
Here's an initial attempt at a test:
That looks straightforward enough doesn't it?
[Test]
public void TestLogException_LogsCorrectValues()
{
try
{
throw new AbandonedMutexException("The poor mutex was abandoned!");
}
catch (Exception ex)
{
// Log the exception
ExceptionLog log = _exceptionLogger.LogException(ex);
// Assert that the logged values are correct
Assert.AreEqual("System.Threading.AbandonedMutexException", log.ExceptionType);
Assert.AreEqual("The poor mutex was abandoned!", log.Message);
Assert.That(!string.IsNullOrEmpty(log.StackTrace));
Assert.AreEqual(1, log.NumOccurences);
Assert.AreEqual(DateTime.Now, log.FirstOccurrence); // <-- Mind the dates!
Assert.AreEqual(DateTime.Now, log.LastOccurrence); // <-- Mind the dates!
}
}
Let's make the test work:
public class ExceptionLogger
{
public ExceptionLog LogException(Exception ex)
{
ExceptionLog log = new ExceptionLog();
log.ExceptionType = ex.GetType().ToString();
log.Message = ex.Message;
log.NumOccurences = 1;
log.StackTrace = ex.StackTrace;
log.FirstOccurrence = DateTime.Now;
log.LastOccurrence = DateTime.Now;
return log;
}
}
public class ExceptionLog
{
public string ExceptionType { get; set; }
public string Message { get; set; }
public string StackTrace { get; set; }
public DateTime FirstOccurrence { get; set; }
public DateTime LastOccurrence { get; set; }
public int NumOccurences { get; set; }
}
Running the test, we see that it fails!
The line failing is:
Assert.AreEqual(DateTime.Now, log.FirstOccurrence);
With this message:
NUnit.Framework.AssertionException:
Expected: 2009-02-02 11:39:42.820
But was: 2009-02-02 11:39:42.787
But was: 2009-02-02 11:39:42.787
As you can see 33 milliseconds have past between saving DateTime.Now to log.FirstOccurence and comparing the results to DateTime.Now in the Assert.AreEqual method.
This makes perfect sense. Time tends to pass even for very fast computers.
But what do we do about it? There are a few possible solutions that spring to mind:
Remove the Assert - We could just decide it's too much trouble to test and move on. That's not very nice. If we go down that road we could just stop testing right now and finish the code.
Make the Assert less precise - We could just strip the milliseconds. Who cares about them anyway? We could do that, but there's a 3,3% chance that the test is run in the milliseconds that overlaps one second changing to another. This would cause the test to inexplicably fail every now and again. Unacceptable.
Overload ExceptionLogger.LogException
We could get control of what DateTime to set by overloading LogException like this:
[Test]
public void TestLogException_LogsCorrectValues()
{
try
{
throw new AbandonedMutexException("The poor mutex was abandoned!");
}
catch (Exception ex)
{
DateTime now = DateTime.Now; //<-- New variable!
// Log the exception
ExceptionLog log = _exceptionLogger.LogException(ex, now);
// Assert that the logged values are correct
Assert.AreEqual("System.Threading.AbandonedMutexException", log.ExceptionType);
Assert.AreEqual("The poor mutex was abandoned!", log.Message);
Assert.That(!string.IsNullOrEmpty(log.StackTrace));
Assert.AreEqual(1, log.NumOccurences);
Assert.AreEqual(now, log.FirstOccurrence); // <-- Compare now instead
Assert.AreEqual(now, log.LastOccurrence); // <-- Compare now instead
}
}
...
public class ExceptionLogger
{
public ExceptionLog LogException(Exception ex)
{
return LogException(ex, DateTime.Now);
}
public ExceptionLog LogException(Exception ex, DateTime timeOfException)
{
ExceptionLog log = new ExceptionLog();
log.ExceptionType = ex.GetType().ToString();
log.Message = ex.Message;
log.NumOccurences = 1;
log.StackTrace = ex.StackTrace;
log.FirstOccurrence = timeOfException; //Use the passed in value
log.LastOccurrence = timeOfException; //Use the passed in value
return log;
}
}
This solution is actually not too shabby. The test passes:
But it comes with two drawbacks:
- It's making the method signature more complex. People using ExceptionLogger might not be sure if they're required to pass in a datetime and what it should be.
- We're not actually testing that DateTime.Now is used as the timestamp in the default case.
Let's look at an alternative!
Let's face it, DateTime.Now is one of those things that gets called a lot and that you don't want to think about. The previous solution works well for a test this small but in more complex scenarios we probably have enough stuff to throw around that we don't want to complicate things further by passing confusing DateTime arguments that are not really needed.
To get complete control of time itself for unit testing here is a class I always create within two hours of joining a software project:
public class TimeWarper
{
private static DateTime? _now;
/// <summary>
/// TimeWarper.Now is a utility for getting the current time.
/// In production code it simply wraps DateTime.Now, but allows the current
/// DateTime to be overridden for unit testing purposes.
/// </summary>
public static DateTime Now
{
get
{
return _now ?? DateTime.Now;
}
set
{
_now = value;
}
}
}
This is a comon trick known as Wrap and Override.
You wrap the thing you want to fake in your unit test and override it with something under your control. In this case we just want to make time stand still so we can accurately measure it.
Here's how it looks if we use it in the example above:
[TestFixture]
public class ExceptionLoggerTests
{
private ExceptionLogger _exceptionLogger;
[SetUp]
public void SetUp()
{
TimeWarper.Now = DateTime.Now; //Freeze!
_exceptionLogger = new ExceptionLogger();
}
[Test]
public void TestLogException_LogsCorrectValues()
{
try
{
throw new AbandonedMutexException("The poor mutex was abandoned!");
}
catch (Exception ex)
{
// Log the exception
ExceptionLog log = _exceptionLogger.LogException(ex);
// Assert that the logged values are correct
Assert.AreEqual("System.Threading.AbandonedMutexException", log.ExceptionType);
Assert.AreEqual("The poor mutex was abandoned!", log.Message);
Assert.That(!string.IsNullOrEmpty(log.StackTrace));
Assert.AreEqual(1, log.NumOccurences);
Assert.AreEqual(TimeWarper.Now, log.FirstOccurrence); // <-- TimeWarper!
Assert.AreEqual(TimeWarper.Now, log.LastOccurrence); // <-- TimeWarper!
}
}
}
...
public class ExceptionLogger
{
public ExceptionLog LogException(Exception ex)
{
ExceptionLog log = new ExceptionLog();
log.ExceptionType = ex.GetType().ToString();
log.Message = ex.Message;
log.NumOccurences = 1;
log.StackTrace = ex.StackTrace;
log.FirstOccurrence = TimeWarper.Now; //Tada.wav!
log.LastOccurrence = TimeWarper.Now; //Tada.wav!
return log;
}
}
There you have it.
Freezing time for unit tests is a great way to make them simpler. You can deal with DateTimes as a value type rather than having to declare multiple variables. Simply refer to any unique point in time you want to set or compare against as TimeWarper.Now.AddMinutes(x)
