A good friend and "former colleague in (an) archaic dev team" (his words :)) recently sent me a problem he was having testing some code he inherited. The code seemed to work during manual testing, but threw exceptions when being tested using NUnit under certain conditions. Let's look at a drastically modified example of the code:
[TestFixture]
public class BigImportantClassFixture {
[Test]
public void CanGetKnownEmployee() {
var existingEmployeeId = Guid.Empty
var importantClass = new BigImportantClass();
var employee = importantClass.GetEmployee(existingEmployeeId);
Assert.That(employee.Name, Is.EqualTo("Bilbo"));
}
}
public class BigImportantClass {
public Employee GetEmployee(Guid employeeID) {
Employee employee = EmployeeRepository.GetEmployeeByID(employeeID);
Logging.AsyncLog("Called GetEmployeeByID");
return employee;
}
}
public static class Logging {
public static void AsyncLog(string message) {
var thread = new Thread(Log);
thread.Start(message);
}
private static void Log(object message) {
//Write line to log. This op may take some time
Thread.Sleep(1000);
Console.WriteLine(message);
}
}
Can you guess the exception that cropped up? The unit test runner tears down the app domain it uses to run the fixtures when it is finished. Because the code spawns a new thread, this means that if that thread is still running it gets aborted as the app domain exits, so we get a ThreadAbortException. So how can we get this under test?
Questioning the approach
I think it would be remiss of us not to spend some time considering why we are using this approach. Is GetEmployee() called a lot and so needs to be fast? Will the added burden of spinning up another thread per call help, or will it hinder overall performance due to the increased load on the system? Would we be better off with a synchronous call? Do we even need logging here? Have we looked at using AOP for logging? Can libraries like log4net handle asynchronous logging for us? Or should we implement our own queue and have that serviced by threads that can work on processing the logs in batches? Should we be using background threads from the ThreadPool? Should we look at message queuing? Are static methods and opaque dependencies like this a work of pure evil? And if you were a tree, what tree would you be?
These are all good questions to ask and something my mate is looking into (I think he's leaning toward the larch). For the rest of this post however, I'd like to concentrate on how we could get this code under test. The code currently seems to work, but we don't have automated tests covering it, so we'll try and keep code changes small to give us confidence we aren't breaking anything during the process. This means we'll try and avoid changes ripping out the dependencies and using constructor injection. Once it's under test, we can worry about making it purdy and move on to more complex refactorings, and maybe even change the whole logging implementation once we decide which approach to use.
Isolating the logging behaviour in GetEmployee()
Our GetEmployee method does two things: looks up an Employee and does some logging. We already have the beginning of a test for the employee lookup part, but the coupling to the logging functionality is causing some problems. It is also untested. Let's write a test that isolates the behaviour.
[Test]
public void GetEmployeeCallIsLogged() {
var mockLogger = MockRepository.GenerateMock<ILogger>();
Logging.SetLogger(mockLogger);
var importantClass = new BigImportantClass();
importantClass.GetEmployee(Guid.Empty);
mockLogger.AssertWasCalled(mock => mock.AsyncLog(Arg<String>.Is.Anything));
}
Normally I'd look at constructor injection for this sort of thing, but we're aiming for minimal modifications to the original code. Logging is also a bit of a special case — you potentially need it everywhere and so you may not want to explicitly put ILogger objects into every single object you have.
To pass this test, we'll need to extract an ILogger interface from our static Logger class, and change the implementation to use a Singleton approach (so we can override the behaviour by changing the instance).
public interface ILogger {
void AsyncLog(string message);
}
public class Logging : ILogger {
private static ILogger instance = new Logging();
public static void SetLogger(ILogger logger) { instance = logger; }
public static void AsyncLog(string message) {
instance.AsyncLog(message);
}
private static void Log(object message) {
//Write line to log. This op may take some time
Thread.Sleep(1000);
Console.WriteLine(message);
}
void ILogger.AsyncLog(string message) {
var thread = new Thread(Log);
thread.Start(message);
}
}
This passes our test. Notice we've made virtually no changes to the pre-existing code and only a few minor additions. We've added a singleton instance and a trivial SetLogger() method, and moved the code previously in the static AsyncLog() method into the ILogger.AsyncLog() instance method, with the static methods delegating to the instance one. We haven't had to change the GetEmployee() method at all. Hopefully this means we haven't broken anything. A quick manual test verifies that everything is working as before.
I'm a bit worried that we might replace the singleton instance with something evil during one test and inadvertently cause another test to break, but I guess that's a price of using singletons. At this point we just want to get the code under test before we go trying to make it all purdy. On the positive side, we can now test the employee lookup functionality independently of the logging, including testing that GetEmployee() invokes the logging call as required.
An integration test for logging
We've isolated our logging behaviour and tested it is called correctly from GetEmployee(), which means we can now write a test to make sure our logging works when it is called.
[TestFixture]
public class LoggingFixture {
[Test]
public void AsyncLogShouldDoFunkyLoggingStuff() {
ILogger logging = new Logging();
logging.AsyncLog("some message");
Thread.Sleep(2000);
//AssertDesiredSideEffectOccurred();
}
}
Because of our previous efforts we can work directly with a Logging instance, rather than through the static methods. We still have a problem though. We want to check that whatever effect AsyncLog() has occurred properly, but because it is called asynchronously we have to put in a hacky Thread.Sleep() to make sure it is done. There are a few problems with this approach. Firstly, how do we know 2000 ms is enough? We might have our test intermittently breaking, which is a huge no-no. Secondly, it will make our tests run slow.
Isolating our threading problem
We'd really like the option of using Thread.Join() or similar so our test can wait on the asynchronous operation to finish. But we currently don't have any way to access the threading part of the operation.
One way to solve this problem is to implement the Asynchronous Programming Model. This lets the operation to be called asynchronously and waited on using polling/spin loop, call back or wait handle. Unfortunately it also looks like quite a lot of work, and a large amount of change to make without tests.
Another possible solution is to isolate the threading behaviour from the logging operation, just as we did for separating the employee lookup from the logging. Let's try that — we'll write a class that specialises in running a function in a new thread.
[TestFixture]
public class ThreadDispatcherFixture {
[Test]
public void CanRunFunctionCall() {
var dispatcher = new ThreadDispatcher();
bool wasRun = false;
dispatcher.Dispach(() => wasRun = true);
Assert.That(wasRun);
}
}
public class ThreadDispatcher {
public void Dispach(Action function) {
function();
}
}
This passes. Let's expand our test fixture, and try a naive implementation:
[Test]
public void RunsFunctionFromDifferentThread() {
var dispatcher = new ThreadDispatcher();
int callingThreadId = Thread.CurrentThread.ManagedThreadId;
int dispatchedThreadId = -1;
dispatcher.Dispach(() => dispatchedThreadId = Thread.CurrentThread.ManagedThreadId);
Assert.That(dispatchedThreadId, Is.Not.EqualTo(callingThreadId));
}
//...
public class ThreadDispatcher {
public void Dispach(Action function) {
var thread = new Thread(() => function());
thread.Start();
}
}
This passes the new RunsFunctionFromDifferentThread() test, but luckily fails the original CanRunFuctionCall() test when run on my machine. I say luckily because it is timing dependent — the thread has not completed by the time the Assert.That(wasRun) executes. If you slip in a Thread.Sleep(...) for a few milliseconds you'll see both tests pass as the async thread starts to win our race condition.
This is a really good illustration that test coverage does not equal correctness, nor is it an excuse to avoid thinking :). Given we've thought about the problem though, TDD can help lead us to a solution. We need to make sure our async thread has run before we call our assert, so let's ammend our tests to show this:
[Test]
public void CanRunFunctionCall() {
var dispatcher = new ThreadDispatcher();
bool wasRun = false;
var dispatchedThread = dispatcher.Dispach(() => wasRun = true);
dispatchedThread.Join();
Assert.That(wasRun);
}
[Test]
public void RunsFunctionFromDifferentThread() {
var dispatcher = new ThreadDispatcher();
int callingThreadId = Thread.CurrentThread.ManagedThreadId;
int dispatchedThreadId = callingThreadId;
var dispatchedThread = dispatcher.Dispach(() => dispatchedThreadId = Thread.CurrentThread.ManagedThreadId);
dispatchedThread.Join();
Assert.That(dispatchedThreadId, Is.Not.EqualTo(callingThreadId));
}
And a reliably passing implementation (I hope):
public Thread Dispach(Action function) {
var thread = new Thread(() => function());
thread.Start();
return thread;
}
It may not be a good idea to pass a reference to the Thread back, so it might be neater to wrap the Join() functionality in a new class (with tests updated accordingly).
public class ThreadDispatcher {
public AsyncCall Dispach(Action function) {
var thread = new Thread(() => function());
thread.Start();
return new AsyncCall(thread);
}
}
public class AsyncCall {
private readonly Thread _thread;
public AsyncCall(Thread thread) { _thread = thread; }
public void WaitUntilCallFinishes() { _thread.Join(); }
}
This is all new code, so we shouldn't have broken anything that was working in our original implementation.
Bringing logging and threading back together
Now we've separated logging and threading, we need to bring them back together so this thing actually works as required. Let's jump into our LoggingFixture:
[TestFixture]
public class LoggingFixture {
[Test]
public void AsyncLogShouldDoFunkyLoggingStuff() {
ILogger logging = new Logging(new ThreadDispatcher());
logging.AsyncLog("some message");
Thread.Sleep(2000);
//AssertDesiredSideEffectOccurred();
}
[Test]
public void AsyncLogShouldUseThreadDispatcher() {
var dispatcher = MockRepository.GenerateMock<ThreadDispatcher>();
ILogger logging = new Logging(dispatcher);
logging.AsyncLog("some message");
dispatcher.AssertWasCalled(x => x.Dispach(null), options => options.IgnoreArguments());
}
}
public class Logging : ILogger {
private readonly ThreadDispatcher dispatcher;
private static ILogger instance = new Logging(new ThreadDispatcher());
public Logging(ThreadDispatcher dispatcher) { this.dispatcher = dispatcher; }
public static void SetLogger(ILogger logger) { instance = logger; }
public static void AsyncLog(string message) {
instance.AsyncLog(message);
}
private static void Log(object message) {
//Write line to log. This op may take some time
Thread.Sleep(1000);
Console.WriteLine(message);
}
void ILogger.AsyncLog(string message) {
dispatcher.Dispach(() => Log(message));
}
}
This has probably been the most radical change to our code. We've changed the implementation of AsyncLog to delegate the threading to our new ThreadDispatcher. We've also added some dependency injection, using the Logging constructor to pass in our ThreadDispatcher. Everything is green. Even better, we can now update the original AsyncLogShouldDoFunkyLoggingStuff() and test the logging behaviour in isolation.
[TestFixture]
public class LoggingFixture {
private class FakeThreadDispatcher : ThreadDispatcher {
public override AsyncCall Dispach(Action function) {
function();
return new AsyncCall(null);
}
}
[Test]
public void AsyncLogShouldDoFunkyLoggingStuff() {
ILogger logging = new Logging(new FakeThreadDispatcher());
logging.AsyncLog("some message");
//No more Thread.Sleep(...) here. Our FakeThreadDispatcher will do a synchronous call.
//AssertDesiredSideEffectOccurred();
}
//...
}
You could also do some fancy mockFu for this, but in this case I think it's easier to hand code a FakeThreadDispatcher (if changes to the base class cascade down to our fake and it starts getting painful we can switch a generated mock or stub).
Conclusion
Our Logging implementation only calls Console.WriteLine(), so for our AssertDesiredSideEffectOccurred() we would need to fake that out. We won't go that far down the rabbit hole though, as the real logging implementation would be probably do all kinds of exciting things that we could test. The point is that we can now test the logging in isolation from our threading. Our threading code is also tested, and we can test our original employee look up too (by setting a stub ILogger when testing BigImportantClass).
Best of all, the only really changes of any consequence we made to our original code is implementing a singleton Logging instance and extracting the thread launching code to a new class. So, from a unit testing point of view, we have gained a lot for very little risk.
This was a very simple bunch of refactorings to perform. I hope that came across during the post, but sometimes these things don't translate well to post format. If that's the case then try picking up the code from the start of this post and go through the process of getting it under test.
As always feel free to pick holes in this post and let me know via comment or email. Hope this helps!
