Kim Kullings Weblog

The idea

Unittests and integration-tests are a great tool not to break your code. They are building a safety-net to help you when you have to add a new feature or fixing a bug in an existing codebase.
But of course there will be situations when a bug will occur which was not covered by your test-suite. One way to get an understanding what went wrong are logfiles. You can use them to write a protocol what happened during runtime. When something useful ( like creating a new entry into a database ) happened you can write this information with a timestamp into your protocol. When a bug occurs like disk is full an error-entry will be created. And you can use it to log some internal states of your application. When the log-entries are well maintained they help you to get a better understanding what happened during a crash ( and of course what went wrong before ). And you can use them to post warnings like: be careful, this API-call is deprecated.
But do you watch your logs in your unit-tests and integration-tests? Maybe there are interesting information stored in them for a test-fixure which you should take care of as well. For instance when you declare an API-call as deprecated, but this call is still in use in a different sub-system it would be great to get this as an error in a unittest. Or when some kind of warning occurrs at some point of your log. We observed stuff like that in production code more than once. To take care of these situations we added a functionality called a log-filter: you can use it to define expected log-entries like an error which must occur in a test because you want to test the error behaviour. When unexpected entries are there the test will fail. So you will see in your tests what shall happen and what not.

Do some coding

Lets start with a simple logging service for an application:
My basic concept for a logging service looks like:
A logger is some kind of a service, so only one is there. Normally I am building a special kind of singleton to implement it ( yes I know, they are bad, shame on me ). You can create them on startup at the beginning. You shall destroy them at the end of the application ( last call before exit( 0 ) )
Log entries have different severities, for instance:
Debug: Internal states messages for debugging
Info: All useful messages
Warn: Warnings for the developer like “API-call deprecated”
Error: External errors like disk full or DAU-user-error
Fatal: An internal error has occurred caused by a bug
You can register log-streams to the logger, each logstream will write the protocol to a special output like a log-file or a window from the frontend.
In code this could look like:

class AbstractLogStream {
public:
  virtual ~AbstractLogStream();
  virtual void write( const std::string &message ) = 0;
};

class LoggingService {
public:
  // the entry severity
  enum class Severity {
    Debug,
    Info,
    Warn,
    Error,
    Fatal
  };
  static LoggingService &create();
  static void destroy();
  static LoggingService &getinstance();
  void registerStream( const AbstractLogStream &stream );
  void log( Severity sev, const std::string &message, 
    const std::string &file, unsigned int line );
  
private:
  static LoggingService *mInstance;
  LoggingService();
  ~LoggingService();
};

With this simple API you can create and destroy your log service, log messages of different severities and register your own log-streams.
Now we want to observer the entries during your unittests. A simple API to do this could look like:

class TestLogStream : public AbstractLogStream {
public:
  TestLogStream();
  ~TestLogStream();
  void write( const std::string &message ) override {
    TestLogFilter.getInstance().addLogEntry( message );
  }
};

class TestLogFilter {
public:
  static TestLogFilter &create();
  static void destroy();
  static TestLogFilter &getInstance();
  void addLogEntry( const std::string &message );
  void registerExpectedEntry( const std::string &message );
  bool hasUnexpectedLogs() const {
    for ( auto entry : m_messages) {
      std::vector::iterator it( std::find( m_expectedMessages.begin, m_expectedMessages.end(), entry );
      if ( it != m_expectedMessages.end() ) {
        return true;
      }
    }
    return false;
  }

private:
  TestLogFilter();
  ~TestLogFilter();

private:
  std::vector m_expectedMessages;
  std::vector m_messages;
};

The filter contains two string-arrays:
One contains all expected entries, which are allowed for the unittest
The other one contains all written log-entries, which were written by the TestLogStream during the test-fixure
Let’s try it out

You need to setup your testfilter before runnning your tests. You can use the registerExpectedEntry-method to add an expected entry during your test-execution.
Most unittest-frameworks support some kind of setup-callback mechanism before executing a bundle of tests. I prefer to use gtest. So you can create this singleton-class here:

#include <gtest/gtest.h>

class MyTest : public ::testing::test {
protected:
  virtual void SetUp() {
    LoggingService::create();
    TestLogFilter::create();
    LoggingService::getInstance().registerStream( new TestLogStream );
    TestLogFilter::getInstance().registerExpectedEntry( "Add your entry here!" );
  }

  virtual void TearDown() {
    TestLogFilter::destroy();
    EXPECT_FALSE( TestLogFilter::getInstance().hasUnexpectedLogs() );
    LoggingService::destroy();
  }
};

TEST_F( MyTest, do_a_test ) {
  ...
}

First you need to create the logging-service. In this example only the TestLogStream will be registered. Afterwards we will register one expected entry for the test-fixure.
When all tests have proceeded the teatDown-callback will check, if any unexpected log-entries were written.
So when unexpected entries were detected the test will be marked as a failure. Andy you can see if you forget to deal with any new behaviour.
What to do next

You can add more useful stuff like:
Add wildcards for expected og entries
Make this thread-safe