10
The TDD Process in Depth
We’re going to add a lot of code to the logging library in this chapter, and while that’s good, it’s not the main purpose of the chapter.
This is a chapter about the test-driven development (TDD) process. Wasn’t Chapter 3 also about the TDD process? Yes, but think of the earlier chapter as an introduction. This chapter will explore the TDD process in detail with a lot more code.
You’ll get ideas for writing your own tests, how to figure out what’s important, and how to refactor code without rewriting tests too, and you’ll also learn when testing is too much and learn about many different types of tests.
The basic TDD process remains as follows:
- To write tests first that use the software in a natural and intuitive way
- To get the code building with minimal changes even if we need to provide fake or stubbed-out implementations
- To get basic scenarios working
- To write more tests and enhance the design
Along the way, we’ll add log levels, tags, and filtering to the logging library.
Specifically, we’ll cover the following main topics in this chapter:
- Finding gaps in the testing
- Adding log levels
- Adding default tag values
- Exploring filtering options
- Adding new tag types
- Refactoring the tag design with TDD
- Designing tests to filter log messages
- Controlling what gets logged
- Enhancing filtering for relative matches
- When is testing too much?
- How intrusive should tests be?
- Where do integration or system tests go in TDD?
- What about other types of tests?
Technical requirements
All code in this chapter uses standard C++ that builds on any modern C++ 20 or later compiler and standard library. The code uses the testing library from Part 1 of this book, Testing MVP, and continues the development of a logging library started in the previous chapter.
You can find all the code for this chapter in the following GitHub repository:
https://github.com/PacktPublishing/Test-Driven-Development-with-CPP
Finding gaps in the testing
We really need more tests. Right now, we only have two logging tests: one for simple log messages and the other for more complicated log messages. The two tests look like this:
TEST("Simple message can be logged"){ std::string message = "simple "; message += Util::randomString(); MereMemo::log() << message << " with more text."; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}TEST("Complicated message can be logged"){ std::string message = "complicated "; message += Util::randomString(); MereMemo::log() << message << " double=" << 3.14 << " quoted=" << std::quoted("in quotes"); bool result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}But is there a good way to find more tests? Let’s look at what we have so far. I like to start with simple tests. Can things be constructed?
That’s why the two tests we have so far are in a file called Contruction.cpp. This is a good place to start when looking for gaps in your testing. Do you have a simple test for each thing that you can construct? Normally, these will be classes. Write a test for each constructor of each class that your project provides.
For the logging library, we don’t have any classes yet. So instead, I created a simple test that calls the log function. Then, another test calls the same function in a slightly more complicated way.
There is an argument to be made that the complicated test duplicates some of the functionality of the simple test. I think what we have so far is okay, but it is something you should be aware of to avoid having a test that does everything another test does plus a little more. As long as a simple test represents a common use case, then it’s valuable to include it, even if another test might do something similar. In general, you want tests that will capture how your code will be used.
Other things to think about when looking for gaps in your testing can be found by looking for symmetry. If you have construction tests, maybe you should consider destruction tests. We don’t have anything like that for the logging library—at least, not yet—but it is something to consider. Another example of symmetry can be found later in this chapter. We’ll need to confirm that some text exists in a file. Why not include a similar test that makes sure some different text does not exist in the file?
Major features are a good source for tests. Think about which problems your code solves and write tests that exercise each feature or capability. For each feature, create a simple or common test, and then consider adding a more complicated test, some error tests that explore what can go wrong, and some tests that explore more purposeful misuses to make sure your code handles everything as expected. You’ll even see one example in the next section where a test is added just to make sure that it compiles.
This chapter will mostly explore tests for missing features. We’re just getting started with the logging library, so the majority of new tests will be based on new features. This is common for a new project and is a great way to let the tests drive the development.
The next section will add a new feature by first creating tests to define the feature.
Adding log levels
Logging libraries have a common idea of log levels that let you control how much information gets logged when an application is run. Let’s say you identify an error condition that needs a log message. This error should almost always be logged, but maybe there’s another place in the code where you decide that it might be useful to record what is happening. This other place is not always interesting, so it would be nice to avoid seeing those log messages all the time.
By having different log levels, you can decide how verbose your log files become. There are a couple of big problems with this approach. The first thing is simply defining what the log levels should be and what each should mean. Common log levels include errors, warnings, general informational messages, and debugging messages.
Errors tend to be easy to identify unless you also want to split them into normal errors and critical errors. What makes an error critical? Do you even need to tell the difference? In order to support as many different customers as possible, a lot of logging libraries provide different log levels and leave it up to the programmer to figure out what each level means.
The logging levels end up being used primarily to control how much information gets logged, which can help reduce the size of the log files when the application is running without any problems or complaints. This is a good thing but it leads to the next big problem. When something needs further investigation, the only way to get more information is to change the logging level, rerun the application, and hope to catch the issue again.
For large applications, changing the logging level to record more information can quickly cause so much extra information that it becomes difficult to find what you need. The additional log messages can also fill up storage drives and cause extra financial charges if the log files are sent to vendors for further processing. The debugging process is usually rushed so that the new logging level is in effect for a short period of time.
To get around the need to change the logging level for the entire application, a common practice is to temporarily change the level that specific parts of the code use when logging information. This requires that an application be rebuilt, deployed, and then put back once the problem is found.
How does all this discussion about logging levels help us design a logging library? We know who our target customer is: a microservice developer who will likely be working with large applications that can produce large log files. Thinking about what would help your customer the most is a great way to create a design.
We’re going to fix the two big problems identified. First, we’re not going to define any logging levels in the logging library. There will not be any notion of an error log message versus a debug log message. This doesn’t mean that there will be no way to control how much information will get logged, just that the whole idea of using log levels is fundamentally broken. The levels themselves are too confusing, and turning them on and off leads quickly to information overload and rushed debugging sessions.
The idea of adding extra information such as a log level to a log message is good. If we come up with a general-purpose solution that can work for log levels as well as other attached information, then we can let the user add whatever is needed and makes sense. We can provide the ability to add log levels without actually defining what those levels will be and what they mean.
So, the first part of the solution will be a general-purpose tagging system. This should avoid the confusion of fixed log levels that are defined by the library. We’ll still refer to the idea of a log level, but that’s only because the idea is so common. However, our log levels will be more like log-level tags because there won’t be any idea of one log level being above or below another log level.
The second part will need something new. The ability to control whether a message is logged or not based on the value of a log-level tag will just lead to the same problem as before. Turning a log level on will end up opening the logs everywhere and still lead to a flood of extra log messages. What we need is the ability to finely control what gets logged instead of turning extra logging on or off everywhere. We’ll need the ability to filter on more than just a log level.
Let’s take these two ideas one at a time. What would a general tagging system look like? Let’s write a test to find out! We should create a new file called Tags.cpp in the tests folder that looks like this:
#include "../Log.h"#include "LogTags.h"#include "Util.h"#include <MereTDD/Test.h>TEST("Message can be tagged in log"){ std::string message = "simple tag "; message += Util::randomString(); MereMemo::log(error) << message; std::string taggedMessage = " log_level="error" "; taggedMessage += message; bool result = Util::isTextInFile(taggedMessage, "application.log"); CONFIRM_TRUE(result);}The most important part of this test is the log function call. We want this to be easy to use and to quickly convey to anybody reading the code that a tag is involved. We don’t want the tag to get hidden in the message. It should stand out as different and at the same time not be awkward to use.
The confirmation is a little more complicated. We want the output in the log file to use a key="value" format. This means that there is some text followed by an equals sign and then more text inside quotation marks. This format will let us easily find tags by looking for something like this:
key="value"For the log level, we’ll expect the output to look like this:
log_level="error"We also want to avoid mistakes such as spelling or differences in capitalization. That’s why the syntax doesn’t use a string, which could be mistyped like this:
MereMemo::log("Eror") << message;By avoiding strings, we can get the compiler to help make sure that tags are consistent. Any mistake should result in a compilation error instead of a malformed tag in the log file.
And because the solution uses a function argument, we don’t need to provide special forms of log such as logError, logInfo, or logDebug. One of our goals was to avoid defining specific logging levels in the library itself and instead come up with something that will let the user decide what the log levels will be, just like any other tag.
This is also the reason for the extra include of LogTags.h, which is also a new file. This is where we will define which log levels we will use. We want the definition to be as simple as possible because the log library will not define these. The LogTags.h file should be placed in the tests folder and look like this:
#ifndef MEREMEMO_TESTS_LOGTAGS_H#define MEREMEMO_TESTS_LOGTAGS_H#include "../Log.h"inline MereMemo::LogLevel error("error");inline MereMemo::LogLevel info("info");inline MereMemo::LogLevel debug("debug");#endif // MEREMEMO_TESTS_LOGTAGS_HJust because the logging library doesn’t define its own logging levels doesn’t mean it can’t help with this common task. We can make use of a helper class that the library will define called LogLevel. We include Log.h in order to gain access to the LogLevel class so that we can define instances. Each instance should have a name such as error that we will use when logging. The constructor also needs a string to be used in the logging output. It’s probably a good idea to use a string that matches the name of the instance. So, for example, the error instance gets an "error" string.
It’s these instances that get passed to the log function, like this:
MereMemo::log(error) << message;One thing to note is the namespace of the LogLevel instances. Because we’re testing the logging library itself, we’ll be calling log from within tests. Each test body is actually part of the run method of a test class defined with one of the TEST macros. The test class itself is in an unnamed namespace. I wanted to avoid needing to specify the MereMemo namespace when using one of the log levels, like this:
MereMemo::log(MereMemo::error) << message;It’s much easier to type just error instead of MereMemo::error. So, the solution (for now) is to declare the log-level instances in the global namespace inside LogTags.h. I recommend that when you define your own tags for your project, you declare the tags in your project’s namespace. Something like this would work:
#ifndef YOUR_PROJECT_LOGTAGS_H#define YOUR_PROJECT_LOGTAGS_H#include <MereMemo/Log.h>namespace yourproject{inline MereMemo::LogLevel error("error");inline MereMemo::LogLevel info("info");inline MereMemo::LogLevel debug("debug");} // namespace yourproject#endif // YOUR_PROJECT_LOGTAGS_HThen, when you are writing your code in your project that is part of your own namespace, you can refer to the tags such as error directly without needing to specify a namespace. You can use whichever namespace you want in place of yourproject. You can see a good example of a project that uses both the logging library and the testing library in Chapter 14, How To Test Services.
Also, note that you should refer to the Log.h file from within your own project as a separate project and use angle brackets. This is just like what we did when we started work on the logging library and had to start referring to the unit test library include with angle brackets.
One extra benefit of passing an instance of MereMemo::LogLevel to the log function is that we no longer need to specify the namespace to the log function. The compiler knows to look in namespaces that function arguments use when trying to resolve the function name. The simple act of passing error to the log function lets the compiler figure out that the log function is the one defined in the same namespace as the error instance. I actually thought about this benefit once the code was working and I could try to call log without a namespace. I was then able to add a test to Tags.cpp that looks like this:
TEST("log needs no namespace when used with LogLevel"){ log(error) << "no namespace";}Here, you can see that we can call log directly without specifying the MereMemo namespace, and we can do this because the compiler knows that the error instance being passed is itself a member of MereMemo.
If we try to call log without any arguments, then we’ll need to go back to using MereMemo::log instead of just log.
Also, notice how this new test was identified. It’s an alternate usage that simplifies the code, and making a test helps make sure that we don’t do anything later that will break the simpler syntax. The new test has no confirmations either. That’s because the test exists just to make sure that the call to log without the namespace compiles. We already know that log can send a log message to the log file because the other test confirms this. This test doesn’t need to duplicate the confirmation. If it compiles, then it has done its job.
The only thing we need now is a definition of the LogLevel class. Remember that we really want a general-purpose tagging solution and that a log level should be just one type of tag. There shouldn’t be anything special about a log level versus any other tag. We might as well define a Tag class too and make LogLevel inherit from Tag. Put the two new classes at the beginning of Log.h just inside the MereMemo namespace, like this:
class Tag{public: virtual ~Tag () = default; std::string key () const { return mKey; } std::string text () const { return mText; }protected: Tag (std::string const & key, std::string const & value) : mKey(key), mText(key + "="" + value + """) { }private: std::string mKey; std::string const mText;};class LogLevel : public Tag{public: LogLevel (std::string const & text) : Tag("log_level", text) { }};Make sure both classes are defined inside the MereMemo namespace. Let’s start with the Tag class, which should not be used directly. The Tag class should be a base class so that a derived class can specify the key to be used. The purpose of the Tag class is really just to make sure that the text output follows the key="value" format.
The LogLevel class inherits from the Tag class and only requires the text of the log level. The key is hardcoded to always be log_level, which enforces consistency. We get the consistency of the values when we declare instances of LogLevel with specific strings and then use the defined instances when calling log.
The logging library supports tags and even log-level tags but doesn’t define any specific log levels itself. The library also doesn’t try to order the log levels so that something such as error is a higher or lower level than debug. Everything is just a tag consisting of a key and a value.
Now that we have the LogLevel and Tag classes, how are they used by the log function? We’ll first need a new overload of log that accepts a Tag parameter, like this:
inline std::fstream log (Tag const & tag){ return log(to_string(tag));}Place this new log function right after the existing log function and still inside the MereMemo namespace in Log.h. The new log function will convert the tag into a string and pass the string to the existing log function. We’ll need to define a to_string function that can be placed right after the definition of the Tag class, like this:
inline std::string to_string (Tag const & tag){ return tag.text();}The to_string function just calls the text method in the Tag class to get the string. Do we really need a function for this? Couldn’t we just call the text method directly from within the new overloaded log function? Yes, we could have, but it’s a common practice in C++ to provide a function called to_string that knows how to convert a class into a string.
All these new functions need to be declared inline because we’re going to keep the logging library as a single include file that another project can simply include to begin logging. We want to avoid declaring functions in the Log.h file and then implementing them inside a Log.cpp file because that would require users to add Log.cpp to their project, or it would require that the logging library be built as a library and then linked into the project. By keeping everything in a single header file, we make it easier for other projects to use the logging library. It’s not really a library—it’s just a header file that gets included. We’ll still refer to it as the logging library, though.
The existing log function needs to be modified to accept a string. It actually used to accept a string for the message to be logged until we removed that and returned a stream instead that the caller uses to specify the message along with any other information to be logged. We’re going to put a string parameter back in the log function and call it preMessage. The log function will still return a stream that the caller can use. The preMessage parameter will be used to pass the formatted tag, and the log function will output the preMessage before returning the stream for the caller to use for the other information to be logged. The modified log function looks like this:
inline std::fstream log (std::string_view preMessage = ""){ auto const now = std::chrono::system_clock::now(); std::time_t const tmNow = std::chrono::system_clock::to_time_t(now); auto const ms = duration_cast<std::chrono::milliseconds>( now.time_since_epoch()) % 1000; std::fstream logFile("application.log", std::ios::app); logFile << std::endl << std::put_time(std::gmtime(&tmNow), "%Y-%m-%dT%H:%M:%S.") << std::setw(3) << std::setfill('0') << std::to_string(ms.count()) << " " << preMessage << " "; return logFile;}The preMessage parameter has a default value so that the log function can still be called without a log-level tag. All the log function does is send a timestamp, then the preMessage parameter to the stream, followed by a single space, before letting the caller have access to the returned stream.
Note that we still want the log-level tag to be separated from the timestamp with a space too. If there is no log level specified, then the output will have two spaces, which is a detail that will be fixed soon.
We have everything we need now to log with a log level that the new tests make use of:
MereMemo::log(error) << message;And building and running the project shows everything passes:
Running 1 test suites--------------- Suite: Single Tests------- Test: Message can be tagged in logPassed------- Test: log needs no namespace when used with LogLevelPassed------- Test: Simple message can be loggedPassed------- Test: Complicated message can be loggedPassed-----------------------------------Tests passed: 4Tests failed: 0And looking at a new log file shows the log levels, as expected:
2022-06-25T23:52:05.842 log_level="error" simple tag 75292022-06-25T23:52:05.844 log_level="error" no namespace2022-06-25T23:52:05.844 simple 248 with more text.2022-06-25T23:52:05.844 complicated 637 double=3.14 quoted="in quotes"The first two entries make use of the new log level. The second one is the one we only wanted to make sure compiles. The third and fourth logs are missing a log level. That’s because they never specified a log level. We should fix this and enable some tags to have default values, which would let us add log levels without specifying a log level so that we can make sure that every log message entry has a log level. The third and fourth entries also have an extra space, which will be fixed too. The next section will add the ability to specify default tags.
Before moving on, notice one more thing. The complicated log entry actually looks like it uses tags already. That’s because we formatted the message with a key="value" format. It’s common to include quotation marks around text values and to not use quotation marks around numbers. The quotation marks help define the entire value when the text has spaces inside of the value, while numbers don’t need spaces and therefore don’t need quotation marks.
Also, note that we don’t add spaces around the equals sign. We don’t log the following:
double = 3.14The reason we don’t log this is that the extra spaces are not needed and only make it harder to process the log output. It might be easier to read with spaces, but trying to automate the processing of log files with scripts is harder with spaces.
Likewise, we don’t use commas between tags. So, we don’t do this:
double=3.14, quoted="in quotes"Adding commas between tags might make it easier to read, but they are just one more thing that must be handled by code that needs to programmatically process log files. Commas are not needed, so we won’t be using them.
Now, we can proceed to add default tags.
Adding default tag values
The previous section identified the need to sometimes add a tag to log messages even if the tag is not given to the log function. We can use this to add a default log-level tag or any other default value needed for any tag.
With this feature, we’re starting to get to the need for the logging library to support configuration. What I mean is that we want to be able to tell the logging library how to behave before we call log, and we want the logging library to remember this behavior.
Most applications support logging only after the configuration is set once at the beginning of the application. This configuration setup is usually done at the beginning of the main function. So, let’s focus on adding some simple configuration that will let us set some default tags and then use those default tags when logging. If we encounter both a default tag and a tag with the same key used during a call to the log function, then we will use the tag provided in the call to log. In other words, the default tags will be used unless overridden in the call to log.
We’ll start with what it will take to set default tag values. This is a case where we won’t actually have a test for setting a default value inside of main, but we will have a test to make sure that a default value set in main does appear in the log output from within a test. And we might as well design the solution so that default values can be set at any time and not just from inside the main function. This will let us test the setting of a default value directly instead of relying on main.
Even though the following code isn’t inside of a test, we can still modify main first to make sure that the solution is something we like. Let’s change main to look like this:
#include "../Log.h"#include "LogTags.h"#include <MereTDD/Test.h>#include <iostream>int main (){ MereMemo::addDefaultTag(info); MereMemo::addDefaultTag(green); return MereTDD::runTests(std::cout);}We’ll include Log.h so that we can get a definition of a new addDefaultTag function that we’ll write, and we’ll include LogTags.h to get access to the info log level and a new tag for a color. Why a color? Because when adding new tests, we want to look for simple and general use cases. We already have the LogLevel tag defined by the logging library, and the only thing we need to do is define specific instances with their own values. But we haven’t yet defined our own tags, and this seems like a good place to check that custom tags work too. The usage flows well, and it seems reasonable that users would want to define multiple default tags.
It’s easy to go too far and add a bunch of new functionality that needs to be tested, but adding related scenarios such as the two default tags info and green that serve to make a test more generic is okay. At least, it’s the type of thing I would do in one step. You might want to make these two separate tests. I figure that we can add a single test that just makes sure both tags are present even if not provided to the log function. The fact that one tag type is provided by the logging library and the other is custom is not enough for me to require separate tests. I’ll be happy if they both appear in the log output.
Let’s add a test now to Tags.cpp that looks like this:
TEST("Default tags set in main appear in log"){ std::string message = "default tag "; message += Util::randomString(); MereMemo::log() << message; std::string logLevelTag = " log_level="info" "; std::string colorTag = " color="green" "; bool result = Util::isTextInFile(message, "application.log", {logLevelTag, colorTag}); CONFIRM_TRUE(result);}As it turns out, I’m glad that I did add two default tags instead of just one because when writing the test, I started thinking about how to verify they both appear in the log file, and that’s when I realized that the isTextInFile function is too rigid for what we now need. The isTextInFile function worked okay when we were only interested in checking if a specific string appeared in a file, but we’re working with tags now, and the order that the tags appear in the output is not specified. The important part is that we can’t reliably create a single string that will always match the order of the tags in the output, and we definitely don’t want to start checking for all possible tag orders.
What we want is the ability to first identify a specific line in the output. This is important because we might have many log file entries that have the same log level or the same color, but the message with the random number is more specific. Once we find a single line in the file that matches the random number, what we really want is to check that same line to make sure all the tags are present. The order within the line is not important.
So, I changed the isTextInFile function to take a third parameter, which will be a collection of strings. Each of these strings will be a single tag value to check. This actually makes the test easier to understand. We can leave the message unchanged and use it as the first argument to identify the line we want to find within the log file. Assuming we find that line, we then pass individually formatted tags in the key="value" format as a collection of strings to verify that they each exist in the same line found already.
Notice also that the tag strings begin and end with a single space. This makes sure that the tags are separated properly with spaces and that we also don’t have any commas at the end of a tag value.
We should fix the other test that checks for the existence of the log level, like this:
TEST("Message can be tagged in log"){ std::string message = "simple tag "; message += Util::randomString(); MereMemo::log(error) << message; std::string logLevelTag = " log_level="error" "; bool result = Util::isTextInFile(message, "application.log", {logLevelTag}); CONFIRM_TRUE(result);}We no longer need to append the message to the end of a formatted log-level tag. We just pass the single logLevelTag instance as the single value in the collection of additional strings to check. Now that we have default tag values set in main, there is no guarantee of the order of the tags. So, we could have failed this test because the color tag happened to come between the error tag and the message. All we check is that the message appears in the output and that the error tag also exists somewhere in the same log-line entry.
Let’s enhance the isTextInFile function now to accept a vector of strings in a third parameter. The vector should have a default value of an empty collection in case the caller just wants to verify that a file contains some simple text without also looking for additional strings on the same line. And while we’re doing this, let’s add a fourth parameter, which will also be a vector of strings. The fourth parameter will check to make sure that its strings are not found in the line. The updated function declaration looks like this in Util.h:
#include <string>#include <string_view>#include <vector>struct Util{ static std::string randomString (); static bool isTextInFile ( std::string_view text, std::string_view fileName, std::vector<std::string> const & wantedTags = {}, std::vector<std::string> const & unwantedTags = {});};We need to include vector and make sure to give the extra parameters default empty values. The implementation in Util.cpp looks like this:
bool Util::isTextInFile ( std::string_view text, std::string_view fileName, std::vector<std::string> const & wantedTags, std::vector<std::string> const & unwantedTags){ std::ifstream logfile(fileName.data()); std::string line; while (getline(logfile, line)) { if (line.find(text) != std::string::npos) { for (auto const & tag: wantedTags) { if (line.find(tag) == std::string::npos) { return false; } } for (auto const & tag: unwantedTags) { if (line.find(tag) != std::string::npos) { return false; } } return true; } } return false;}The change adds an extra for loop once we find the line identified by the text parameter. For all the wanted tags provided, we search through the line again to make sure each tag exists. If any of them are not found, then the function returns false. Assuming it finds all the tags, then the function returns true, just like before.
Almost the same thing happens for the unwanted tags except that the logic is reversed. If we find an unwanted tag, then the function returns false.
All we need now is to add the definition of the Color tag type and then the green color instance. We can add these to LogTags.h, like this:
inline MereMemo::LogLevel error("error");inline MereMemo::LogLevel info("info");inline MereMemo::LogLevel debug("debug");class Color : public MereMemo::Tag{public: Color (std::string const & text) : Tag("color", text) { }};inline Color red("red");inline Color green("green");inline Color blue("blue");Building the project shows that I forgot to implement the addDefaultTag function that we started out using in main. Remember when I said that it’s easy to get sidetracked? I started to add the function to Log.h, like this:
inline void addDefaultTag (Tag const & tag){ static std::map<std::string, Tag const *> tags; tags[tag.key()] = &tag;}This is a great example of how writing the usage first helped with the implementation. What we need to do is store the tag passed to the addDefaultTag function so that it can be retrieved later and added to log messages. We first need a place to store the tags so that the function declares a static map.
Originally, I wanted the map to make a copy of the tag, but that would have required changing the Tag class so that it could be used directly instead of working with derived classes. I like how the derived classes help with keeping the key consistent and didn’t want to change that part of the design.
So, instead, I decided that the collection of tags would use pointers. The problem with using pointers is that it’s not obvious to the caller of addDefaultTag that the lifetimes of any tags passed to the function must remain valid for as long as the tag remains in the default tag collection.
We can still make copies and store the copies in unique pointers, but that requires either extra work for the caller of addDefaultTag or some method that knows how to clone a tag. I don’t want to add extra complexity to the code in main that calls addDefaultTag and force that code to make a copy. We’ve already written the code in main, and we should strive to keep that code as-is because it was written using TDD principles and provides the solution we will be most happy with.
To avoid lifetime surprises, we should add a clone method to the Tag-derived classes. And because we are using a map in addDefaultTag and have identified the need for unique pointers, we need to include map and memory at the top of Log.h, like this:
#include <chrono>#include <ctime>#include <fstream>#include <iomanip>#include <iostream>#include <map>#include <memory>#include <string>#include <string_view>Now, let’s implement the correct addDefaultTag function to make a copy of the passed-in tag instead of storing a pointer directly to the caller’s variable. This will free up the caller so that the tags passed in no longer have to remain alive indefinitely. Add this code to Log.h right after the LogLevel class:
inline std::map<std::string, std::unique_ptr<Tag>> & getDefaultTags (){ static std::map<std::string, std::unique_ptr<Tag>> tags; return tags;}inline void addDefaultTag (Tag const & tag){ auto & tags = getDefaultTags(); tags[tag.key()] = tag.clone();}We use a helper function to store the collection of default tags. The collection is static, so it gets initialized to an empty map the first time the tags are requested.
We need to add a pure virtual clone method to the Tag class that will return a unique pointer. The method declaration can go right after the text method and looks like this:
std::string text () const { return mText; } virtual std::unique_ptr<Tag> clone () const = 0;protected:And now, we need to add the clone method implementation to both the LogLevel and Color classes. The first looks like this:
class LogLevel : public Tag{public: LogLevel (std::string const & text) : Tag("log_level", text) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new LogLevel(*this)); }};And the implementation for the Color class looks almost identical:
class Color : public MereMemo::Tag{public: Color (std::string const & text) : Tag("color", text) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new Color(*this)); }};Even though the implementations look almost identical, each makes a new instance of the specific type involved, which gets returned as a unique pointer to Tag. This is the complexity that I was hoping to avoid when I started, but it’s better to add complexity to the derived classes instead of placing extra and unexpected requirements on the caller of addDefaultTag.
We’re now ready to build and run the test application. One of the tests fails, like this:
Running 1 test suites--------------- Suite: Single Tests------- Test: Message can be tagged in logPassed------- Test: log needs no namespace when used with LogLevelPassed------- Test: Default tags set in main appear in logFailed confirm on line 37 Expected: true------- Test: Simple message can be loggedPassed------- Test: Complicated message can be loggedPassed-----------------------------------Tests passed: 4Tests failed: 1The failure is actually a good thing and is part of the TDD process. We wrote the code as we intended it to be used in main, and wrote a test that would verify that the default tags appear in the output log file. The default tags are missing, and that’s because we need to change the log function so that it will include the default tags.
Right now, the log function only includes the tags that are directly provided—or, I should say, the tag that is directly provided because we don’t yet have a way to log multiple tags. We’ll get there. One thing at a time.
Our log function currently has two overloaded versions. One takes a single Tag parameter and turns it into a string that it passes to the other. Once the tag is turned into a string, it becomes harder to detect which tags are currently being used, and we’ll need to know that so that we don’t end up logging both a default tag and a directly specified tag with the same key.
For example, we don’t want a log message to include both info and debug log levels because the log was made with debug while info was the default. We only want the debug tag to appear because it should override the default.
We need to pass the tag to the log function that does the output as a Tag instance instead of a string. Instead of a single Tag instance, though, let’s let callers pass more than one tag when calling log. Should we let the number of tags be unlimited? Probably not. Three seems like a good amount. If we need more than three, we’ll come up with a different solution or add more.
I thought about different ways to write a log function that takes a variadic number of tags using templates. While it might be possible, the complexity quickly became unworkable. So, instead, here are three overloads of log that turn the parameters into a vector of Tag pointers:
inline auto log (Tag const & tag1){ return log({&tag1});}inline auto log (Tag const & tag1, Tag const & tag2){ return log({&tag1, &tag2});}inline auto log (Tag const & tag1, Tag const & tag2, Tag const & tag3){ return log({&tag1, &tag2, &tag3});}These functions replace the earlier log function that converted the tag into a string. The new functions create a vector of Tag pointers. We might eventually need to call clone to create copies instead of using pointers to the caller’s arguments, but for now, this works, and we don’t have to worry about the lifetime issues we had with the default tags.
We’ll need to include vector at the top of Log.h, and while implementing the log function that actually does the logging, I ended up needing algorithm too. The new include section looks like this:
#include <algorithm>#include <chrono>#include <ctime>#include <fstream>#include <iomanip>#include <iostream>#include <map>#include <memory>#include <string>#include <string_view>#include <vector>And now, to the changes to the log function that does the logging. It looks like this:
inline std::fstream log (std::vector<Tag const *> tags = {}){ auto const now = std::chrono::system_clock::now(); std::time_t const tmNow = std::chrono::system_clock::to_time_t(now); auto const ms = duration_cast<std::chrono::milliseconds>( now.time_since_epoch()) % 1000; std::fstream logFile("application.log", std::ios::app); logFile << std::endl << std::put_time(std::gmtime(&tmNow), "%Y-%m-%dT%H:%M:%S.") << std::setw(3) << std::setfill('0') << std::to_string(ms.count()); for (auto const & defaultTag: getDefaultTags()) { if (std::find_if(tags.begin(), tags.end(), [&defaultTag](auto const & tag) { return defaultTag.first == tag->key(); }) == tags.end()) { logFile << " " << defaultTag.second->text(); } } for (auto const & tag: tags) { logFile << " " << tag->text(); } logFile << " "; return logFile;}Instead of accepting a string of pre-formatted tags, the function now takes a vector of Tag pointers with a default value of an empty collection. As far as this function is concerned, there can be an unlimited number of tags. The limit of three tags comes only because of the overloaded log functions that take up to three tags.
The default value for the tags vector lets callers continue to be able to call log with no arguments.
The first part of the function that formats the timestamp, opens the log file, and prints the timestamp remains unchanged, except that we no longer display a pre-formatted string for the tags.
The changes start with the first for loop, which looks at each default tag. We want to try finding the same tag key in the vector of tag pointers. If we find the same key, then we skip the default tag and try the next one. If we don’t find the same key, then we display the default tag.
To do the searching, we use the std::find_if algorithm and provide a lambda that knows how to compare the keys.
After displaying only the default tags that were not overridden, the code goes through a second for loop to display all the tags passed in directly.
Building and running the test application shows that all the tests pass, and the log file now contains default tags for all the entries, like this:
2022-06-26T06:24:26.607 color="green" log_level="error" simple tag 47182022-06-26T06:24:26.609 color="green" log_level="error" no namespace2022-06-26T06:24:26.609 color="green" log_level="info" default tag 84442022-06-26T06:24:26.609 color="green" log_level="info" simple 4281 with more text.2022-06-26T06:24:26.610 color="green" log_level="info" complicated 8368 double=3.14 quoted="in quotes"All the log messages contain the color tag set to "green", and they all contain the log_level tag with either the default value of "info" or the overridden value of "error". For the test that overrides the default value, let’s make sure that the default value does not exist. We can make use of the unwanted tags parameter in the isTextInFile function, like this:
TEST("Message can be tagged in log"){ std::string message = "simple tag "; message += Util::randomString(); MereMemo::log(error) << message; // Confirm that the error tag value exists and that the // default info tag value does not. std::string logLevelTag = " log_level="error" "; std::string defaultLogLevelTag = " log_level="info" "; bool result = Util::isTextInFile(message, "application.log", {logLevelTag}, {defaultLogLevelTag}); CONFIRM_TRUE(result);}Should the extra check that the default tag value does not exist in the log file be added to a separate test? The benefit of a separate test is that it makes it clear what is being tested. The downside is that the test will be almost identical to this one. It’s something to think about. In this case, I think the extra check and comment in the existing test is enough.
Before moving on, we need to add a test for the feature that I slipped in for multiple tags. I really should have written a test for this first before enhancing the code to support multiple tags, but for the purposes of explaining the code, it was much more direct to just explain the idea of multiple tags once instead of going back and adding the extra explanation.
Let’s quickly add a new type of Tag called Size with a few named instances in LogTags.h, like this:
class Size : public MereMemo::Tag{public: Size (std::string const & text) : Tag("size", text) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new Size(*this)); }};inline Size small("small");inline Size medium("medium");inline Size large("large");And now, here is a test for multiple tags:
TEST("Multiple tags can be used in log"){ std::string message = "multi tags "; message += Util::randomString(); MereMemo::log(debug, red, large) << message; std::string logLevelTag = " log_level="debug" "; std::string colorTag = " color="red" "; std::string sizeTag = " size="large" "; bool result = Util::isTextInFile(message, "application.log", {logLevelTag, colorTag, sizeTag}); CONFIRM_TRUE(result);}The log file contains the entry with all three tags, like this:
2022-06-26T07:09:31.192 log_level="debug" color="red" size="large" multi tags 9863We have the ability to log with up to three directly specified tags and multiple default tags. We need to eventually use the tags for more than just displaying information in the log file. We want to be able to filter log messages based on the tag values to control which log messages make it all the way to the log file and which are ignored. We’re not quite ready for filtering. The next section will explore filtering options based on the tag values.
Exploring filtering options
Filtering log messages lets us write code that includes calls to log information at important places within the code but then ignore some of those logging calls. Why would we go to all the trouble of adding code to do logging but then not do the logging?
For some events in the code such as an error that gets detected, it makes sense to always log that event. Other places might be equally important even if they are not errors. Usually, these are places in the code where something gets created or deleted. I’m not talking about creating or deleting an instance of a local variable. I mean something major, such as the creation of a new customer account, the completion of a quest in an adventure game, or the deletion of an old data file to free up space. All of these are good examples of important events that should probably always be logged.
Other events might help a developer understand what a program was doing right before it crashed. These log messages act like signposts along a journey. They’re not as big as the errors or major events, but they can let us figure out what a program was doing. These are usually good to log too because, without them, it can be hard to fix bugs. Sure—the error log might show clearly that something bad happened, but understanding what led up to the problem can be difficult without the signpost messages.
And sometimes, when we know the general idea of what led to a problem, we need even more details. This is where we sometimes want to turn off the logging because log messages such as these can sometimes be extremely verbose and cause the size of the log files to increase. They can also make it hard to see the bigger picture. Have you ever tried walking someplace with your eyes intently focused on the ground at your feet? You can get all the details of every step but might find that you get lost. Looking up to see the general direction makes it hard to also notice a small rock that can cause you to trip.
When writing code, we want to put all these types of log messages into the code because adding extra logging messages later can be difficult, especially if the program is running at a remote customer location. So, we want the code to try to log everything. And then, at runtime, we want to control exactly how much information appears in the log files. Filtering lets us control how much logging we see by ignoring some logging requests.
We’re going to filter log messages based on tags and their values, but we have a problem.
Let’s say that we want to ignore a log message unless it has a certain tagged value. The way our log function works now is that it immediately opens a log file and starts streaming a timestamp, then adds tags, and finally lets the caller send whatever else is needed.
The only way to know for certain if a log message should be allowed to complete is to look at the tags once they have been finalized. In other words, we need to let everything be sent as if it will be logged but without actually doing anything. Once we have the complete message, we can look at the message to see if it meets the criteria to be sent to the output file.
This means we need to do two things differently. First, we need to stop writing to a log file right away and collect everything in case we do eventually need to write it. And second, we need to know when a log message is complete. We can’t simply return an open stream to the caller and let the caller do whatever they want with the stream. Or, I should say that we can’t return a stream that directly modifies the output log file. Letting the caller work directly with the final output log file gives us no way to know when the caller is done so that we can finish up and either ignore the log or let it continue.
I know of three ways to determine when a potential log message is complete. The first is to put everything into a single function call. The function can accept a variable number of arguments, so we won’t be limited to a fixed number. But because the entire log message is bundled into a single function call, we will know when we have everything. It might look like this:
MereMemo::log(info, " count=", 5, " with text");I’m using a tag instance, a couple of string literals, and an integer number in this example. The string literals could instead be string variables or maybe function calls that return information to be logged. One of the string literals, together with the number, actually forms a key=value tag. The point is that the log function would know for certain exactly how much information was sent to be logged and we would know all the values. We could easily test the log message to see if it should be allowed to continue or if it should be ignored.
We even have the beginning of a solution like this already because we accept up to three tag instances in the log function.
The second way to determine when a log is complete is to use something to terminate the stream we have now. It might look like this:
MereMemo::log(info) << "count=" << 5 << " with text" << MereMemo::endlog;Notice that we don’t need the extra space inside the "count=" string literal because the log function adds one for us after all the tags.
Or, we could even allow tags to be sent to the stream, like this:
MereMemo::log() << info << " count=" << 5 << " with text" << MereMemo::endlog;And we’re back to needing the leading space before the count string literal again. This is common for streams where the caller needs to manage spaces between streamed elements. The only place where we don’t need to add a space is at the very first item streamed after the log function.
The main idea with the stream approach is that we need something at the end to let the logging library know that all the information is ready to be tested against the criteria to see if the log should be ignored or not.
I like the stream approach better. It feels more open to me—almost more natural. And because of operator precedence and the chaining of the streaming operators, we know the order in which the log line will be evaluated. That might not be very important, but it plays into the feeling that I like the streaming approach better.
With this second approach, the stream that the caller gets back from the log function can’t be a std::fstream instance that is directly tied to the log file. Working with fstream directly would not let us ignore the log message because the information would already be sent to the file. Maybe we could return a stream that’s tied to a string instead and let the terminating endlog element send the string that gets built to the log file or ignore it.
What happens if the terminating endlog element is forgotten? The terminating endlog element needs to evaluate the log and move it forward or ignore it. If endlog is forgotten, then the log message will not complete. The developer might not notice the problem until a need to look at the log file shows that the expected log message is always ignored.
The third approach is similar to the second but without the need for a terminating element that can be forgotten. Anytime a design relies on a person to remember to do something, there will almost certainly be cases where the required part is left out. By removing the need to remember to add a terminating marker, we get a better design that can no longer be misused due to a simple oversight.
We already know that we can’t just return a stream tied directly to a log file. The third approach takes this a step further and returns a custom stream. We don’t use a standard stream at all because we need to add code in the stream destructor that finishes the logging and decides to either let the message complete or ignore it.
This approach relies on specific object lifetime rules defined by C++. We need to know exactly when the destructor will run because we need the destructor to fill the role of a terminating endlog element. Other programming languages that use garbage collection to clean up deleted objects would not be able to support this third solution because the stream would not be deleted until some unspecified time in the future. C++ is very clear about when object instances get deleted, and we can rely on the order. For instance, we could make a call to log like this:
MereMemo::log(info) << "count=" << 5 << " with text";The custom stream that log returns will be destructed at the semicolon, which ends the expression. The programmer cannot forget anything, and the stream will be able to run the same code that an explicit endlog element would trigger.
Maybe we could combine the best aspects of all three approaches. The first function call approach doesn’t need a terminating element because it knows exactly how many arguments are being passed. The second terminating endlog approach is more open and natural and can work with a standard stream to a string, and the custom stream approach is open and natural too and avoids misuse.
I initially wanted to create a logging library that would be able to filter messages based on the entire message. While filtering on anything in the message seems to be the most flexible and powerful solution, it’s also the most complicated to implement. We don’t want to choose one design over another just because one is easier to code. We should choose a design based on the end usage that we will be happy with and find natural to use. Sometimes, complex implementations are a sign that the end use will also be complicated. A solution that might be less powerful overall but is easier to use will be better, as long as we don’t take away anything that is required.
One filtering complexity that we should be able to remove without affecting the end use is to only look at tags formed through the Tag-derived classes. We should be able to drop the ability to filter a log message based on the content of manually crafted tags.
Another simplification we can make will be to only filter tags passed to the log function. This will combine the aspect of the first approach where the log function accepts multiple arguments with the custom streaming approach, which accepts an intuitive series of information in chunks. So, take a look at the following streaming example:
MereMemo::log(info) << green << " count=" << 5 << " with text";Here, there are a total of three key=value tags. The first is the info tag, then the green tag, and then a tag formed manually with the count text and number. Instead of trying to filter based on all three tags, the only information we’ll use for filtering will be the info tag because that is the only tag passed to the log function directly. We should also filter based on default tags because the log function knows about the default tags too. This makes it easy to understand what the log function does. The log function starts the logging and determines if anything that comes after it will be accepted or ignored.
If we want to consider the green tag in the filtering, then we just need to add it to the log function too, like this:
MereMemo::log(info, green) << "count=" << 5 << " with text";This is the type of use that needs to be thought through with TDD. The result is not always the most powerful. Instead, the goal is to meet the needs of the user and be easy and intuitive to understand.
Because tags are becoming more important to this design, we should enhance them to support more than just text values. The next section will add new types of tags.
Adding new tag types
Since we’re starting to refer to tags with numbers instead of text for the value, now would be a good time to add support for numeric and Boolean tags that don’t need quotation marks around the value.
We’re going to get slightly ahead of ourselves here and add some code that we don’t have a test for. That’s only because the additional support for numeric and Boolean tags is so similar to what we already have. This change is in Log.h in the Tag class. We need to add four extra constructors like this after the existing constructor that accepts a string:
protected: Tag (std::string const & key, std::string const & value) : mKey(key), mText(key + "="" + value + """) { } Tag (std::string const & key, int value) : mKey(key), mText(key + "=" + std::to_string(value)) { } Tag (std::string const & key, long long value) : mKey(key), mText(key + "=" + std::to_string(value)) { } Tag (std::string const & key, double value) : mKey(key), mText(key + "=" + std::to_string(value)) { } Tag (std::string const & key, bool value) : mKey(key), mText(key + "=" + (value?"true":"false")) { }Each constructor forms text following either the key="value" or the key=value syntax. To test the new constructors, we’re going to need some new derived tag classes. All of these classes can go in LogTags.h. The two integral classes look like this:
class Count : public MereMemo::Tag{public: Count (int value) : Tag("count", value) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new Count(*this)); }};class Identity : public MereMemo::Tag{public: Identity (long long value) : Tag("id", value) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new Identity(*this)); }};We’re not going to provide named instances of these tags. The earlier Color and Size tag types both have reasonable and common choices that make sense, but even they can be used directly if a strange color or an uncommon size needs to be logged. The new tags have no such common values.
Continuing, the double tag looks like this:
class Scale : public MereMemo::Tag{public: Scale (double value) : Tag("scale", value) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new Scale(*this)); }};And again, it has no obvious default values. Maybe we could provide a named value for 1.0 or some other specific values, but these seem like they would be best defined by the domain of the application. We’re just testing a logging library and will go without named instances for this tag.
The Boolean tag looks like this:
class CacheHit : public MereMemo::Tag{public: CacheHit (bool value) : Tag("cache_hit", value) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new CacheHit(*this)); }};inline CacheHit cacheHit(true);inline CacheHit cacheMiss(false);And for this one, we have obvious named values for true and false that we can provide.
All of the new tag classes should give you an idea of what they can be used for. Many of these are very applicable for large financial microservices where, for example, values can take a long time to be calculated and need to be cached. Logging whether a result was due to a cache hit or miss is very valuable when figuring out the flow of a calculation.
We’d like to be able to pass one of the new tags to the stream returned by the log function, like this:
MereMemo::log(info) << Count(1) << " message";To do so, we need to add a stream overload that knows how to handle the Tag class. Add this function to Log.h right after the to_string function:
inline std::fstream & operator << (std::fstream && stream, Tag const & tag){ stream << to_string(tag); return stream;}The function uses an rvalue reference to the stream because we’re using the temporary stream returned from the log function.
Now, we can create a test that will log and confirm each of the new types. You could make separate tests for each type or put all of them into one test, like this:
TEST("Tags can be streamed to log"){ std::string messageBase = " 1 type "; std::string message = messageBase + Util::randomString(); MereMemo::log(info) << Count(1) << message; std::string countTag = " count=1 "; bool result = Util::isTextInFile(message, "application.log", {countTag}); CONFIRM_TRUE(result); messageBase = " 2 type "; message = messageBase + Util::randomString(); MereMemo::log(info) << Identity(123456789012345) << message; std::string idTag = " id=123456789012345 "; result = Util::isTextInFile(message, "application.log", {idTag}); CONFIRM_TRUE(result); messageBase = " 3 type "; message = messageBase + Util::randomString(); MereMemo::log(info) << Scale(1.5) << message; std::string scaleTag = " scale=1.500000 "; result = Util::isTextInFile(message, "application.log", {scaleTag}); CONFIRM_TRUE(result); messageBase = " 4 type "; message = messageBase + Util::randomString(); MereMemo::log(info) << cacheMiss << message; std::string cacheTag = " cache_hit=false "; result = Util::isTextInFile(message, "application.log", {cacheTag}); CONFIRM_TRUE(result);}The reason I wasn’t so worried about creating this test before the code we added to enable the test is that we already thought through the desired usage before beginning.
The tag for double values might need some more work later to control the precision. You can see that it uses the default six decimals of precision. The log entries for the new test look like this:
2022-06-27T02:06:43.569 color="green" log_level="info" count=1 1 type 28072022-06-27T02:06:43.569 color="green" log_level="info" id=123456789012345 2 type 77272022-06-27T02:06:43.570 color="green" log_level="info" scale=1.500000 3 type 54952022-06-27T02:06:43.570 color="green" log_level="info" cache_hit=false 4 type 3938Notice how the message that is prepared for each log call is made unique with the numbers 1 to 4. This makes sure that in the rare case where a duplicate random number will be generated, none of the four log messages will have the same text.
We can now log default tags, tags provided directly to the log function, and tags that are streamed just like any other piece of information. Before we implement the actual filtering, there are some enhancements that the next section will make to improve the tag classes even more by reducing the amount of code that needs to be written for each tag class.
Refactoring the tag design with TDD
We have a base Tag class and several derived tag classes in the tests. Even though the logging library will only define the log-level tag, it should still make it easy for developers to create new derived tag classes. And right now, creating a new derived tag class is mostly boilerplate code that needs to be repeated over and over. We should be able to enhance the experience by using templates.
Here’s what an existing derived tag class looks like:
class LogLevel : public Tag{public: LogLevel (std::string const & text) : Tag("log_level", text) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new LogLevel(*this)); }};The LogLevel-derived tag class is the only class like this that the logging library will provide. It defines the log-level tag without actually defining any specific log-level values. It’s better to say that this class defines what a log level should be.
We can compare the LogLevel class to one of the other derived tag classes from the tests. Let’s choose the CacheHit class, which looks like this:
class CacheHit : public MereMemo::Tag{public: CacheHit (bool value) : Tag("cache_hit", value) { } std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new CacheHit(*this)); }};What can we improve about these classes? They’re almost the same, with a few differences that can be moved into a template class. What’s different about these two classes?
- The name, obviously. LogLevel versus CacheHit.
- The parent class namespace. LogLevel is already in the MereMemo namespace.
- The key string. LogLevel uses "log_level" while CacheHit uses "cache_hit".
- The type of the value. LogLevel uses a std::string value while CacheHit uses a bool value.
That’s all the differences. There should be no need to make developers recreate all this every time a new tag class is needed. And we’re going to need to add more code to the tag classes in order to support filtering, so now is a great time to simplify the design.
We should be able to make the upcoming filtering changes without affecting any of the existing tests, but that will require design changes now. We’re refactoring the design, and the tests will help make sure that the new design continues to behave just like the current design. The confidence we get from knowing everything still works is one of the benefits of using TDD.
The Tag class represents an interface that all tags support. We’ll leave it as-is and simple. Instead of changing the Tag class, we’ll introduce a new template class that can hold the clone method implementation and any upcoming filtering changes.
Change the LogLevel class in Log.h to use a new TagType template class that can use different types of values, like this:
template <typename T, typename ValueT>class TagType : public Tag{public: std::unique_ptr<Tag> clone () const override { return std::unique_ptr<Tag>( new T(*static_cast<T const *>(this))); } ValueT value () const { return mValue; }protected: TagType (ValueT const & value) : Tag(T::key, value), mValue(value) { } ValueT mValue;};class LogLevel : public TagType<LogLevel, std::string>{public: static constexpr char key[] = "log_level"; LogLevel (std::string const & value) : TagType(value) { }};We still have a class called LogLevel that can be used just like before. It now specifies the type of the value, which is std::string, in the template argument to TagType, and the key string is now a constant array of chars that each derived tag class will define. The LogLevel class is simpler because it no longer needs to handle cloning.
The new TagType template class does most of the hard work. For right now, that work is just cloning, but we’ll need to add more features in order to implement filtering. We should be able to put those upcoming features inside the TagType class and leave the derived tag classes unchanged.
The way this design works is based on something called the Curiously Recurring Template Pattern (CRTP) and involves a class inheriting from a template that is parameterized on the class itself. In this case, LogLevel inherits from TagType, and TagType is given LogLevel as one of its template parameters. This allows TagType to refer back to LogLevel from within the clone method in order to construct a new instance of LogLevel. Without the CRTP, then TagType would have no way to create a new LogLevel instance because it would not know what type to create.
And TagType needs to refer back to LogLevel one more time in order to get the name of the key. TagType does this again by referring to the type given to it by the CRTP in the T parameter.
The clone method is a little more complicated because when we’re inside the clone method, we’re in the TagType class, which means that the this pointer needs to be cast to the derived type.
We can now simplify the other derived tag types in LogTags.h. The Color and Size types both use std::string as the value type just like LogLevel, and they look like this:
class Color : public MereMemo::TagType<Color, std::string>{public: static constexpr char key[] = "color"; Color (std::string const & value) : TagType(value) { }};class Size : public MereMemo::TagType<Size, std::string>{public: static constexpr char key[] = "size"; Size (std::string const & value) : TagType(value) { }};The Count and Identity types both use integral value types of different lengths, and they look like this:
class Count : public MereMemo::TagType<Count, int>{public: static constexpr char key[] = "count"; Count (int value) : TagType(value) { }};class Identity : public MereMemo::TagType<Identity, long long>{public: static constexpr char key[] = "id"; Identity (long long value) : TagType(value) { }};The Scale type uses a double value type and looks like this:
class Scale : public MereMemo::TagType<Scale, double>{public: static constexpr char key[] = "scale"; Scale (double value) : TagType(value) { }};And the CacheHit type uses a bool value type and looks like this:
class CacheHit : public MereMemo::TagType<CacheHit, bool>{public: static constexpr char key[] = "cache_hit"; CacheHit (bool value) : TagType(value) { }};Each of the derived tag types is much simpler than before and can focus on what makes each one unique: the class name, the key name, and the type of the value.
The next section will create filtering tests based on logical criteria that will allow us to specify what should be logged, and we’ll be using the simplified tag classes too with the clone method.
Designing tests to filter log messages
Filtering log messages is going to be one of the biggest features of the logging library. That’s why this chapter is devoting so much effort to exploring ideas and enhancing the design. Most logging libraries offer some support for filtering, but usually, it’s limited to just logging levels. And the logging levels are also usually ordered so that when you set one logging level, then you get all logs with a level equal to and either above or below the filtered level.
This always seemed arbitrary to me. Do the logging levels go up or down? Does setting the filtering level to info mean that you get debug too, or just info and error logs?
And this ignores the bigger problem of information overload. Once you do figure out how to get debug-level logs, they all get logged and the logs quickly fill up. I’ve even seen logs fill up so fast that the messages I was interested in were already zipped up and about to be deleted to save space before I could even exit the application to see what happened.
Our target customer for the logging library is a microservices developer. This means that the applications being worked on are probably large and distributed. Turning on debug logging everywhere, even within a single service, causes a lot of problems.
The logging library we’re building will fix these problems, but we need to start simple. A test like this in Tags.cpp is a good start:
TEST("Tags can be used to filter messages"){ int id = MereMemo::createFilterClause(); MereMemo::addFilterLiteral(id, error); std::string message = "filter "; message += Util::randomString(); MereMemo::log(info) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::clearFilterClause(id); MereMemo::log(info) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}The idea for this test is to first set a filter that will cause a log message to be ignored. We confirm that the message does not appear in the log file. Then, the test clears the filter and tries to log the same message again. This time, it should appear in the log file.
Normally, a filter match should allow a log to proceed, and no match should cause the message to be ignored. But when there are no filters set at all, then we should let everything through. Letting everything through without any filters lets users opt into filtering. If filtering is being used at all, then it controls the log output, but when there are no filters, then it would be strange to not let anything through. When the test sets a filter that does not match the log message, then the message does not appear in the log file because filtering has been enabled. When the filter is cleared, then we’re assuming there are no other filters set, and all log messages will be allowed to proceed again.
We’ll be filtering logs based on formulas in the Disjunctive Normal Form (DNF). The DNF specifies one or more clauses that are OR’ed together. Each clause contains literals that are AND’ed together. These are not literals in the C++ sense. Here, literal is a mathematical term. Each literal in a clause can either be AND’ed as-is or NOT’ed first. All this is Boolean logic and has the ability to represent any logical condition from simple to complex filters. Explaining all the details of DNF is not the purpose of this book, so I won’t be explaining all the math behind DNF. Just know that DNF is powerful enough to represent any filter we can think of.
This is a case where a powerful solution is needed. Even so, we’ll try to focus on the end use and keep the solution as easy to use as possible.
The test calls a createFilterClause function that returns an identifier for the clause created. Then, the test calls addFilterLiteral to add an error tag to the clause just created. What the test is trying to accomplish is to complete a log only if the error tag is present. If this tag is not present, then the log should be ignored. And remember that in order for a tag to be considered, it must either be present in the default tags or supplied directly to the log function.
Then, the test calls another function, clearFilterClause, which is intended to clear the filter clause just created and let everything be logged again.
Normally, the microservices developer won’t run their application with filtering completely empty because that would allow all log messages to go through. Some amount of filtering will likely be in place at all times. As long as at least one filter clause is active, then filtering will only allow messages to proceed that match one of the clauses. By allowing multiple clauses, what we’re doing is letting extra log messages go through because each additional clause has the chance to match more log messages. We’ll have the ability to adjust what gets logged with a powerful system of Boolean logic.
A large project could then add tags that identify different components. The debug logs could be turned on only for certain components or for other matching criteria. The extra logic opens up more flexibility to increase the logging for interesting areas during debugging sessions while leaving other areas unaffected and logging at normal levels.
What happens if a tag is present in the default tags but gets overridden directly in the call to log? Should the default tag be ignored in favor of the explicit tag? I think so, and this will be a great test to include. Edge cases such as this really help define a project and improve the benefits gained by using TDD. Let’s add the test now so that we don’t forget. It looks like this:
TEST("Overridden default tag not used to filter messages"){ int id = MereMemo::createFilterClause(); MereMemo::addFilterLiteral(id, info); std::string message = "override default "; message += Util::randomString(); MereMemo::log(debug) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::clearFilterClause(id);}This test relies on the info tag already being set in the default tags. We should probably add the ability to test which tags are default so that the test can fail if info is not found in the default tags, and we need to make sure to clear the filter clause at the end of the test so that other tests are not affected. The previous test also cleared the clause but at a specific point in the test. Even so, the previous test should have a stronger guarantee that the test will not end with the filter clause still set. We should make use of a test teardown to always clear the filter clause at the end of any test that creates one.
Before continuing to add a teardown, the idea for the test that I started to explain is this. After setting a clause to only allow logs with the info tag, then the log message should have been allowed to continue because it will gain the info tag through the default set of tags. But instead, the log overrides the info tag with the debug tag. The end result is that the log message should not be found in the output log file.
To make sure that we always clear the filter clause even if a test fails and throws an exception before it reaches the end of the test, we need to define a setup and teardown class in Tags.cpp, like this:
class TempFilterClause{public: void setup () { mId = MereMemo::createFilterClause(); } void teardown () { MereMemo::clearFilterClause(mId); } int id () const { return mId; }private: int mId;};If you want more information about setup and teardown classes, refer to Chapter 7, Test Setup and Teardown.
It’s okay for a test to clear the filters itself at the appropriate times. Adding an instance of SetupAndTeardown will make sure to call the clearFilterClause function even if it was already called. The first test from this section looks like this:
TEST("Tags can be used to filter messages"){ int id = MereMemo::createFilterClause(); MereMemo::addFilterLiteral(id, error); std::string message = "filter "; message += Util::randomString(); MereMemo::log(info) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::clearFilterClause(id); MereMemo::log(info) << message; result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}The test now gets the clause ID from the setup and teardown instance. The ID is used to add the filter literal and to clear the filter clause at the correct time. The filter clause will be cleared again at the end of the test with no effect.
The second test from this section no longer needs to explicitly clear the filter itself and only needs to add the SetupAndTeardown instance, like this:
TEST("Overridden default tag not used to filter messages"){ MereTDD::SetupAndTeardown<TempFilterClause> filter; MereMemo::addFilterLiteral(filter.id(), info); std::string message = "override default "; message += Util::randomString(); MereMemo::log(debug) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result);}This test was calling clearFilterClause at the end to put the filters back in an unfiltered state. The test no longer needs to call clearFilterClause directly because relying on the SetupAndTeardown destructor is more reliable.
We have two filter tests that call functions that don’t exist yet. Let’s add the following function stubs to Log.h right after the addDefaultTag function:
inline int createFilterClause (){ return 1;}inline void addFilterLiteral (int filterId, Tag const & tag, bool normal = true){}inline void clearFilterClause (int filterId){}The createFilterClause function just returns 1 for now. It will need to eventually return a different identifier for each clause created.
The addFilterLiteral function adds the given tag to the clause identified. The normal parameter will let us add literals that are NOT’ed or inverted by passing false. Be careful with the meaning of flags such as this. When I first wrote this, the flag was called invert and had a default value of false. I didn’t notice the problem until writing a test for an inverted filter and it seemed strange to pass true in order to get an inverted literal. The test highlighted the backward usage while the initial function declaration let it slip by unnoticed.
And the clearFilterClause function does nothing for now. We’ll need to have some sort of collection of clauses later that we can work with.
Stubbing out the filter functions lets us build and run the test application. We get two test failures, like this:
Running 1 test suites--------------- Suite: Single Tests------- Test: Message can be tagged in logPassed------- Test: log needs no namespace when used with LogLevelPassed------- Test: Default tags set in main appear in logPassed------- Test: Multiple tags can be used in logPassed------- Test: Tags can be streamed to logPassed------- Test: Tags can be used to filter messagesFailed confirm on line 123 Expected: false------- Test: Overridden default tag not used to filter messagesFailed confirm on line 143 Expected: false------- Test: Simple message can be loggedPassed------- Test: Complicated message can be loggedPassed-----------------------------------Tests passed: 7Tests failed: 2The results are expected with TDD. We did the bare minimum needed to get the code building so that we can see the failures. We can add a little more implementation to the stubbed-out functions next.
I mentioned that we’ll need a collection for the clauses. Add the following functions to Log.h, right before the stubbed-out filter functions:
struct FilterClause{ std::vector<std::unique_ptr<Tag>> normalLiterals; std::vector<std::unique_ptr<Tag>> invertedLiterals;};inline std::map<int, FilterClause> & getFilterClauses (){ static std::map<int, FilterClause> clauses; return clauses;}The pattern is similar to what we did for the default tags. There is a function called getFilterClauses that returns a reference to a static map of FilterClause objects, and the FilterClause struct is defined to hold a couple of vectors for the normal and inverted literals. The literals are pointers to the tags that we get from cloning.
The createFilterClause function can be implemented to use the collection of clauses, like this:
inline int createFilterClause (){ static int currentId = 0; ++currentId; auto & clauses = getFilterClauses(); clauses[currentId] = FilterClause(); return currentId;}This function keeps track of the current id in a static variable that gets incremented each time the function is called. The only other task that needs to be done is to create an empty filter clause record. The id is returned to the caller so that the filter clause can be modified or cleared later.
The addfilterLiteral function can be implemented like this:
inline void addFilterLiteral (int filterId, Tag const & tag, bool normal = true){ auto & clauses = getFilterClauses(); if (clauses.contains(filterId)) { if (normal) { clauses[filterId].normalLiterals.push_back( tag.clone()); } else { clauses[filterId].invertedLiterals.push_back( tag.clone()); } }}This function makes sure that the clauses collection contains an entry for the given filter id before pushing back a cloned pointer to either the normal or inverted vector.
And the clearFilterClause function is the simplest because it just needs to get the collection and erase whichever filter clause exists with the given id like this:
inline void clearFilterClause (int filterId){ auto & clauses = getFilterClauses(); clauses.erase(filterId);}We still need to examine the filter clauses when logging, and that will be explained in the next section. When following TDD, it’s good to get tests working to the point where the code builds and the tests fail when run. Let’s get the tests to pass in the next section!
Controlling what gets logged
Earlier in this chapter when we were exploring filtering options, I mentioned that we will need a custom stream class instead of returning std::fstream from the log function. We need this so that we don’t immediately send information to the log file. We need to avoid sending a log message directly to the log file because there could be filtering rules in place that could cause the log message to be ignored.
We also decided that we would make the decision to log or not based entirely on the default tags and any tags sent directly to the log function. We could have the log function make the decision and either return std::fstream if the log message should proceed or a fake stream if the log message should be ignored, but it’s probably better to always return the same type. That seems like the simplest and most straightforward solution. Switching between stream types just seems like a more complicated solution that still requires a custom stream type.
And using a custom stream type will also let us fix a nagging problem where we have to put newlines before each log message instead of after. This has resulted in log files with an empty first line and the last line ending abruptly. We went with the temporary solution to put newlines before each log message because we didn’t have anything at the time that would let us know when all the information had been streamed.
Well, a custom stream class will let us solve the nagging newline problem and give us a way to avoid writing log messages directly to the log file. Let’s start with the new stream class. Create this class in Log.h, right before the log functions, like so:
class LogStream : public std::fstream{public: LogStream (std::string const & filename, std::ios_base::openmode mode = ios_base::app) : std::fstream(filename, mode) { } LogStream (LogStream const & other) = delete; LogStream (LogStream && other) : std::fstream(std::move(other)) { } ~LogStream () { *this << std::endl; } LogStream & operator = (LogStream const & rhs) = delete; LogStream & operator = (LogStream && rhs) = delete;};We’re going to fix one problem at a time. So, we’ll continue to refactor this class until it does everything we need. Right now, it just inherits from std::fstream, so it won’t solve the problem of writing directly to the log file. The constructor still opens the log file, and all the streaming capability is inherited from fstream.
What this class does solve is the newline problem. It solves this by sending std::endl to the stream in the class destructor. The constructor that opens the file based on the name provided and the destructor that adds the newline are really the only parts of this class that solve the problem. The rest of the class is needed to get the code to compile and work properly.
Because we added a destructor, that set off a chain reaction of other requirements. We now need to provide a copy constructor. We actually need the move copy constructor because streams tend to act strange when copied. Copying a stream is not a simple task, but moving a stream into another stream is much simpler and does everything we need anyway. We don’t need to make any copies of the stream but we do need to return the stream from the log function, which means the stream either needs to be copied or moved. So, we explicitly delete the copy constructor and implement the move copy constructor.
We also delete both the assignment operator and the move assignment operator because we don’t need to assign the stream either.
We can use the new LogStream class by modifying the log function to look like this:
inline LogStream log (std::vector<Tag const *> tags = {}){ auto const now = std::chrono::system_clock::now(); std::time_t const tmNow = std::chrono::system_clock::to_time_t(now); auto const ms = duration_cast<std::chrono::milliseconds>( now.time_since_epoch()) % 1000; LogStream ls("application.log"); ls << std::put_time(std::gmtime(&tmNow), "%Y-%m-%dT%H:%M:%S.") << std::setw(3) << std::setfill('0') << std::to_string(ms.count()); for (auto const & defaultTag: getDefaultTags()) { if (std::find_if(tags.begin(), tags.end(), [&defaultTag](auto const & tag) { return defaultTag.first == tag->key(); }) == tags.end()) { ls << " " << defaultTag.second->text(); } } for (auto const & tag: tags) { ls << " " << tag->text(); } ls << " "; return ls;}The log function now returns a LogStream instance instead of std::fstream. Inside the function, it creates a LogStream instance as if it were a fstream instance. The only thing that changes is the type. And we now have the file open mode defaulted to append, so we don’t need to specify how to open the file. The name of the stream changed to ls because this is no longer a log file.
And then, when sending the initial timestamp, we no longer need to send an initial std::endl instance and can immediately start with the timestamp.
The only thing different when the test application runs after these changes is that the log file will no longer have an empty first line and all lines will end with a newline.
That’s one small problem fixed. What about the bigger problem of writing directly to the log file? We still want to write to a standard stream because implementing our own stream class adds a lot of complexity we don’t really need right now. So, instead of inheriting the LogStream class from std::fstream, we’ll instead inherit from std::stringstream.
We’re going to need to include sstream to get a definition of stringstream, and we might as well include ostream now too. We’ll need ostream in order to change our streaming helper function in Log.h, which currently uses std::fstream, to look like this instead:
inline std::ostream & operator << (std::ostream && stream, Tag const & tag){ stream << to_string(tag); return stream;}We probably should have implemented this helper function to use ostream from the very beginning. This way, we can stream tags to any output stream. And because both fstream and stringstream are based on ostream, we can use this one helper function to stream to both.
Here are the updated includes for Log.h:
#include <algorithm>#include <chrono>#include <ctime>#include <fstream>#include <iomanip>#include <map>#include <memory>#include <ostream>#include <sstream>#include <string>#include <string_view>#include <vector>Technically, we don’t need to include ostream because we get it already through including fstream and stringstream, but I like to include headers for things we are directly using. And while looking into the headers being included, I noticed that we were including iostream. I think I originally included iostream to get the definition of std::endl, but it seems that endl is actually declared in ostream. So, based on my rule to include headers being used, we should have been including ostream since the very beginning instead of iostream.
Back to LogStream, we need to change this class to inherit from stringstream, like this:
class LogStream : public std::stringstream{public: LogStream (std::string const & filename, std::ios_base::openmode mode = ios_base::app) : mProceed(true), mFile(filename, mode) { } LogStream (LogStream const & other) = delete; LogStream (LogStream && other) : std::stringstream(std::move(other)), mProceed(other.mProceed), mFile(std::move(other.mFile)) { } ~LogStream () { if (not mProceed) { return; } mFile << this->str(); mFile << std::endl; } LogStream & operator = (LogStream const & rhs) = delete; LogStream & operator = (LogStream && rhs) = delete; void ignore () { mProceed = false; }private: bool mProceed; std::fstream mFile;};There is a new data member called mProceed that we set to true in the constructor. Since we no longer inherit from std::fstream, we now need a data member that is a file stream. We also need to initialize the mFile member. The move copy constructor needs to initialize the data members, and the destructor checks if the logging should proceed or not. If the logging should proceed, then the string content of stringstream is sent to the file stream.
We still haven’t implemented the filtering, but we’re getting close. This change gets us to the point where we can control the logging. The logging will proceed unless we call ignore before the destructor is run. This simple change will let us build and test to make sure that we haven’t broken anything.
Running the test application shows the same two test failures as before related to the filtering. The main thing is that the other tests continue to pass, which shows that the changes to use stringstream are working as before when we were streaming directly to the file stream.
It’s important when making pivotal changes such as switching streams to make sure that nothing breaks. This is why I made the change with a hardcoded choice to always log. We can use the TDD tests we already have to verify that the stream change works before making more changes to add filtering.
Let’s take the next change to the log function in two parts. We’re going to need the full collection of active tags after figuring out which of the default tags have been overridden. Instead of sending the tags to the stream, we can first put them into an active collection, like this:
inline LogStream log (std::vector<Tag const *> tags = {}){ auto const now = std::chrono::system_clock::now(); std::time_t const tmNow = std::chrono::system_clock::to_time_t(now); auto const ms = duration_cast<std::chrono::milliseconds>( now.time_since_epoch()) % 1000; LogStream ls("application.log"); ls << std::put_time(std::gmtime(&tmNow), "%Y-%m-%dT%H:%M:%S.") << std::setw(3) << std::setfill('0') << std::to_string(ms.count()); std::map<std::string, Tag const *> activeTags; for (auto const & defaultTag: getDefaultTags()) { activeTags[defaultTag.first] = defaultTag.second.get(); } for (auto const & tag: tags) { activeTags[tag->key()] = tag; } for (auto const & activeEntry: activeTags) { ls << " " << activeEntry.second->text(); } ls << " "; // Filtering will go here. return ls;}This not only gets us the active collection, but it also seems simpler. We let the map handle the overrides by first putting all the default tags into the map and then putting all the provided tags into the map. Building and running the test application shows that the change hasn’t broken anything new. So, we’re ready for the next part, which is comparing the filtering clauses with the active tags.
The filtering needs to change the last part of the log function where the comment indicates that filtering will go, like this:
bool proceed = true; for (auto const & clause: getFilterClauses()) { proceed = false; bool allLiteralsMatch = true; for (auto const & normal: clause.second.normalLiterals) { // We need to make sure that the tag is // present and with the correct value. if (not activeTags.contains(normal->key())) { allLiteralsMatch = false; break; } if (activeTags[normal->key()]->text() != normal->text()) { allLiteralsMatch = false; break; } } if (not allLiteralsMatch) { continue; } for (auto const & inverted: clause.second.invertedLiterals) { // We need to make sure that the tag is either // not present or has a mismatched value. if (activeTags.contains(inverted->key())) { if (activeTags[inverted->key()]->text() != inverted->text()) { break; } allLiteralsMatch = false; break; } } if (allLiteralsMatch) { proceed = true; break; } } if (not proceed) { ls.ignore(); } return ls;The logic is a little complicated, and this is a case where I found it easier to implement the logic almost completely instead of trying to break the change into multiple parts. Here’s what the code does. Because we are using DNF logic, we can treat each clause separately. We start out as if we will proceed with the log, just in case there are no filters set at all. If there are any filters, then for each one, we start out as if we will not proceed. But we also set a new bool variable that assumes that all the literals will match until proven otherwise. We’ll treat a clause without any literals as a sign that we should proceed with the log.
For checking the literals, we have two types: normal and inverted. For the normal literals, the tags must all be present in the active tags and have matching values. If any tag is missing or has the wrong value, then we did not match all the literals for this clause. We’ll continue because there might be another clause that will match. This is what I mean about treating each clause separately.
Assuming we matched all the normal literals, we must still check the inverted literals. Here, the logic is reversed, and we need to make sure that either the tag is not present or that it has the wrong value.
Once we’ve checked all the clauses or found a clause that matches all the literals, the code makes one last check to see if the log should proceed or not. If not, then we call ignore, which will stop the log message from being sent to the output log file.
This approach makes a decision about whether or not to proceed at the time that the log function is called based on the default tags and tags sent to the log function. We’ll let the calling code send whatever information is desired to the stream. The information will only make it all the way to the output log file if ignore was not called.
Everything builds and runs now, and we get all tests passing again, like this:
Running 1 test suites--------------- Suite: Single Tests------- Test: Message can be tagged in logPassed------- Test: log needs no namespace when used with LogLevelPassed------- Test: Default tags set in main appear in logPassed------- Test: Multiple tags can be used in logPassed------- Test: Tags can be streamed to logPassed------- Test: Tags can be used to filter messagesPassed------- Test: Overridden default tag not used to filter messagesPassed------- Test: Simple message can be loggedPassed------- Test: Complicated message can be loggedPassed-----------------------------------Tests passed: 9Tests failed: 0This shows that the filtering is working! At least, for the equality of the tags. Testing whether or not a tag is present with a matching value is a good start, but our microservices developer will need more power than this. Maybe we will need to log only if a count tag has a value greater than 100 or some other comparison that involves a numeric value greater or lesser than a specified filter value. This is what I meant when I said that I implemented the filtering logic almost completely. I got the logic and all the loops and breaks working for tag equality. We should be able to use the same basic structure of the code for relative comparisons in the next section.
There’s one more thing to add before we start relative comparisons, and this is important. Whenever code is added like what I did with the DNF logic without a test to back it up, we need to add a test. Otherwise, a missed test has a way of getting pushed back until it’s forgotten about completely.
And this new test helped out in another way. It caught a problem with the initial definition of the addFilterLiteral function. The original function defined a bool parameter called invert that had a default value of false. The default value meant that creating a normal literal could leave out the parameter and use the default. But to create an inverted literal, the function required that the true value be passed. This seemed backward to me. I realized that it would make more sense to pass false for this parameter to get an inverted literal, and that true should create a normal literal. So, I went back and changed the function definition and implementation. The test caught a problem with the usage of a function that went unnoticed at first.
Here is the new test that will create an inverted filter:
TEST("Inverted tag can be used to filter messages"){ MereTDD::SetupAndTeardown<TempFilterClause> filter; MereMemo::addFilterLiteral(filter.id(), green, false); std::string message = "inverted "; message += Util::randomString(); MereMemo::log(info) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result);}Building and running shows that the new test passes, and we have confirmed that we can filter log messages that contain a matching tag when the filter is inverted. This test uses the default green tag that is added to log messages and makes sure that the log message does not appear in the output log file because of the presence of the green tag.
The next section will enhance the filtering to allow filtering based on relative values of tags instead of just exact matches.
Enhancing filtering for relative matches
TDD encourages incremental changes and enhancements when designing software. Write a test, get something working, and then write a more elaborate test that enhances the design. We’ve been following a TDD approach to designing the logging library, and the previous section was a great example. We got filtering working in the previous section, but only for tag equality.
In other words, we can now filter log messages based on the presence or absence of a tag that matches a filter literal tag. We compare the tags to see if both the key and value match. That was a great first step because even getting that far required a lot of work. Imagine if we had tried to go all the way and supported, for example, logging only if a count tag had a value greater than 100.
When designing software using TDD, it really helps to look for obvious steps that can be taken and confirmed to work before taking the next step. Some steps might be bigger than others, and that’s okay as long as you don’t go straight to the final implementation because that will only lead to longer development times and more frustration. It’s so much better to confirm some parts of the design work as expected and have tests to make sure those parts continue to work. It’s like building a house with a solid foundation. It’s much better to make sure that the foundation really is solid before building the walls, and you want to have tests to make sure that the walls stay straight while the roof is being added.
We have working tests in place to make sure that basic filtering works. We are testing both normal and inverted literals. We check for matching tags by comparing the text of the tags, which works for all value types. For relative filters such as a count greater than 100, we’re going to need a solution that knows how to compare the values with a numeric check instead of a string match.
We can start by figuring out how to represent a filter literal to check for greater or lesser numeric values. Here is a test that can go in Tags.cpp that sets a filter based on a count greater than 100:
TEST("Tag values can be used to filter messages"){ MereTDD::SetupAndTeardown<TempFilterClause> filter; MereMemo::addFilterLiteral(filter.id(), Count(100, MereMemo::TagOperation::GreaterThan)); std::string message = "values "; message += Util::randomString(); MereMemo::log(Count(1)) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::log() << Count(101) << message; result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::log(Count(101)) << message; result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}What’s new with this test? The main part is the way the Count tag is created. We previously only added a value when creating tags, like this:
Count(100)And because we now need a way to specify if something should have a relative value, we need a place to say what kind of relative value and a method to communicate which relative value to use. I think an enumeration of various relative comparisons should work. We probably don’t need more advanced relative comparisons such as "between" because we can always use DNF to express more elaborate comparisons. For a brief overview of how we’re using DNF, refer to the Designing tests to filter log messages section of this chapter.
At the tag level, all we really need is to know how to compare one value against another. So, it makes sense to specify what type of comparison is needed when constructing a tag, like this:
Count(100, MereMemo::TagOperation::GreaterThan)It might make sense to treat a tag with a comparison operator such as GreaterThan as a completely different type, but I think we can get away with a single type. With this solution, any tag can have a comparison operator, but it only makes sense to specify comparison operators for tags that will be used in filters.
What happens if a regular tag without a comparison operator is used in a filter? Then, we should treat that as an exact match because that’s what the existing tests expect.
Back to the new test. It first creates a filter that should only let a message be logged if it has a count tag with a value greater than 100. It first tries to log a message with a count of only 1, and this is verified to not exist in the log file.
Then, the test creates a count of 101 but does not use the count tag directly in the log function call. This also should not make it to the output log file because we only want to filter on tags that are either default or directly specified when calling log.
And finally, the test calls log with a count tag of 101, and this message is verified to appear in the log file.
Now that we have a test, how will we get it working? Let’s define comparison operations first in Log.h, right before the TagType class, like this:
enum class TagOperation{ None, Equal, LessThan, LessThanOrEqual, GreaterThan, GreaterThanOrEqual};We’ll use the None operation for regular tags that only want to express a value. The Equal operation will act like the existing equality checks between tags. And the real change is to support less than, less than or equal, greater than, and greater than or equal comparisons.
We need to compare one tag with another without worrying about what the tags represent. A good way to do this is to declare a pure virtual method in the Tag class, just like what we did for cloning. The new method is called match and can go right after the clone method, like this:
virtual std::unique_ptr<Tag> clone () const = 0; virtual bool match (Tag const & other) const = 0;Here’s where things get a bit difficult. I had wanted to wrap everything up in the TagType class. The idea was to first check the key of each tag being compared and make sure that the tags were the same. If they have the same key, then check the value. If they don’t have the same key, then they must not match. At least, that was a good plan. I ran into problems when trying to implement the match method in one place that could compare strings with strings, numerics with numerics, and Booleans with Booleans. A tag such as CacheHit has a bool value type, and the only operation that makes sense is Equal comparisons. Tags based on strings need to compare differently than numerics. And if we really want to get elaborate, doubles should compare differently than an int type.
Each derived tag type could know how to compare, but I didn’t want to change the derived types and make them each implement the match method, especially after all the work we went through to avoid the derived types implementing clone. The best solution I came up with was to create an additional set of intermediate classes that derive from TagType. Each new class is based on the type of the value. Since we only support five different tag value types, this is not a bad solution. The main benefit is that the derived tag types that the caller will use are only slightly affected. Here’s a new StringTagType class that inherits from TagType so that you can see what I mean. Place this new class in Log.h, right after the TagType class:
template <typename T>class StringTagType : public TagType<T, std::string>{protected: StringTagType (std::string const & value, TagOperation operation) : TagType<T, std::string>(value, operation) { } bool compareTagTypes (std::string const & value, TagOperation operation, std::string const & criteria) const override { int result = value.compare(criteria); switch (operation) { case TagOperation::Equal: return result == 0; case TagOperation::LessThan: return result == -1; case TagOperation::LessThanOrEqual: return result == 0 || result == -1; case TagOperation::GreaterThan: return result == 1; case TagOperation::GreaterThanOrEqual: return result == 0 || result == 1; default: return false; } }};This class is all about comparing string-based tags with other string-based tags. The class implements a new virtual method I’ll explain in just a moment, called compareTagTypes. The only thing this method has to worry about is how to compare two strings based on an operation. One of the strings is called value and the other is called criteria. It’s important to not mix up the value and criteria strings because, for example, while "ABC" is greater than "AAA", the same is not true the other way around. The method uses the compare method in the std::string class to do the comparisons.
You can see that the StringTagType class inherits from TagType and passes on the T derived type while hardcoding std::string for the value type. One interesting thing about the constructor is the need to repeat the template parameters when constructing TagType in the constructor initialization list. Normally, this should not be required, but maybe there is some arcane rule that only applies here that I’m not aware of whereby the compiler does not look at the TagType parameters in the parent class list to figure out the template parameters.
Before moving on to the changes in TagType, let’s look at how a derived tag class such as LogLevel will use the new StringTagType intermediate class. Change the LogLevel class to look like this:
class LogLevel : public StringTagType<LogLevel>{public: static constexpr char key[] = "log_level"; LogLevel (std::string const & value, TagOperation operation = TagOperation::None) : StringTagType(value, operation) { }};The only change needed for LogLevel is to change the parent class from TagType to the more specific StringTagType. We no longer need to worry about specifying std::string as a template parameter because that information is built into the StringTagType class. I had wanted to keep the derived tag classes completely unchanged, but this slight modification is not so bad because there is no need to write any comparison code.
There is more work to be done in the TagType class. In the protected section at the end of the TagType class, make these changes:
protected: TagType (ValueT const & value, TagOperation operation) : Tag(T::key, value), mValue(value), mOperation(operation) { } virtual bool compareTagTypes (ValueT const & value, TagOperation operation, ValueT const & criteria) const { return false; } ValueT mValue; TagOperation mOperation;};The protected constructor needs to store the operation, and this is where the virtual compareTagTypes method is declared and given a default implementation that returns false. The TagType class also implements the match method that was declared in the Tag class, like this:
bool match (Tag const & other) const override { if (key() != other.key()) { return false; } TagType const & otherCast = static_cast<TagType const &>(other); if (mOperation == TagOperation::None) { switch (otherCast.mOperation) { case TagOperation::None: return mValue == otherCast.mValue; default: return compareTagTypes(mValue, otherCast.mOperation, otherCast.mValue); } } switch (otherCast.mOperation) { case TagOperation::None: return compareTagTypes(otherCast.mValue, mOperation, mValue); default: return false; } }The match method first checks the keys to see whether the two tags being compared have the same key. If the keys match, then the types are assumed to be the same and the other tag is cast to the same TagType.
We have a couple of scenarios to figure out. At least one of the tags should be a normal tag without an operation and is the tag we’ll call the value. The other tag can also be a regular tag without an operation, in which case all we need to do is compare the two values for equality.
If one of the two tags is normal and the other has a comparison operation other than None, then the tag with the comparison operator set is treated as the criteria. Remember that it’s important to know which is the value and which is the criteria. The code needs to handle the case where we are comparing a value with a criterion or the case where we are comparing a criterion with a value. We call into the virtual compareTagTypes method to do the actual comparison, making sure to pass mValue and otherCast.mValue according to which is the normal tag and which is the criteria.
And finally, if both tags have the comparison operator set to something other than None, then we treat the match as false because it doesn’t make sense to compare two criteria tags against each other.
There’s a bit of complexity wrapped up in the match method that I wanted to implement in only one spot. This is why I decided to keep the TagType class and create value type-specific intermediate classes such as StringTagType. The TagType class implements part of the comparison by figuring out what is being compared with what and then relies on the type-specific classes to do the actual comparison.
We need to add other type-specific intermediate tag classes. All of these go in Log.h, right after the StringTagType class. Here is the one for the int type:
template <typename T>class IntTagType : public TagType<T, int>{protected: IntTagType (int const & value, TagOperation operation) : TagType<T, int>(value, operation) { } bool compareTagTypes (int const & value, TagOperation operation, int const & criteria) const override { switch (operation) { case TagOperation::Equal: return value == criteria; case TagOperation::LessThan: return value < criteria; case TagOperation::LessThanOrEqual: return value <= criteria; case TagOperation::GreaterThan: return value > criteria; case TagOperation::GreaterThanOrEqual: return value >= criteria; default: return false; } }};This class is almost identical to the StringTagType class with changes designed for an int type instead of a string. Mainly, the comparisons can be done with simple arithmetic operators instead of calling the string compare method.
I thought about using this class for all the int, long long, and double arithmetic types, but that would have meant it would still need a template parameter for the actual type. Then, the question becomes one of consistency. Should the StringTagType class also have a template parameter to specify the type of string? Maybe. There are different kinds of strings so that almost makes sense. But what about the bool type? We’ll need an intermediate class for Booleans too, and it seems strange to specify a bool template type when the class name will already have bool in it. So, to make everything consistent, I decided to go with separate intermediate classes for all the supported types. We’ll handle ints with the IntTagType class and create another class called LongLongTagType, like this:
template <typename T>class LongLongTagType : public TagType<T, long long>{protected: LongLongTagType (long long const & value, TagOperation operation) : TagType<T, long long>(value, operation) { } bool compareTagTypes (long long const & value, TagOperation operation, long long const & criteria) const override { switch (operation) { case TagOperation::Equal: return value == criteria; case TagOperation::LessThan: return value < criteria; case TagOperation::LessThanOrEqual: return value <= criteria; case TagOperation::GreaterThan: return value > criteria; case TagOperation::GreaterThanOrEqual: return value >= criteria; default: return false; } }};This is the class I am not very happy about because it duplicates exactly the implementation for ints. But the one thing I am happy about is the consistency it creates. It means that all the intermediate tag-type classes can be used the same way.
The next class is for doubles, and while it also has the same implementation, there is the potential to compare doubles differently because they don’t compare like the integral types. There is always a little room for errors and slight discrepancies between floating-point values. For now, we’re not going to do anything different about doubles, but this class will give us the ability to compare them differently if needed. The class looks like this:
template <typename T>class DoubleTagType : public TagType<T, double>{protected: DoubleTagType (double const & value, TagOperation operation) : TagType<T, double>(value, operation) { } bool compareTagTypes (double const & value, TagOperation operation, double const & criteria) const override { switch (operation) { case TagOperation::Equal: return value == criteria; case TagOperation::LessThan: return value < criteria; case TagOperation::LessThanOrEqual: return value <= criteria; case TagOperation::GreaterThan: return value > criteria; case TagOperation::GreaterThanOrEqual: return value >= criteria; default: return false; } }};The last intermediate tag type class is for Booleans, and it does need to do something different. This class is really only interested in equality and looks like this:
template <typename T>class BoolTagType : public TagType<T, bool>{protected: BoolTagType (bool const & value, TagOperation operation) : TagType<T, bool>(value, operation) { } bool compareTagTypes (bool const & value, TagOperation operation, bool const & criteria) const override { switch (operation) { case TagOperation::Equal: return value == criteria; default: return false; } }};Now that we have all the tags worked out, the place where comparison needs to be made is in the log function, which currently uses the text of the tags to compare the normal and inverted tags. Change the normal block to look like this:
for (auto const & normal: clause.second.normalLiterals) { // We need to make sure that the tag is // present and with the correct value. if (not activeTags.contains(normal->key())) { allLiteralsMatch = false; break; } if (not activeTags[normal->key()]->match(*normal)) { allLiteralsMatch = false; break; } }The code still loops through the tags and checks for the existence of the keys involved. Once it finds that the tags exist and need to be compared, instead of getting the text of each tag and comparing for equality, the code now calls the match method.
The inverted block needs to change in a similar manner, like this:
for (auto const & inverted: clause.second.invertedLiterals) { // We need to make sure that the tag is either // not present or has a mismatched value. if (activeTags.contains(inverted->key())) { if (activeTags[inverted->key()]->match( *inverted)) { allLiteralsMatch = false; } break; } }For the inverted loop, I was able to simplify the code a little. The real change is similar to the normal loop where the match method is called to make the comparison instead of directly comparing the tag text.
Before we can build and try out the new test, we need to update the other derived tag types in the test application. Just like how we needed to update the LogLevel tag class to use the new intermediate tag class, we need to change all the tag classes in LogTags.h. The first is the Color class, like this:
class Color : public MereMemo::StringTagType<Color>{public: static constexpr char key[] = "color"; Color (std::string const & value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : StringTagType(value, operation) { }};The Color class is based on a string value type, just like LogLevel.
The Size tag type also uses a string and looks like this now:
class Size : public MereMemo::StringTagType<Size>{public: static constexpr char key[] = "size"; Size (std::string const & value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : StringTagType(value, operation) { }};The Count and Identity tag types are based on an int type and a long long type respectively, and they look like this:
class Count : public MereMemo::IntTagType<Count>{public: static constexpr char key[] = "count"; Count (int value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : IntTagType(value, operation) { }};class Identity : public MereMemo::LongLongTagType<Identity>{public: static constexpr char key[] = "id"; Identity (long long value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : LongLongTagType(value, operation) { }};And finally, the Scale and CacheHit tag types are based on a double type and a bool type, and look like this:
class Scale : public MereMemo::DoubleTagType<Scale>{public: static constexpr char key[] = "scale"; Scale (double value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : DoubleTagType(value, operation) { }};class CacheHit : public MereMemo::BoolTagType<CacheHit>{public: static constexpr char key[] = "cache_hit"; CacheHit (bool value, MereMemo::TagOperation operation = MereMemo::TagOperation::None) : BoolTagType(value, operation) { }};The changes to each tag type were minimal. I think this is acceptable, especially because the tests that use the tag types don’t need to change. Let’s take another look at the test that started this section:
TEST("Tag values can be used to filter messages"){ MereTDD::SetupAndTeardown<TempFilterClause> filter; MereMemo::addFilterLiteral(filter.id(), Count(100, MereMemo::TagOperation::GreaterThan)); std::string message = "values "; message += Util::randomString(); MereMemo::log(Count(1)) << message; bool result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::log() << Count(101) << message; result = Util::isTextInFile(message, "application.log"); CONFIRM_FALSE(result); MereMemo::log(Count(101)) << message; result = Util::isTextInFile(message, "application.log"); CONFIRM_TRUE(result);}This test should make more sense now. It creates a Count tag with a value of 100 and a TagOperation tag of GreaterThan. The operation is what makes this tag into a criteria tag that can be compared with other instances of the Count tag to see if the count in the other instance is really greater than 100 or not.
Then, the test tries to log with a normal Count tag with a value of 1. We know now how this will fail the match, and the log message will be ignored.
The test then tries to log with a Count tag of 101, but this time, the tag is outside of the log function and will not be considered. The second log message will also be ignored without ever trying to call match.
The test then tries to log with a count of 101 inside the log function. This one should match because 101 is indeed greater than 100, and the message should appear in the output log file.
Notice how the test is structured. It starts out with a couple of known scenarios that should not succeed before finally moving on to a scenario that should succeed. This is a good pattern for you to follow when writing your tests and helps to confirm that everything is working as designed.
The filtering is now working completely even with relative comparisons! The rest of this chapter will provide insights and advice to help you design better tests.
When is testing too much?
I remember a story I heard once about a child that was in a hospital in intensive care and was connected to all the monitoring machines, including one that watched the heartbeat electrical signals. The child’s condition took a sudden turn for the worse and showed all the signs of a lack of blood flow to the brain. The doctors couldn’t figure out why because the heart was beating, and they were about to send the child for a scan to look for a blood clot that would cause a stroke when one doctor thought to listen for a heartbeat. There was none. The machine showed that the heart was beating but there was no sound to confirm the beat. The doctors were able to determine that swelling around the heart was putting pressure on the heart and preventing it from beating. I don’t know how, but they reduced the swelling and the child’s heart started pumping again.
Why does this story come to mind? Because the machine that monitored heart activity was looking for electrical signals. In normal circumstances, the presence of proper electrical signals is a great way to monitor heart activity. But it’s indirect. Electrical signals are how the heart beats. The signals cause the heart to beat, but as the story shows, they don’t always mean that the heart is beating.
It’s easy to fall into the same trap with software testing. We think that because we have a lot of tests, the software must be well-tested. But are the tests really testing the right things? In other words, is each test looking for tangible results? Or are some tests instead looking at how the results would normally be obtained?
When is testing too much? My answer is that testing is good, and every test that you can add will normally help to improve the quality of the software. Testing can become too much if it starts looking at the wrong things.
It’s not that a test that is looking at the wrong thing is bad. The bad part comes when we rely on that test to predict some outcome. It’s much better to directly confirm the desired outcome than it is to confirm some internal step along the way.
For example, have a look at a recent test that added a filter literal:
TEST("Tag values can be used to filter messages"){ MereTDD::SetupAndTeardown<TempFilterClause> filter; MereMemo::addFilterLiteral(filter.id(), Count(100, MereMemo::TagOperation::GreaterThan));We could have verified that a filter was indeed added to the collection. We have access to call the getFilterClauses function from within the test and examine each clause and look for the literal just added. We could even confirm that the literal itself behaves as expected and has the value 100 assigned to the literal.
The test doesn’t do this. Why? Because that is how filters work. Looking for a filter in the collection would be like watching heartbeat electrical signals. The ability to call getFilterClauses is a detail that exists just because of our desire to keep the logging library contained in a single header file. The function is not intended to be called by customers. The test instead looks at the results of setting the filter.
Once the filter is set, the test tries to log a few messages and makes sure that the results match the expectations.
What if the logging library needed some type of custom collection? Would it make sense to test that the filter literal was properly added to the collection then? Again, my answer is no, at least not here in the filter test.
If the project needed a custom collection, then it would need tests to make sure that the collection works. I’m not saying to skip the tests for any code that needs to be written just because that code serves a supporting role within a project. What I am saying is to keep the tests focused on what they are testing. What is the desired outcome that the test is looking to confirm? In the case of the filters test, the desired outcome is that some log messages will be ignored while others will appear in the output log file. The test directly sets up the conditions needed to confirm the outcome, causes the needed steps to be run, and confirms the outcome. Along the way, the collection and all the matching code will be tested too in an indirect manner.
If we have a custom collection involved, then indirect testing is not enough. But direct testing inside the filter test is also not appropriate. What we need is a set of tests designed to directly test the custom collection itself.
So, if we have a need for a supporting component such as a custom collection, then that component needs to be tested by itself. The tests can be included in the same overall test application. Maybe put them into their own test suite. Think about the code that will be using the component as a customer of the component and think about the customer’s needs.
If the component is big enough or serves a more general purpose so that it might be useful outside of the project, then giving it a project on its own is a good idea. This is what we’re doing in this book by treating the unit test library and the logging library as separate projects.
One final thought about when testing is too much will help you to identify when you are in this situation because it can be easy to slide into too much indirect testing. If you find that you need to change a lot of tests after refactoring how your software works, then you could be testing too much.
Think about how this chapter added filters and was able to keep the existing tests almost entirely unchanged. Sure—we had to change the code underneath by adding a whole set of intermediate tag-type classes, but we did not have to rewrite the existing tests.
If a refactor causes the tests to also need a lot of work, then either you are testing too much or the problem could be that you are changing the desired usage of the software. Be careful of changing how you want your design to be used, because if you are following TDD, then that initial usage is one of the first things you want to get right. Once you have the software designed in a way that makes it easy and intuitive to use, then be extra cautious about any refactoring that would cause changes to the test.
The next section explains a topic related to this section. Once you know what needs to be tested, a question that often comes up next is how to design software to make it easy to be tested, and specifically, if the tests need to reach inside the inner workings of the components being tested.
How intrusive should tests be?
There is a benefit to designing software that is easy to test. To me, this starts by following TDD and writing tests first that make use of the software as the customer would most expect it to be used. This is the most important consideration.
You don’t want to make the user of your software question why extra steps are needed or why it is difficult to understand how to use your software. And by customer or user, I mean anybody that will use your software. A customer or user could be another software developer who needs to use a library that is being designed. The tests are a great example of what a user must go through. If there is an extra step that a user must take that provides no value to the user, then that step should be removed, even if the step makes it easier to test the code.
Maybe the extra step can be hidden from the user, and if so, then it might make sense to keep it as long as it makes the testing better. Anytime a test relies on something extra that the user doesn’t need or know about, then the test is intruding on the software design.
I’m not saying this is a bad thing. Intrusion often has a negative meaning. It can be good for a test to be able to reach inside a component as long as you are aware that this makes it easy to fall into the trap that the previous section describes: too much testing.
The main thing to understand is that anything that a test uses should become part of a supported interface. If a component exposes an inner working so that it can be confirmed by a test, then this inner working should be accepted as part of the design and not some internal detail that is subject to change at any time.
The difference between what this section describes and the previous section comes down to what is agreed to be supported. We get into too much testing when we try to test things that either should be tested someplace else or that are internal details and should be off-limits to testing. If there’s an internal detail that is stable and agreed should not change, and if that internal detail makes testing more reliable, then it might make sense for a test to use the detail.
I remember one project I worked on many years ago that exposed the internal state of classes through Extensible Markup Language (XML). The state could be quite complicated at times, and using XML let the tests confirm that the state was configured correctly. The XML would then be passed to other classes that would make use of it. The user was not aware of the XML and did not need to use it, but the tests relied on it to break complicated scenarios in half. One half of the test could make sure that the configuration was correct by verifying the XML matched. The other half could then make sure that the actions taken worked properly when supplied with known XML input data.
The software did not have to be designed like this to use XML. It could even be said that the tests intruded on the design. The XML became a supported part of the design. What could have been just a detail became something more. But I would go further and say that the use of XML in this case never started out as a detail. It was a conscious design decision that was added for the specific reason of making the testing more reliable.
So far, we’ve only explored unit tests. That’s why this book starts out by building a unit test library. When considering what should be tested and how intrusive the tests should be, there are other types of tests that the next section will begin explaining.
Where do integration or system tests go in TDD?
Sometimes, it’s good to create a test that brings together multiple components and confirms that the overall system being built works as expected. These are called integration tests because they integrate multiple components to make sure they work well together. Or, the tests can be called system tests because they test the entire system. The two names are mostly interchangeable with each other.
For our microservice developer who is the target customer of the logging library, there will likely be unit tests for an individual service, and even unit tests for various classes and functions inside the service. Some of the tests for a particular service might even be called integration tests, but usually, an integration test will be working with multiple services. The services should work together to accomplish something bigger. So, having tests that make sure the overall results can be reached will help improve the reliability and quality of all the services involved.
What if you’re not building a set of microservices? What if you’re building a desktop application to manage a cryptocurrency wallet? You can still make use of system tests. Maybe you want a system test that opens a new wallet and makes sure it can synchronize the blockchain data up to the current block, or maybe you want another system test that stops the synchronization and then resumes it again. Each of these tests will make use of many different components such as classes and functions in the application. System tests make sure that some higher-level goal can be accomplished and, more importantly, system tests use real data that is downloaded over the network.
It’s common for a system test to take a long time to complete. Add in multiple system tests, and the entire set of tests might need several hours to run. Or, maybe there are tests that continuously use the software for a day or more.
Whether or not a particular test is called a unit test or a system test often comes down to how long it takes to run and which resources are needed. Unit tests tend to be quick and are able to determine whether something passes without needing to rely on other external factors or components. If a test needs to request information from another service, then that’s a good sign that the test is more of an integration test instead of a unit test. A unit test should never need to download data from a network.
When it comes to TDD, in order for a test to actually drive the design—as the name implies—then the test will normally be of the unit test variety. Don’t get me wrong—system tests are important and can help uncover strange usage patterns that can be missed by unit tests. But the typical system test or integration test is not intended to make sure that the design is easy to use and intuitive. Instead, a system test makes sure that a higher-level goal can be reached and that nothing breaks the ultimate goals.
If there’s any difference between system tests and integration tests, then in my mind, it comes down to integration tests being all about making sure that multiple components work well together, while a system test is more about the higher-level goals. Both integration tests and system tests are at a higher level than unit tests.
TDD makes more use of unit tests when creating the initial designs of small components and functions. And then, TDD makes use of system and integration tests to make sure that the overall solution makes sense and works properly.
You can think of all the testing we are doing for the logging library as system tests for the unit test library. We’re making sure that the unit test library can actually help design another project.
As for where to put system or integration tests, they normally belong in a different test project—something that can be run on its own. This could even be a script. If you put them in the same test project as the unit tests, then there needs to be some way to only run the unit tests when a quick response is needed.
Other than system and integration tests, there are still more tests you’ll want to consider adding. The next section describes more types of tests.
What about other types of tests?
There are still more types of tests to consider, such as performance testing, load testing, and penetration testing. You can even get into usability testing, upgrade testing, certification testing, continuous operation testing, and more, including types that I’ve probably never heard of.
Each type of test has a purpose that is valuable to software development. Each type has its own process and steps, ways of running the test, and ways to verify success.
A performance test might pick a specific scenario such as loading a large file and making sure that the operation can complete within a certain amount of time. If the test also checks to make sure that the operation completes by only using a certain amount of computer memory or CPU time, then it starts becoming more of a load test, in my opinion. And if the test makes sure that the end user doesn’t have to wait or is notified of a delay, then it starts becoming more of a usability test.
The lines between the test types sometimes are not clear. The previous section already explained that system tests and integration tests are often the same thing, with a subtle distinction that often doesn’t matter. The same is true of other tests. For example, whether a particular test is a load test or a performance test often comes down to the intent. Is the test trying to make sure that an operation completes in a certain time? Who decides what time is good enough? Or, is the test trying to make sure that an operation can complete while other things are going on at the same time? Or, maybe for a test that loads a large file, a large file of several megabytes is used for performance testing because that is a typical large file that a customer might encounter, while a load test would try to load a file much larger. These are just some ideas.
Penetration tests are a little different because they are normally created as part of an official security review. The whole software solution will be analyzed, lots of documents produced, and tests created. A penetration test is often trying to make sure that the software does not crash when malicious data is provided or when the system is misused.
Other penetration tests will check for information disclosure. Is it possible to misuse the software so that an attacker gains knowledge that should have remained confidential?
Even more important are penetration tests that catch data manipulation. A common example is students trying to change their grades, but this type of attack can be used to steal money or delete critical information.
Elevation-of-privilege attacks are super important to prevent penetration testing because they let an attacker gain access that can lead to more attacks. When an attacker is able to take control of a remote server, this is an obvious elevation of privilege, but elevation of privilege can be used to gain any extra permissions or capabilities that an attacker would not normally have.
Usability tests are more subjective and often involve customer interviews or trials.
All of the various different types of tests are important, and my goal with this section is not to list or describe every type of test possible but to give you an idea of the types of testing available and which benefits different tests can provide.
Software testing is not a question of which tests to use but where each type fits into the process. An entire book could be written about each of these test types, and many have been written. There’s a reason this book is so focused on unit testing: because unit tests are closest to the TDD process.
Summary
The TDD process is much more important than the features added to the logging library in this chapter. We added log levels, tags, and filtering, and even refactored the design of the logging library. And while all of this is valuable, the most important thing to pay attention to is the process involved.
The reason this chapter is so detailed is so that you can see all the decisions that went into the design and how tests were used to guide the entire process. You can apply this learning to your own projects. And if you also use the logging library, then that’s a bonus.
You learned the importance of understanding the needs of the customer. A customer doesn’t have to be a person who walks into a store to buy something. A customer is the intended user of whatever software is being developed. This could even be another software developer or another team within your company. Understanding the needs of the intended user will let you write better tests that solve those needs.
It’s very easy to write a function or design an interface that seems appropriate, only to find it difficult to use later. Writing the tests first helps to avoid usage problems. And you saw in this chapter a place where I still had to go back and change how a function worked because a test showed it to be backward.
There was an extensive set of changes needed to support filtering log messages by value, and this chapter showed how to make changes while keeping the tests unchanged.
One of the best ways to understand TDD is to use the process in a project. This chapter developed a lot of new code for the logging library to give you a front-row view into the process and gives you more than simple examples could ever show.
The next chapter will explore dependencies and will extend the logging library to send log messages to more than a single log file destination.