C++ logging library

I am creating a logging library in C++, and I wanted your opinion on code quality and performance within some methods.

You may ask why yet another logger - the answer is simple. This logging library that I am developing is not exclusively said to be released, it's purely for my own experience and fun. But if it turns out to be atleast decent, why not.

Here is the code

lwlog.h

#pragma once

#include <iostream>
#include <string>
#include <cctype>

#include "core.h"
#include "detail.h"
#include "datetime.h"
#include "registry.h"

namespace lwlog
{
enum class log_level
{
all =       (1 << 0),
info =      (1 << 1),
warning =   (1 << 2),
error =     (1 << 3),
critical =  (1 << 4),
debug =     (1 << 5),
none =      (1 << 6)
};

static log_level operator |(log_level lhs, log_level rhs)
{
return static_cast<log_level> (
static_cast<std::underlying_type<log_level>::type>(lhs)
| static_cast<std::underlying_type<log_level>::type>(rhs)
);
}

static log_level operator &(log_level lhs, log_level rhs)
{
return static_cast<log_level> (
static_cast<std::underlying_type<log_level>::type>(lhs)
& static_cast<std::underlying_type<log_level>::type>(rhs)
);
}

class LWLOG logger
{
private:
std::string m_message;
std::string m_loggerName;
std::string m_pattern;
std::string m_logLevel;
log_level m_logLevel_visibility = log_level::all;

std::unordered_map<std::string, std::string> m_patterns_data;

private:
void print_formatted(const std::string& message, std::string pattern);

public:
explicit logger(const std::string& name);
~logger();

void set_name(const std::string& loggerName);
void set_logLevel_visibility(log_level logLevel);
void set_pattern(const std::string& pattern);

void info(const std::string& message);
void warning(const std::string& message);
void error(const std::string& message);
void critical(const std::string& message);
void debug(const std::string& message);

inline std::string get_name() const { return m_loggerName; }
inline std::string get_logLevel() const { return m_logLevel; }
};

template<typename... Args>
void print(std::string format_str, Args&&... args)
{
std::vector<std::string> format_string_tokens_vec;
std::vector<int> format_numeric_tokens_vec;

std::regex reg("(\\{\\d\\})");

detail::populate_vec_with_regex_matches_from_str(format_string_tokens_vec, reg, format_str);

detail::string_to_numeric_vec(format_string_tokens_vec, format_numeric_tokens_vec, "{}");

for (int i = 0; i < format_string_tokens_vec.size(); ++i)
{
}

std::cout << format_str;
}
}


lwlog.cpp

#include "lwlog.h"

namespace lwlog
{
logger::logger(const std::string& logger_name)
: m_loggerName(logger_name), m_pattern("[%d, %x] [%l] [%n]: %v")
{
if (registry::instance().is_registry_automatic() == true)
{
registry::instance().register_logger(this);
}
}

logger::~logger()
{
}

void logger::set_name(const std::string& logger_name)
{
m_loggerName = logger_name;
}

void logger::set_logLevel_visibility(log_level logLevel)
{
if (logLevel == log_level::all)
{
m_logLevel_visibility = log_level::info | log_level::warning | log_level::error
| log_level::critical | log_level::debug;
}
else if (logLevel == log_level::none)
{
m_logLevel_visibility = log_level::none;
}
else
{
m_logLevel_visibility = logLevel;
}
}

void logger::set_pattern(const std::string& pattern)
{
m_pattern = pattern;
}

void logger::info(const std::string& message)
{
m_message = message;
m_logLevel = "info";

if (static_cast<std::underlying_type_t<log_level>>(m_logLevel_visibility)
& static_cast<std::underlying_type_t<log_level>>(log_level::info))
{
print_formatted(message, m_pattern);
}
}

void logger::warning(const std::string& message)
{
m_message = message;
m_logLevel = "warning";

if (static_cast<std::underlying_type_t<log_level>>(m_logLevel_visibility)
& static_cast<std::underlying_type_t<log_level>>(log_level::warning))
{
print_formatted(message, m_pattern);
}
}

void logger::error(const std::string& message)
{
m_message = message;
m_logLevel = "error";

if (static_cast<std::underlying_type_t<log_level>>(m_logLevel_visibility)
& static_cast<std::underlying_type_t<log_level>>(log_level::error))
{
print_formatted(message, m_pattern);
}
}

void logger::critical(const std::string& message)
{
m_message = message;
m_logLevel = "critical";

if (static_cast<std::underlying_type_t<log_level>>(m_logLevel_visibility)
& static_cast<std::underlying_type_t<log_level>>(log_level::critical))
{
print_formatted(message, m_pattern);
}
}

void logger::debug(const std::string& message)
{
m_message = message;
m_logLevel = "debug";

if (static_cast<std::underlying_type_t<log_level>>(m_logLevel_visibility)
& static_cast<std::underlying_type_t<log_level>>(log_level::debug))
{
print_formatted(message, m_pattern);
}
}

void logger::print_formatted(const std::string& message, std::string pattern)
{
m_patterns_data.emplace("%d", datetime::get_current_date());
m_patterns_data.emplace("%L", std::string(1, toupper(m_logLevel[0])));
m_patterns_data.emplace("%l", m_logLevel);
m_patterns_data.emplace("%n", m_loggerName);
m_patterns_data.emplace("%v", message);
m_patterns_data.emplace("%x", datetime::get_current_time());

std::vector<std::string> pattern_string_tokens_vec;

std::regex rg("(\\%[DdLlnvx]{1})");

detail::populate_vec_with_regex_matches_from_str(pattern_string_tokens_vec, rg, pattern);

for (int i = 0; i < pattern_string_tokens_vec.size(); ++i)
{
for (auto it = m_patterns_data.begin(); it != m_patterns_data.end(); ++it)
{
if (pattern_string_tokens_vec[i] == it->first)
{
detail::replace_in_string(pattern, pattern_string_tokens_vec[i], it->second);
}
}
}

print("{0} \n", pattern);
m_patterns_data.clear();
}
}


registry.h

#pragma once

#include <vector>
#include <memory>
#include <string>
#include <unordered_map>

#include "core.h"

namespace lwlog
{
class logger;

class LWLOG registry
{
private:
registry() {}
std::unordered_map<std::string, logger*> m_loggersMap;
bool m_automatic_registry = true;

public:
registry(const registry&) = delete;
registry& operator=(const registry&) = delete;

void register_logger(logger* new_logger);

void drop(const std::string& logger_name);
void drop_all();

void set_automatic_registry(bool automatic);

void display_all_loggers();

inline bool is_registry_automatic() { return m_automatic_registry ? true : false; }

static registry& instance()
{
static registry s_instance;
return s_instance;
}
};
}


registry.cpp

#include "registry.h"

#include "lwlog.h"

namespace lwlog
{
void registry::register_logger(logger* new_logger)
{
m_loggersMap.emplace(new_logger->get_name(), new_logger);
}

void registry::drop(const std::string& logger_name)
{
for (auto it = m_loggersMap.begin(); it != m_loggersMap.end(); ++it)
{
if (it->first == logger_name)
{
m_loggersMap.erase(logger_name);
break;
}
}
}

void registry::drop_all()
{
m_loggersMap.clear();
}

void registry::set_automatic_registry(bool automatic)
{
m_automatic_registry = automatic;
}

void registry::display_all_loggers()
{
for (auto it = m_loggersMap.begin(); it != m_loggersMap.end(); it++)
{
print("{0} \n", it->first);
}
}
}


detail.h

#pragma once

#include <regex>
#include <vector>
#include <map>
#include <unordered_set>

namespace detail
{
static void populate_vec_with_regex_matches_from_str(std::vector<std::string>& v, std::regex rg, std::string& s)
{
std::smatch matches;
std::string temp = s;

while (std::regex_search(temp, matches, rg))
{
v.push_back(matches.str(1));
temp = matches.suffix().str();
}
}

template<typename... Args>
{
std::vector<std::string> vec =
{
[](auto && arg)
{
if constexpr (std::is_same_v<std::remove_reference_t<decltype(arg)>, char>)
{
return std::string(1, arg);
}
else if constexpr (std::is_arithmetic_v<std::remove_reference_t<decltype(arg)>>)
{
return std::to_string(std::forward<decltype(arg)>(arg));
}
else
{
return arg;
}
}(std::forward<Args>(args))...
};

for (const auto& i : vec)
{
v.push_back(i);
}
}

template<typename T, typename T1>
void string_to_numeric_vec(std::vector<T>& sv, std::vector<T1>& nv, const char* chars_to_remove)
{
for (int i = 0; i < sv.size(); ++i)
{
std::string temp = sv[i];

for (int i = 0; i < strlen(chars_to_remove); ++i)
{
temp.erase(std::remove(temp.begin(), temp.end(), chars_to_remove[i]), temp.end());
}
nv.push_back(std::stoi(temp));
}
}

template<typename T>
void remove_duplicates_in_vec(std::vector<T>& v)
{
std::unordered_set<T> s;
for (const auto& i : v)
{
s.insert(i);
}

v.assign(s.begin(), s.end());
}

static void replace_in_string(std::string& s, const std::string& to_replace, const std::string& replace_with)
{
size_t index = 0;
while (true)
{
index = s.find(to_replace, index);
if (index == std::string::npos)
{
break;
}
s.replace(index, to_replace.length(), replace_with);
index += to_replace.length();
}
}
}


datetime.h

#pragma once

#include <iomanip>
#include <sstream>
#include <chrono>
#include <ctime>

namespace lwlog
{
namespace datetime
{
static std::string get_current_time_and_date(const char* format)
{
auto now = std::chrono::system_clock::now();
auto in_time_t = std::chrono::system_clock::to_time_t(now);

std::stringstream ss;
ss << std::put_time(std::localtime(&in_time_t), format);
return ss.str();
}

static std::string get_current_time()
{
return get_current_time_and_date("%X");
}

static std::string get_current_date()
{
return get_current_time_and_date("%Y-%m-%d");
}
}
}


core.h

#pragma once

#ifdef _WIN32
#define LWLOG_PLATFORM_WINDOWS
#endif
#ifdef __linux__
#define LWLOG_PLATFORM_LINUX
#endif
#ifdef __APPLE__
#define LWLOG_PLATFORM_MAC
#endif

#ifndef LWLOG
#ifdef LWLOG_PLATFORM_WINDOWS
#if defined(LWLOG_BUILD_DLL)
#define LWLOG __declspec(dllexport)
#elif !defined(LWLOG_BUILD_STATIC)
#define LWLOG __declspec(dllimport)
#else
#define LWLOG
#endif
#else
#if __GNUC__ >= 4
#define LWLOG __attribute__((visibility("default")))
#else
#define LWLOG
#endif
#endif
#endif


And here is the sandbox (example usage) for you to play with the logger

Sandbox.cpp

#include "lwlog/lwlog.h"

int main()
{
std::string str1 = "test";
std::string str2 = "for";

lwlog::print("That's a {0} message {1} you. \n\n", str1, str2);

std::shared_ptr<lwlog::logger> core_logger = std::make_shared<lwlog::logger>("LOGGER");
std::shared_ptr<lwlog::logger> core_ldsdogger = std::make_shared<lwlog::logger>("LOGGER2");
std::shared_ptr<lwlog::logger> core_logaager = std::make_shared<lwlog::logger>("LOGGER3");

lwlog::registry::instance().display_all_loggers();

lwlog::registry::instance().drop("LOGGER2");
lwlog::print("\n");

lwlog::registry::instance().display_all_loggers();

core_logger->set_logLevel_visibility(lwlog::log_level::error | lwlog::log_level::critical);
core_logger->set_pattern("[%x] [%n]: %v");
core_logger->critical("A very critical message!");

return 0;
}


Still, there is no documentation, but I guess it will be simple to navigate since there is a Sandbox project for you to play with the library's features.

Any suggestions, opinions on code quality and performance are welcome, as well as feature suggestions. I suggest taking a closer look in terms of performance into the print method within lwlog.h, and maybe the detail.h file's contents.

P.S. Be aware that I started it a couple of days ago, so It's not so rich in features, so again, any suggestions for features are welcome. When it comes to multithreaded loggers, thread-safety, async and logging in files - I have these features on my mind, will try my best to implement them. Also, colored logs are something I'm working on using the ANSI escape codes.

• If it makes you feel better, my experience with code review is that they don't judge you for "reinventing-the-whee"'. They just help improve your code. – Chipster Jun 8 at 17:47
• Yes, figured that out. I only want constructive critique, opinions and suggestions all for the improvement of the code – Christian Panov Jun 8 at 17:56
• Why is m_message a field? Unless I missed it, nothing ever reads it. Why is m_logLevel a field instead of being passed into the print method like message? If this were ever used from multiple threads, bad things would happen. I guess the intent is that every thread would use its own logger? – David Conrad Jun 9 at 21:10
• @David Not in standard C++. You have to write platform-specific code to get a stack trace from an exception. – Cody Gray Jun 9 at 21:39
• @DavidConrad: See my answer (and my last comment). – einpoklum Jun 10 at 7:38

Lots of good code comments already given. I'll focus on non-code aspects.

Take this from a DevOps engineer that regularly troubleshoots complex, unfamiliar systems from logs under time pressure.

You want all logs to always be consistently formatted and to have timestamp and location (source file and line) by default, it looks like you request the date with format specifiers. You want context if it is available (e.g. request id). You want to easily print non-pod types as well and it looks like that is not possible with your design relying on to_string() which only accepts pods. Typically you'd use a design based on something that inherits from std::ostream so that your regular operator<<(ostream&, const T&) will work.

When I did this AGES ago, I used a custom buffer class that tee'd to a file and cout that I injected into std::clog using rdbuf(...)and then created a set of macros to print location and time like:

 #define ERROR std::clog<<date_time_now()<<", status=ERROR ("<<__FILE__<<":"<<__LINE__<<"): "

ERROR << "Honey, I shrunk the kids! " << m_kids << std::endl;


Macros are the devil but also the only way of getting line number and file name automatically into the log line. Unless there is some new hotness in c++17/2x i don't know off.

Please excuse the brevity and lack of formatting, I'm typing this on a phone.

• Isn't it better to make this macro-like function and drop ; at the end of line? – val Jun 9 at 9:55
• Whatever works for you. The semicolon was unintended force of habit. – Emily L. Jun 9 at 11:24
• Regarding new hotness, source_location has design approval, so there's a good chance we'll see that standardized in time for C++2b and finally have a good way of capturing that information. – chris Jun 10 at 1:56

Separate interface from implementation

The interface goes into a header file and the implementation (that is, everything that actually emits bytes including all functions and data) should be in a separate .cpp file. In this case virtually everything in datetime.h and all static functions in detail.h should actually not be static but should instead be split into .h and .cpp files instead. The same is true for both the log_level operator functions in lwlog.h.

Make sure you have all required #includes

The code uses std::string in datetime.h but doesn't #include <string>. Also, carefully consider which #includes are part of the interface (and belong in the .h file) and which are part of the implementation per the above advice.

Be careful with signed and unsigned

In the current string_to_numeric_vec() routine, the loop integers i is a signed int value, but it's being compared with quantity format_string_tokens_vec.size() which returns a std::size_t. Better would be to declare i as std::size_t.

Fix the bugs

Right now, the remove_duplicates_in_vec routine incorrectly reverses the order of the passed parameters so the message printed says "That's a for message test you." which is clearly not what was intended. Also, if we call it like this:

lwlog::print("That's a {0} message {1} you. \n\n", str1, "{1}");


It prints "That's a test message test you." which is also suspect.

Reconsider the approach

The use of the regex and unordered_set and vector variables in this seem overly complicated to me. A lot of wasted work is done as well, such as setting up all of the variables in print_formatted instead of just the ones that are actually used. Further, the use of variadic templates instead of variadic functions means that there is considerable code bloat. On my 64-bit Linux box using gcc with -O2 optimizations, adding these five lines adds over 11120 bytes to the size of the executable.

    lwlog::print("{0}\n", 1);
lwlog::print("{0}\n", 1.0f);
lwlog::print("{0}\n", 1u);
lwlog::print("{0}\n", 1l);
lwlog::print("{0}\n", "no");


Also, this code is not thread safe. If I were writing this, I would probably start with something like std::basic_osyncstream.

Use const where practical

There are a few places, such as the reg declaration in print that would be better as static const.

Avoid relative paths in #includes

Generally it's better to omit relative path names from #include files and instead point the compiler to the appropriate location.

#include "lwlog/lwlog.h"


For gcc, you'd use -I. This makes the code less dependent on the actual file structure, and leaving such details in a single location: a Makefile or compiler configuration file.

Omit return 0 at the end of main

In both C and C++, the compiler will automatically create the code that is the exact equivalent of return 0; so it can safely be omitted.

• Man, I hate that omitting the return statement at the end of the main function has become standard fare on Code Review. It is not good advice. Yes, it's legal and the compiler will silently generate the equivalent code on your behalf, but that doesn't make it a good idea. Good code is clear and explicit. Therefore, good code should return EXIT_SUCCESS at the end of the main function. – Cody Gray Jun 9 at 6:25
• @Edward no, but void functions do not return an int somewhere else as main() does to the OS. We do write "return 0;" at the end of each function that returns an int. – Mavrik Jun 9 at 8:50
• @Edward main doesn't return void, it turns int. void is valueless, int is not. This is why we omit return void;  at the end of void returning functions even though it's allowed. Your question is a strawman. It doesn't motivate why we shouldn't be explicit about the return from main. – Emily L. Jun 9 at 8:54
• @Edward I do not have a problem with you omitting the return or what type of code you value. What I'm concerned about is that omitting it is being presented as if it was best practice while it is clearly not established as such. It is a personal preference that is being passed on as general advice, and I believe that's misinformation. – Emily L. Jun 9 at 11:36
• I’ll think about a better way to convey the idea in future answers. Thanks all for your feedback. – Edward Jun 9 at 12:08
• Making functions in header files static means that each translation unit gets its own separate definition. This usually isn't what we want. Standard practice is to declare the function in the header, and then define it in a .cpp file, e.g.:

// header:

#include <string>

namespace lwlog
{
namespace datetime
{
std::string get_current_time_and_date(const char* format);
}
}


.

// .cpp:

#include <iomanip>
#include <sstream>
#include <chrono>
#include <ctime>

namespace lwlog
{
namespace datetime
{
static std::string get_current_time_and_date(const char* format)
{
auto now = std::chrono::system_clock::now();
auto in_time_t = std::chrono::system_clock::to_time_t(now);

std::stringstream ss;
ss << std::put_time(std::localtime(&in_time_t), format);
return ss.str();
}
}
}


While this is a pain in the butt, it means that anyone including datetime.h doesn't also get the sstream chrono, etc. headers as an unnecessary side-effect.

• Prefer to declare variables as close to the point of use as possible, and (ideally) assign the necessary value directly, e.g. for the local variables in the print function.

• Descriptive names are nice, but something like detail::populate_vec_with_variadic_params is probably overkill. Maybe detail::string_vec_from_args instead? Likewise with the local variables: variadic_arguments_vec -> arguments, format_string_tokens_vec -> format_tokens.

The various detail functions used to print with could be simplified quite a bit:

• Rather than populate_vec_with_variadic_params we can define our own to_string function, and then do something like:

namespace detail
{

std::string to_string(std::string s) { return s; }

template<class T>
std::string arg_to_string(T&& t)
{
using detail::to_string;
using std::to_string;
}

} // detail

...

auto arguments = std::vector<std::string>{ detail::arg_to_string(std::forward<Args>(args))... };


This has the advantage of allowing users to specify to_string functions for their own classes too.

• populate_vec_with_regex_matches_from_str:

• shouldn't take s by reference, as it doesn't change s (this allows us to eliminate the temp variable).
• should simply return a vector, instead of altering one.
• should use iterators to avoid unnecessary copies (both internally, and in the vector it returns).
• rather than capturing the curly brackets and then removing them later, we can just capture the number inside the curly brackets.
• we need to capture one or more digit inside the brackets, not a single digit character, or the function will stop working when we get to 10 arguments.

using substring_view = std::pair<std::string::const_iterator, std::string::const_iterator>;

std::vector<substring_view> find_matches(std::regex rg, std::string const& s)
{
auto result = std::vector<substring_view>();

auto begin = s.cbegin();
auto const end = s.cend();

std::smatch match;
while (std::regex_search(begin, end, match, rg))
{
result.push_back({ match[1].first, match[1].second });
begin = match.suffix().first;
}

return result;
}

...

auto format_strings = detail::find_matches(std::regex("\\{(\\d+)\\}"), format_str);


• remove_duplicates_in_vec:
• can be a call to std::unique.
• should be applied to format_strings_tokens_vec instead of variadic_arguments_vec!!! We want to remove duplicate indices, not duplicate arguments.

• string_to_numeric_vec:

• could use std::transform.
• should produce indices of std::size_t (a.k.a. std::vector<T>::size_type), not int.
• should probably do some sort of error handling on conversion failure (even just assertions).
• std::from_chars is probably the best standard converter available for this.

std::vector<std::size_t> convert_indices(std::vector<substring_view> const& s)
{
auto result = std::vector<std::size_t>(s.size(), 0);

auto convert = [] (substring_view const& v)
{
auto const begin = &*v.first;
auto end = &*v.second;
auto value = std::size_t{ 0 };
auto result = std::from_chars(begin, end, value);

assert(result.ptr == end);
assert(result.ec == std::errc{ });

return value;
};

std::transform(s.begin(), s.end(), result.begin(), convert);

return result;
}


• replace_in_string is called for every format token index, and iterates over the whole string each time, turning the complexity from O(n) to O(n^2). Yikes!

We'll be doing much less work if we do the "replacement" at the same time as we do the regex search.

So I'd probably do something like this:

#include <cassert>
#include <charconv>
#include <iostream>
#include <regex>
#include <string>
#include <vector>

namespace detail
{

std::string to_string(std::string s) { return s; }

template<class T>
std::string arg_to_string(T&& t)
{
using detail::to_string;
using std::to_string;
}

std::size_t convert_index(std::string::const_iterator begin, std::string::const_iterator end)
{
auto value = std::size_t{ 0 };
auto result = std::from_chars(&*begin, &*end, value);

assert(result.ptr == &*end);
assert(result.ec == std::errc{ });

return value;
};

} // detail

template<typename... Args>
std::string format(std::string const& format_str, Args&&... args)
{
auto const arguments = std::array<std::string, sizeof...(Args)>{ detail::arg_to_string(std::forward<Args>(args))... };

auto arguments_total_size = std::size_t{ 0 };
for (auto const& a : arguments)
arguments_total_size += a.size();

auto result = std::string();
result.reserve(format_str.size() + arguments_total_size);

auto begin = format_str.cbegin();
auto const end = format_str.cend();
auto const regex = std::regex("\\{(\\d+)\\}");

while (true)
{
std::smatch match;
if (!std::regex_search(begin, end, match, regex))
break;

result.append(match.prefix().first, match.prefix().second);

auto index = detail::convert_index(match[1].first, match[1].second);
result.append(arguments.at(index));

begin = match.suffix().first;
}

result.append(begin, end);

return result;
}

int main()
{
std::cout << format("test: {0}, {1}, {0}, {3}", "5", 5, 123.f, std::string("test")) << std::endl;
}


N.B. We could just send everything straight to std::cout instead of building the formatted string.

Support logging stack traces - it's easy!

Standard C++ offers no facilities for obtaining stack traces, so traditionally - logging libraries and manual logging have foregone those. But these traces are extremely useful in inspecting logs and debugging programs (despite their verbosity); and developers in other languages, especially non-compiled ones, ridicule us for not having them!

Well, recently, Antony Polukhin (of magic_get fame) has undertaken the task of combining the available platform-specific stack walking libraries into a single multi-platform Boost library named stacktrace. Its plain vanilla use is as simple as:

#include <boost/stacktrace.hpp>

// ... etc. etc. ...

std::cout << boost::stacktrace::stacktrace();


and it has facilities for decorating exceptions with stack traces etc.

Consider using string views instead of std::string references

If you pass a temporary string to a function taking a const string&, but then initialize some std::string with it, you get - yes, you know it - you get a string copy. And indeed, it seems you do just that.

Also, std::string's live on the heap. Do you really want to be making a bunch of heap allocations? Surely not; or at least - as few as possible. What's more, you may be forcing whoever is passing you the string to construct an std::string and to know about std::string. I would try to avoid that too.

So, what's the alternative? std::string_view. It's not perfect (in the sense you have to be a little careful when using it), but it's a pretty good idea still:

How exactly is std::string_view faster than const std::string&?

if you're writing pre-C++17 code, you can find a string view in implementations of the Guidelines Support Library.

You have some good answers already. My criticism comes from one word. "printf".

The problem for fault-finding is not just knowing what each part has reported, but also knowing in what order they happened. Any practical logging library is going to hit threads sooner or later, and at that point things go wrong.

For starters, we need to think about thread-safe printing. The behaviour of printf when called from two threads simultaneously is not defined, but typically you'll find one interrupts the other mid-print to print its own text, then the next one finishes. The result is not very readable.

And we also need to think about "Heisenbugs" where the test code changes the behaviour of the system so that your fault-finding is invalidated. printf is relatively slow, so by the time it's done, a second thread whose interaction caused the bug you're investigating would be in a completely different state.

And lastly, you might want your logging to in several different directions. Perhaps you want normal level messages to go to the screen, verbose to go to the main log file, and critical messages to go to a secure registry. You can't do that here.

I've built a logging library myself to sort these problems. (This was a few years ago, when the libraries available were less good.) There were several key features:-

• The function logging an error in a thread stored the log details.
• The function then passed that atomically to a singleton log store which pushed the log details into a FIFO. (Actually a FIFO of pointers, because you don't want to waste time copying stuff.)
• At regular intervals and at low priority, the log store popped a batch of FIFO entries and sent them to one or more registered log printers.
• Each log printer had options for setting log levels it was interested in.Running in separate threads and again at low priority, each dumped details of those logs it was interested in to its chosen destination.

So it became quite a complex structure, and the output side needed to be much more heavyweight, but the result was to make logging during execution almost unnoticeable. This allowed us to use our logging to accurately fault-find issues happening between threads in an application controlling hardware, databases, user interface, files, etc..