Won't someone please think of the users?

Test driven development can be used to better focus on the user needs. In this article, I design a small logger library in C++ as an example of user-oriented, test-driven development.

Test Driven Development is a software design technique in which tests for a desired new software are written before the software itself. The name is technically accurate, but a bit dull: it hides the very important facts that the tests we write are the first users of our code. Hence, as we’re writing them, we’re putting ourselves in the shoes of whoever will it. That may be a customer paying to access a commercially available SDK, a colleague that will extend our code down the line, or our future selves. For this reason, I prefer thinking of TDD as user driven development.

The concept of Behaviour Driven Development was introduced exactly to clarify this point, but continuing the tradition of getting names just slightly off we IT guys are so fond of, even the term “BDD” is shy of telling the whole truth about how central users are, or should be.

In this article, I’ll go through the thought process I call Iterative Test Driven Development, and show how considering the point of view of the user flows naturally into designing unit test in the earliest stage of software development.

I don’t always do TDD&

TDD purists recommend actually starting from writing the actual test first, and then the program that will make the test to pass, in a bottom-top approach where the test is the “bottom”, the basic the solution of the problem from which to climb up to a solving algorithm.

That is a very good advice, especially if you want to hammer the habit of writing tons of untestable code out of junior developers. But if you have been in this industry for some time, you may have already achieved a basic sensitivity for how a good interface may look like.

I find no sin in starting from a very simple, skeleton implementation of the code to be developed, provided that’s done with the objective to write something ready to be used in a unit test, following a top-down-top, iterative approach.

That’s also a way to beat the “blank page” syndrome, the lack of creative input that may paralyse a developer when attacking a large problem without any previous work to extend on.

Last but not least, this procedure may also help more senior developers entering the habit of working regularly with TDD, and seem “less radical”, while being just as effective.

A simple logging system

Every non-trivial application requires a logging system. This is the perfect example of code to be written with a central attention to the user: while it’s vital that a log system is internally efficient, it’s greatest value lies in how simple is for the users to integrate it in their application. A well designed logger API can encourage good logging practices; a badly written one can lead to developers trying to avoid logging as much as possible. For this reason, it’s crucial to design its interface with the comfort of the user as a primary concern.

Note: for this example, I will use C++ and GTEST, but I will skip all the language-specific details besides the actual necessary code.

If I were a user&

As you code, keep this question at the forefront of your mind; print it and stick it below the monitor if it helps:

If I were a user of this code I am writing, how would I like to use it?

For this example, we’re the writer/user of a logging system. There are many way to expose the concept of a “system” in C++, but the simplest way is using a singleton:

class Logger {
public:
  static Logger& instance()
    static Logger logger;
    return logger;
  }

  // ... More to come ...
};

#ifndef LOG
#define LOG (Logger::instance())
#endif

The #define is syntactic sugar, because we don’t really want to write Logger::instance() every time we want to log a new message. There are other ways to achieve the same effect, but for the time being this will do.

Now, if I were a user, what would I want to do with the logger? Certainly, first of all, log a message tagged with a certain priority level, which should be an enumerated value out of a few reasonable possibilities, from critical down to trace or with some debug scaling as debug_0, debug_1 and so on. For this example, it will be:

    typedef enum {
        ERROR,
        INFO,
        DEBUG
    } t_log_level;

    void log(t_log_level level, const std::string& message) {}

Of course, I would also want to be able to limit what is actually logged; for example, I may want to strip debug information out of a program running in production.

void setLogLevel(t_log_level level) {}

And then, I need somewhere to send our logs to; that would be a listener, or to save some typing, a channel. Of course, I also need a way to link the channel to the logger, so that it can actually receive the messages.

   class Channel {
      public:
        virtual ~Channel() = default;
        virtual void onMessage(t_log_level level, const std::string& message) = 0;
    };

    using ChannelPtr = std::shared_ptr<Channel>;
    void addChannel(ChannelPtr channel);

And this is the minimal code for me to see something happening. I can now expect to log a message and having it repeated to all listening channels, if its priority is high enough, or ignored otherwise.

Since I, as user, can now expect something out of this code, this is a good time to start writing a test.

Our test will need a somewhat self-aware channel to receive the messages the logger wants to distribute. A minimal implementation with GTEST may look like:

struct TestChannel: public Logger::Channel {
    int m_messageCount{0};

    virtual ~TestChannel() = default;
    virtual void onMessage(Logger::t_log_level level, const std::string& message) {
        m_messageCount++;
    }
};

We may use GMOCK for this, but for the sake of this example, it would be like shooting a fly with a cannon& from a battleship.

Now, we’ll need to check that the message is replicated when the log level is set to equal or less (higher priority) than the logged message, and we have just a few levels to test. This suggest using a parametrised test, so to avoid replicating test code many times over. A tuple will hold the values to be used as logger level, message level and expected result.

using BaseTestData = std::tuple<Logger::t_log_level, Logger::t_log_level, int>;
struct BaseTest: testing::TestWithParam<BaseTestData> {};

TEST_P(BaseTest, properFilter) {
    // Should receive a message if logLevel <= msgLevel (lower level = higher priority)
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channel = std::make_shared<TestChannel>();
    LOG.addChannel(channel);
    LOG.setLogLevel(logLevel);
    LOG.log(msgLevel, "A Message");
    ASSERT_EQ(channel->m_messageCount, expect);
}

Finally, we can give a pretty large list of parameters to try out; as we have just three levels, it’s easy to use them all:

INSTANTIATE_TEST_SUITE_P(SimpleLogs, BaseTest,
    testing::Values(
        BaseTestData{Logger::DEBUG, Logger::DEBUG, 1},
        BaseTestData{Logger::DEBUG, Logger::INFO, 1},
        BaseTestData{Logger::DEBUG, Logger::ERROR, 1},
        BaseTestData{Logger::INFO, Logger::INFO, 1},
        BaseTestData{Logger::INFO, Logger::ERROR, 1},
        BaseTestData{Logger::ERROR, Logger::ERROR, 1},
        BaseTestData{Logger::INFO, Logger::DEBUG, 0},
        BaseTestData{Logger::ERROR, Logger::INFO, 0},
        BaseTestData{Logger::ERROR, Logger::DEBUG, 0}
));

This test compiles, but all the expectations fail; that’s because we actually didn’t write any code for the logger to work. Let’s fix this; we just need a variable where to record the desired log level and a list of active channels on which to broadcast the message.

private:
    t_log_level m_logLevel{DEBUG};
    std::list<ChannelPtr> m_channels;

public:
    void setLogLevel(t_log_level level) {
        m_logLevel = level;
    }

    void addChannel(ChannelPtr channel) {
        m_channels.push_back(channel);
    }

    void log(t_log_level level, const std::string& message) {
        if(level > m_logLevel) {
            return;
        }

        for(auto& channel: m_channels) {
            channel->onMessage(level, message);
        }
    }

And the result is:

[ PASSED ] 9 tests.

To provide a more complete test, it would be necessary to add a check on the actual value of the message to be what expected; but we’ll leave that for an exercise to the reader.

A better logger

Now it would be nice if I could declare a log level not just for the whole logger, but also for the specific log channels; so, I could direct informational logs to the console, debug logs to a file and error logs to a specific device that would immediately raise an alert (e.g. stderr).

The desired log level is specific of a given channel, and it would seem natural to encapsulate it where it belongs to, as a part of the Channel class, but, as a user, I’d rather keep it as a pure interface (it’s more flexible, and there are less requirements to care about). So, we’ll record the channel log level separately.

Instead of a list of channels, the log system will hold a list of channel information where to store the pointer to the concrete channel and all the additional necessary information; for now, just the log level.

 struct ChannelInfo {
      t_log_level m_logLevel{DEBUG};
      ChannelPtr m_channel;
  };
  std::list<ChannelInfo> m_channels;

I want to be able to declare a channel having a certain log level, so it can ignore any message of lower priority. That can be done so easily that we can even venture writing a bit of trivial code before testing it  after all, it’s just an extension of what’s already under test:

    void addChannel(t_log_level level, ChannelPtr channel) {
        m_channels.push_back(ChannelInfo{level, channel});
    }

    void log(t_log_level level, const std::string& message) {
        if(level > m_logLevel) {
            return;
        }

        for(auto& cinfo: m_channels) {
            if(level <= cinfo.m_logLevel) {
                cinfo.m_channel->onMessage(level, message);
            }
        }
    }

See the changes in lines 2 and 11.

Let’s review the test; I expect it to behave exactly the same if I just declare the channel as listening to the lowest priority possible. See the change on line 5:

TEST_P(BaseTest, properFilter) {
    // Should receive a message if logLevel <= msgLevel (lower level = higher priority)
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channel = std::make_shared<TestChannel>();
    LOG.addChannel(Logger::DEBUG, channel);
    LOG.setLogLevel(logLevel);
    LOG.log(msgLevel, "A Message");
    ASSERT_EQ(channel->m_messageCount, expect);
}

Indeed, recompiling and running the test proves that I didn’t break any previous expectations. But, I have a new one: the log level should prevent undesired messages to be broadcast on higher priority channles, allowing the lower ones to proceed.

TEST_P(BaseTest, channelLevelFilter) {
    // Should receive a message if logLevel <= msgLevel (lower level = higher priority)
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channelBase = std::make_shared<TestChannel>();
    auto channelFiltered = std::make_shared<TestChannel>();
    LOG.addChannel(Logger::DEBUG, channelBase);
    LOG.addChannel(logLevel, channelFiltered);
    LOG.setLogLevel(Logger::DEBUG);
    LOG.log(msgLevel, "A Message");
    ASSERT_EQ(channelBase->m_messageCount, 1);
    ASSERT_EQ(channelFiltered->m_messageCount, expect);
}

Here the general logger and a reference channelBase have the log level set to DEBUG, which means channelBase should always receive all the logs. The channelFiltered should only receive the expected logs, which are the same as before. Running this test as part of the same suite feeds the same test data and expects the same results; indeed the result is:

[ PASSED ] 18 tests.

An Even Better Logger

Being able to set the log level at channel creation is good. However, at times I would like to change the level at runtime, or programmatically, to get more detailed debug information when I see a problem happening.

The new interface comes out naturally by simply writing my requirement down as code: “I want to be able to assign a different log level to a channel”.

void setChannelLevel(t_log_level level, ChannelPtr channel) {}

Another “natural” choice for this purpose would be that of adding a method to the channel interface, but then we’d have to either lose the pure interface quality of the Channel declaration, or write some glue code in every implementation.

Now, how is this expected to work? I would expect that, after reducing the log level on a channel, messages previously dropped get actually logged; I would also expect that changing the level on one channel won’t affect the others. Let’s write down this test:

TEST_P(BaseTest, channelChangeLevel) {
    // Should receive messages when dropping the channel log priority
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channelCatchAll = std::make_shared<TestChannel>();
    auto channelCatchErrorOnly = std::make_shared<TestChannel>();
    auto channelFiltered = std::make_shared<TestChannel>();
    // Keep a reference channels around.
    LOG.addChannel(Logger::DEBUG, channelCatchAll);
    LOG.addChannel(Logger::ERROR, channelCatchErrorOnly);
    // Create a channel at highest priority possible.
    LOG.addChannel(Logger::ERROR, channelFiltered);
    // Eventually decrease the level to the desired value.
    LOG.setChannelLevel(logLevel, channelFiltered);

    LOG.setLogLevel(Logger::DEBUG);
    LOG.log(msgLevel, "A Message");

    int isErrorLevel = msgLevel == Logger::ERROR ? 1 : 0;
    ASSERT_EQ(channelCatchErrorOnly->m_messageCount, isErrorLevel);
    ASSERT_EQ(channelCatchAll->m_messageCount, 1);
    ASSERT_EQ(channelFiltered->m_messageCount, expect);
}

Of course, if we run this test now we expect it to fail, as setChannelLevel currently does nothing; but once the method is filled with a little search-and-change loop, everything should work as expected:

    void setChannelLevel(t_log_level level, ChannelPtr channel) {
        for(auto& chinfo: m_channels) {
            if(chinfo.m_channel.get() == channel.get()) {
                chinfo.m_logLevel = level;
                break;
            }
        }
    }

And indeed, the result is now:

[ PASSED ] 27 tests.

Conclusions

This is a very basic example of a software development technique I call Iterative Test Driven Development, where the coding starts from a simple interface, nothing more than the description of the required functionality written down as code, and tests are written immediately after.

However, I’d like to focus the attention of the reader not on the mechanical process of writing an interface, some tests and then go back and write the implemenation_,_ but on the creative process at its base.

The spirit of the technique consists in acting as the users of our own code, so to better appreciate a their need. In this process, the tests are not to be seen (only) as hammers meant to break a less-than-perfect implementation, but as a minimal, self contained example user code.

In this way, we’ll put ourselves in the shoes of the users, and this will ultimately lead to writing simple, effective and user-friendly code.

The whole code

Here follows the complete working example, in C++17.

#include <gtest/gtest.h>

#include <list>
#include <memory>
#include <string>
#include <tuple>

class Logger {
public:
    static Logger& instance() {
        static Logger logger;
        return logger;
    }

    typedef enum {
        ERROR,
        INFO,
        DEBUG
    } t_log_level;

    class Channel {
    public:
        virtual ~Channel() = default;
        virtual void onMessage(t_log_level level, const std::string& message) = 0;
    };

    using ChannelPtr = std::shared_ptr<Channel>;

private:
    t_log_level m_logLevel{DEBUG};

    struct ChannelInfo {
        t_log_level m_logLevel{DEBUG};
        ChannelPtr m_channel;
    };
    std::list<ChannelInfo> m_channels;

public:
    void setLogLevel(t_log_level level) {
        m_logLevel = level;
    }

    void addChannel(t_log_level level, ChannelPtr channel) {
        m_channels.push_back(ChannelInfo{level, channel});
    }

    void setChannelLevel(t_log_level level, ChannelPtr channel) {
        for(auto& chinfo: m_channels) {
            if(chinfo.m_channel.get() == channel.get()) {
                chinfo.m_logLevel = level;
                break;
            }
        }
    }

    void log(t_log_level level, const std::string& message) {
        if(level > m_logLevel) {
            return;
        }

        for(auto& cinfo: m_channels) {
            if(level <= cinfo.m_logLevel) {
                cinfo.m_channel->onMessage(level, message);
            }
        }
    }
};

#ifndef LOG
#define LOG (Logger::instance())
#endif

//=============================================================


struct TestChannel: public Logger::Channel {
    int m_messageCount{0};

    virtual ~TestChannel() = default;
    virtual void onMessage(Logger::t_log_level level, const std::string& message) {
        m_messageCount++;
    }
};

using BaseTestData = std::tuple<Logger::t_log_level, Logger::t_log_level, int>;
struct BaseTest: testing::TestWithParam<BaseTestData> {};

TEST_P(BaseTest, properFilter) {
    // Should receive a message if logLevel <= msgLevel (lower level = higher priority)
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channel = std::make_shared<TestChannel>();
    LOG.addChannel(Logger::DEBUG, channel);
    LOG.setLogLevel(logLevel);
    LOG.log(msgLevel, "A Message");
    ASSERT_EQ(channel->m_messageCount, expect);
}

TEST_P(BaseTest, channelLevelFilter) {
    // Should receive a message if logLevel <= msgLevel (lower level = higher priority)
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channelBase = std::make_shared<TestChannel>();
    auto channelFiltered = std::make_shared<TestChannel>();
    LOG.addChannel(Logger::DEBUG, channelBase);
    LOG.addChannel(logLevel, channelFiltered);
    LOG.setLogLevel(Logger::DEBUG);
    LOG.log(msgLevel, "A Message");
    ASSERT_EQ(channelBase->m_messageCount, 1);
    ASSERT_EQ(channelFiltered->m_messageCount, expect);
}

TEST_P(BaseTest, channelChangeLevel) {
    // Should receive messages when dropping the channel log priority
    auto [logLevel, msgLevel, expect] = GetParam();
    auto channelCatchAll = std::make_shared<TestChannel>();
    auto channelCatchErrorOnly = std::make_shared<TestChannel>();
    auto channelFiltered = std::make_shared<TestChannel>();
    // Keep a reference channels around.
    LOG.addChannel(Logger::DEBUG, channelCatchAll);
    LOG.addChannel(Logger::ERROR, channelCatchErrorOnly);
    // Create a channel at highest priority possible.
    LOG.addChannel(Logger::ERROR, channelFiltered);
    // Eventually decrease the level to the desired value.
    LOG.setChannelLevel(logLevel, channelFiltered);

    LOG.setLogLevel(Logger::DEBUG);
    LOG.log(msgLevel, "A Message");

    int isErrorLevel = msgLevel == Logger::ERROR ? 1 : 0;
    ASSERT_EQ(channelCatchErrorOnly->m_messageCount, isErrorLevel);
    ASSERT_EQ(channelCatchAll->m_messageCount, 1);
    ASSERT_EQ(channelFiltered->m_messageCount, expect);
}

INSTANTIATE_TEST_SUITE_P(SimpleLogs, BaseTest,
    testing::Values(
        BaseTestData{Logger::DEBUG, Logger::DEBUG, 1},
        BaseTestData{Logger::DEBUG, Logger::INFO, 1},
        BaseTestData{Logger::DEBUG, Logger::ERROR, 1},
        BaseTestData{Logger::INFO, Logger::INFO, 1},
        BaseTestData{Logger::INFO, Logger::ERROR, 1},
        BaseTestData{Logger::ERROR, Logger::ERROR, 1},
        BaseTestData{Logger::INFO, Logger::DEBUG, 0},
        BaseTestData{Logger::ERROR, Logger::INFO, 0},
        BaseTestData{Logger::ERROR, Logger::DEBUG, 0}
));