Practical Testing: 5 - Testing shouldn't be this hard

2004-05-25

I’m writing some blog entries that show how to write tests for non trivial pieces of code. This is part 5; the one where we find a bug we weren’t expecting…

[Update: Welcome to anyone who’s coming here from the link on Dans Data there’s actually a freely available program that DOES help you work with the TickCount rollover bug, it’s available on my site here.]

Last time I slipped an interface between our object under test and its source of time. This allowed us to provide a mock time source that we could control from within our test. This moved us nearer to being able to write the test we need to prove that the code doesn’t currently handle GetTickCount() wrapping to 0 after 49.7 days of machine up-time. I pointed out that the test was still not quite deterministic enough for me as the CCallbackTimer object’s timeout management thread was spinning in a way that we couldn’t control and so we couldn’t easily know reliably exactly what the test log from the mock time provider would contain.

We can fix this problem quite easily by allowing the mock time provider to provide time a certain number of times and then block. This will allow us to completely control the way the timeout management thread runs: We can set the time provider to supply time for 2 calls and then block and then wait for the time provider to process both calls and we then know that the timeout management thread is blocked within our time provider and that the objects are in a certain state. Often you don’t need this level of control within a test but it’s useful to know how to achieve it for those situations when you do.

The mock time provider can be called from 2 threads. The thread on which it was created; such as during a call to SetTimer() on the CCallbackTimer and the thread that the timer queue runs internally to manage timeouts. It’s only the internal thread that we want to control so we’ll take a note of the thread that the mock time provider is created on and allow all calls from that thread to work all of the time.

Next we’ll add an events, so that we can wait for the timer to be in a particular state, and a counter so that we can allow just a certain number of calls. For the counter we use a simple helper class, CWaitableCounter which implements a counter that manages a couple of events so that you can wait for the counter to reach zero, or wait for it to move away from zero. We also use a critical section because, even though we know that only one thread will be using the code path that we’re protecting in this test we may want to use the mock time provider in situations where multiple threads access it and it’s easier to add a critical section now than waste time trying to work out why it doesn’t work at a later date.

GetTickCount() now looks like this:

DWORD CMockTickCountProvider::GetTickCount() const
{
   if (m_mainThreadId != ::GetCurrentThreadId())
   {
      CCriticalSection::Owner lock(m_criticalSection);
  
      if (0 == m_counter.GetValue())
      {
         m_blockedCallEvent.Set();
      }
  
      m_counter.WaitForNonZero();
  
      m_blockedCallEvent.Reset();
  
      LogMessage(_T("GetTickCount: Another Thread: ") + ToString(m_tickCount));
  
      m_counter.Decrement();
   }
   else
   {
      LogMessage(_T("GetTickCount: Main Thread: ") + ToString(m_tickCount));
   }
  
   return m_tickCount;
}

It’s fairly complicated but that’s because we’re trying to test a piece of code that is fairly hard to test and we want a lot of control over the test environment… The function works like this; for calls that originate on a thread that isn’t the thread that the object was created on, if the counter is zero it sets and event to let us know that the call is about to block and then waits on the counter and, most likely, blocks. As soon as the wait returns (meaning the counter is not zero) it resets the ‘blocked’ event. The blocked event is used so that the test can wait for a call to block within the time provider. We use this to synchronise the test with the state of the timer queue thread. Next we update the test log and finally we decrement the counter and return the value.

This mock time provider allows us to selectively allow calls to occur, to wait for those calls to complete and to wait for a call to block. With this level of control we can write some tests that are more reliable; our first test now looks like this:

void CCallbackTimerTest::TestTimer()
{
//1
   const _tstring functionName = _T("CCallbackTimerTest::TestTimer");
  
   Output(functionName + _T(" - start"));
  
   CMockTickCountProvider tickProvider;
  
   tickProvider.SetTickCount(1000);
  
   CCallbackTimer timer(tickProvider);
  
   CMockTickCountProvider::AutoRelease releaser(tickProvider);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
//2
   CLoggingCallbackTimerHandleCallback callback;
  
   CCallbackTimer::Handle handle(callback);
  
   timer.SetTimer(handle, 100, 1);
  
   tickProvider.CheckResult(_T("|GetTickCount: Main Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
//3
   // Prove that time is standing still
   THROW_ON_FAILURE(functionName, false == callback.WaitForTimer(0));
  
   callback.CheckResult(_T("|"));
  
   tickProvider.SetTickCount(1100);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1100|"));
  
   THROW_ON_FAILURE(functionName, true == callback.WaitForTimer(s_delay));
  
   callback.CheckResult(_T("|OnTimer: 1|"));
  
   Output(functionName + _T(" - stop"));
}

The test does three things; the code between //1 and //2 sets up the environment for testing and gets the timer queue thread to a well known state (waiting for an infinite time or until the timer queue state changes). Between //2 and //3 we set a timer and allow the timer queue thread to spin once and then block. The timer queue thread would have retrieved a value for ’now’ of 1000, compared this to the first timeout to occur of 1100 and slept for 100ms before checking the time again, and blocking. After //3 we set ’now’ to 1100 so the timer will go off, allow the timer queue thread to run again so that it picks up the new time and signals the timer. The timer queue thread then goes back into an infinite wait and the test completes.

Note that we’ve added a helper class CMockTickCountProvider::AutoRelease to unblock the timer queue thread in the event of a test failure exception. Since the CCallbackTimer object is destroyed when an exception occurs and the thread inside it may be blocked the destruction will block as the object can’t shut its worker thread down. The AutoRelease object will get destroyed before the timer queue and its destructor sets the time provider to allow lots of calls; thus unblocking the timer queue.

Unfortunately we still rely on a hard coded timeout within the tests; s_delay is set to a value at the top of the test harness and used when we’re expecting an event to be set within a short period of time. If the tests are working correctly then s_delay could be set to INFINITE, however this would mean that test failure would cause the test to hang rather than actually fail. By setting s_delay to a smaller value we can force the test to fail by throwing an exception rather than hanging; this is better if the test is part of an automated build, but introduces a level of uncertainty. I find that setting it to 1000 seems to work fine for me whilst I’m developing tests, and 60000 removes any chance of false failure during automated test runs. Setting the value to INFINITE is useful if you want to debug into the test code and you don’t want your timeouts to go off and tear the test harness down around you.

The code above is ripe for refactoring, but we’ll leave that for later. First we’ll write some more tests in case the repeated structure that’s obvious in this test needs to change for other tests… Then we’ll refactor.

So, we have a test for a single timer, we should add tests for multiple timers and for cancelling timers before, and after, they expire. We can then add our test for the tick count wrap and any others that we think about.

The test for multiple timers is relatively easy to write. We can set several timers to go off at different times and then run the timer queue manually as we have done for the single timer and check that the timers go off at the right times and in the right order. Something like this:

void CCallbackTimerTest::TestMultipleTimers()
{
   const _tstring functionName = _T("CCallbackTimerTest::TestMultipleTimers");
  
   Output(functionName + _T(" - start"));
  
   CMockTickCountProvider tickProvider;
  
   tickProvider.SetTickCount(1000);
  
   CCallbackTimer timer(tickProvider);
  
   CMockTickCountProvider::AutoRelease releaser(tickProvider);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   CLoggingCallbackTimerHandleCallback callback1;
  
   CCallbackTimer::Handle handle1(callback1);
  
   timer.SetTimer(handle1, 100, 1);
  
   tickProvider.CheckResult(_T("|GetTickCount: Main Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
///
   CLoggingCallbackTimerHandleCallback callback2;
  
   CCallbackTimer::Handle handle2(callback2);
  
   timer.SetTimer(handle2, 200, 2);
  
   tickProvider.CheckResult(_T("|GetTickCount: Main Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
///
   CLoggingCallbackTimerHandleCallback callback3;
  
   CCallbackTimer::Handle handle3(callback3);
  
   timer.SetTimer(handle3, 150, 3);
  
   tickProvider.CheckResult(_T("|GetTickCount: Main Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
  
   CLoggingCallbackTimerHandleCallback callback4;
  
   CCallbackTimer::Handle handle4(callback4);
  
   timer.SetTimer(handle4, 150, 4);
  
   tickProvider.CheckResult(_T("|GetTickCount: Main Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1000|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
  
   // Prove that time is standing still
   THROW_ON_FAILURE(functionName, false == callback1.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback2.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback3.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback4.WaitForTimer(0));
  
   callback1.CheckResult(_T("|"));
   callback2.CheckResult(_T("|"));
   callback3.CheckResult(_T("|"));
   callback4.CheckResult(_T("|"));
  
   tickProvider.SetTickCount(1100);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1100|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
  
   THROW_ON_FAILURE(functionName, true  == callback1.WaitForTimer(s_delay));
   THROW_ON_FAILURE(functionName, false == callback2.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback3.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback4.WaitForTimer(0));
  
   callback1.CheckResult(_T("|OnTimer: 1|"));
   callback2.CheckResult(_T("|"));
   callback3.CheckResult(_T("|"));
   callback4.CheckResult(_T("|"));
  
   tickProvider.SetTickCount(1160);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1160|"));
  
   THROW_ON_FAILURE(functionName, true == tickProvider.WaitForBlockedCall(s_delay));
  
   THROW_ON_FAILURE(functionName, false == callback1.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback2.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, true  == callback3.WaitForTimer(s_delay));
   THROW_ON_FAILURE(functionName, true  == callback4.WaitForTimer(s_delay));
  
   callback1.CheckResult(_T("|"));
   callback2.CheckResult(_T("|"));
   callback3.CheckResult(_T("|OnTimer: 3|"));
   callback4.CheckResult(_T("|OnTimer: 4|"));
  
   tickProvider.SetTickCount(1201);
  
   THROW_ON_FAILURE(functionName, true == tickProvider.AllowCalls(1, s_delay));
  
   tickProvider.CheckResult(_T("|GetTickCount: Another Thread: 1201|"));
  
   // No more timers pending so the thread goes into an infinite wait until new timers are added.
  
   THROW_ON_FAILURE(functionName, false == callback1.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, true  == callback2.WaitForTimer(s_delay));
   THROW_ON_FAILURE(functionName, false == callback3.WaitForTimer(0));
   THROW_ON_FAILURE(functionName, false == callback4.WaitForTimer(0));
  
   callback1.CheckResult(_T("|"));
   callback2.CheckResult(_T("|OnTimer: 2|"));
   callback3.CheckResult(_T("|"));
   callback4.CheckResult(_T("|"));
  
   Output(functionName + _T(" - stop"));
}

Unfortunately running this test locates a bug in the code under test. The timer queue isn’t being maintained in lowest to highest order. Timers 3 and 4 are being inserted in the queue after timer 2 rather than before… This bug probably doesn’t show up in our current usage of the timer queue as all the timers tend to be set to very low values, but it’s definitely a bug. Looking at the code in question the debug Output statements give away the fact that I obviously had problems getting things to work here… Looks like I stopped before I actually fixed the problem :(

Anyway, in the best tradition of TDD, we have a failing test, so it’s OK to stop for a break… Code is here. Same rules as before.