General Support: Logging
There have already been a few places where the ILogger interface has appeared.
For my personal projects, I considered several options for logging. Simply using a Boost logging model was one possibility, or another third-party option. But I decided I wanted to be able to deal with logging at a very high level, without as such worrying about a mechanism. Above all, I wanted a logging mechanism that I could integrate with unit testing.
So I produced a minimal public interface:
LogSeverity.h:
namespace Log
{
enum class Severity
{
Trace,
Debug,
Informational,
Warning,
Error,
Fatal
};
}
ILogger.h:
namespace Log
{
class ILogger
{
public:
virtual ~ILogger();
virtual void log(const Severity inSeverity,
const std::string &inVal) const = 0;
virtual void log(const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const = 0;
virtual void log(const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const = 0;
};
}
You can log a simple message; you can also log a message tied to a source location (C++20) or a std::error_code value (C++11).
There's a NullObject implementation:
class NullLogger : public ILogger
{
public:
~NullLogger () override;
void log(const Severity inSeverity, const std::string& inVal) const override { }
void log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const override { }
void log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const override { }
};
To handle the common formatting between different types of logging, the formatting is in a separate class:
namespace Log
{
class LoggingFormatter
{
public:
static void PrintTimestamp (std::ostream &outStream, std::chrono::time_point<std::chrono::system_clock> inTime);
static void Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal);
static void Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal,
const std::source_location &inLocation);
static void Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal,
const std::error_code inError);
private:
static std::string_view
convertSeverity (const Severity inValue)
{
using namespace std::literals;
switch (inValue)
{
using enum Severity;
case Trace:
return "TRACE"sv;
break;
case Debug:
return "DEBUG"sv;
break;
case Informational:
return "INFORMATIONAL"sv;
break;
case Warning:
return "WARNING"sv;
break;
case Error:
return "ERROR"sv;
break;
case Fatal:
return "FATAL"sv;
break;
}
return {};
}
};
The implementations are simple:
void
LoggingFormatter::PrintTimestamp (std::ostream &outStream, std::chrono::time_point<std::chrono::system_clock> inTime)
{
const std::time_t t_c = std::chrono::system_clock::to_time_t(inTime);
outStream << std::put_time(std::localtime(&t_c), "%FT%T.");
}
(PrintTimestamp originally attempted to use std::format, but there is no present compiler support for it. The time is a strict ISO format.)
void LoggingFormatter::Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal)
{
outStream << " " << convertSeverity (inSeverity) << ": " << inVal;
}
void LoggingFormatter::Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal,
const std::source_location &inLocation)
{
outStream << " " << convertSeverity (inSeverity) << "["
<< inLocation.file_name () << "(" << inLocation.line () << ":"
<< inLocation.column () << ") " << inLocation.function_name ()
<< "] " << inVal;
}
void LoggingFormatter::Convert (std::ostream &outStream,
const Severity inSeverity,
const std::string &inVal,
const std::error_code inError)
{
if (static_cast<int> (inSeverity)
> static_cast<int> (Severity::Warning))
outStream << " " << convertSeverity (inSeverity);
else
outStream << " WARNING";
outStream << inVal << " <" << inError.message () << ">";
}
The simplest implementation just logs to the console:
namespace Log
{
class ConsoleLogger : public ILogger
{
public:
~ConsoleLogger() override;
void log(const Severity inSeverity, const std::string &inVal) const override;
void log(const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const override;
void log(const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const override;
};
void ConsoleLogger::log(const Severity inSeverity, const std::string &inVal) const
{
std::osyncstream str(std::cerr);
theFormatter.Convert(str, inSeverity, inVal);
str << std::endl;
}
void ConsoleLogger::log(const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const
{
std::osyncstream str(std::cerr);
theFormatter.Convert(str, inSeverity, inVal, inLocation);
str << std::endl;
}
void ConsoleLogger::log(const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const
{
std::osyncstream str(std::cerr);
theFormatter.Convert(str, inSeverity, inVal, inError);
str << std::endl;
}
The only real point of interest is the use of osyncstream to ensure that the messages are handled in a synchronized manner.
The Test Logger
Recorded Actions
I use Boost Test for structuring and supporting my unit tests. To provide for mock classes which can be set up and then checked within that context, I have (in a separate TestSupport library) a header-only class from which mock classes can be derived:
class RecordedActions
{
public:
const std::span<std::string> getActions() const
{
return m_actions;
}
void clearActions()
{
m_actions.clear();
}
std::size_t actionCount() const
{
return m_actions.size();
}
bool hasNoActions() const
{
return m_actions.empty();
}
bool matchesAction(const std::string &inVal, const std::size_t inIndex) const
{
if (inIndex >= m_actions.size())
{
std::cerr << "Index out of bounds: " << inIndex;
if (m_actions.empty())
std::cerr << "; No actions recorded" << std::endl;
else
std::cerr << "; Array size is " << m_actions.size() << std::endl;
return false;
}
if (inVal == m_actions[inIndex])
return true;
std::cerr << "Expected " << inVal << " at index " << inIndex << " received " << m_actions[inIndex] << std::endl;
return false;
}
protected:
void add(const std::string &inAction) const
{
m_actions.push_back(inAction + "()");
}
void add(const std::string &inAction, const std::string &inArg) const
{
m_actions.push_back(inAction + "():" + inArg);
}
void add(const std::string &inAction, int inIntegralValue) const
{
std::ostringstream str;
str << inAction << "():" << inIntegralValue;
m_actions.push_back(str.str());
}
protected:
mutable std::vector<std::string> m_actions;
};
(Yes, I know that std::cerr flushes on write. I still think that passing std::endl when a flush is wanted is a good habit to get into.)
This allows for testing with (assume class Foo derives from RecordedActions):
Foo testable;
// Do stuff iwth testable
BOOST_CHECK_EQUAL(testable.actionCount(), 5);
BOOST_CHECK_EQUAL(testable.matchesAction("call1()", 0);
// etc.
TestLogger
The TestLogger class derives from the RecordedActions class:
class TestLogger : public ILogger, public TestSupport::RecordedActions
{
public:
~TestLogger() override;
void log(const Severity inSeverity, const std::string &inVal) const override;
void log(const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const override;
void log(const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const override;
};
void TestLogger::log (const Severity inSeverity, const std::string &inVal) const
{
std::ostringstream str;
LoggingFormatter ().Convert (str, inSeverity, inVal);
std::string s(str.str());
add ("log<1>", s);
}
void TestLogger::log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const
{
std::ostringstream str;
LoggingFormatter ().Convert (str, inSeverity, inVal, inLocation);
std::string s(str.str());
add ("log<2>", s);
}
void TestLogger::log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const
{
std::ostringstream str;
LoggingFormatter ().Convert (str, inSeverity, inVal, inError);
std::string s(str.str());
add ("log<3>", s);
}
This captures a logging call and the format it would have but does not log the data, isntead storing it as an action which can be verified by the RecordedActions interface.
Logging to File
Of course, logging to console is useful only in a limited number of contexts. So the next level of complexity up is the SimpleLogger class:
class SimpleLogger : public ILogger
{
public:
explicit SimpleLogger (const std::string &inFilename);
~SimpleLogger () override;
void log (const Severity inSeverity, const std::string &inVal) const override;
void log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const override;
void log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const override;
private:
mutable std::ofstream m_str;
};
Implemenattions:
namespace
{
constexpr Log::LoggingFormatter theFormatter;
std::ofstream
OpenFile (const std::string &inVal)
{
std::ofstream rval (inVal);
if (!rval.good ())
throw std::runtime_error ("Could not open " + inVal + " for logging");
return rval;
}
}
namespace Log
{
SimpleLogger::SimpleLogger (const std::string &inFilename)
: m_str (OpenFile (inFilename))
{ }
void SimpleLogger::log (const Severity inSeverity, const std::string &inVal) const
{
std::osyncstream str (m_str);
theFormatter.Convert (str, inSeverity, inVal);
str << std::endl;
}
void SimpleLogger::log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const
{
std::osyncstream str (m_str);
theFormatter.Convert (str, inSeverity, inVal, inLocation);
str << std::endl;
}
void SimpleLogger::log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const
{
std::osyncstream str (m_str);
theFormatter.Convert (str, inSeverity, inVal, inError);
str << std::endl;
}
}
Essentially, it's just the console logger but with output sent to a file instead. Good enough for a simple, single-threaded program or even (given the use of osyncstream) some simple threaded programs.
Threaded Logger
The problem with the simple logger is that the cost of formatting and writing to file occurs on the same thread as the one doing substantive work. If we're logging a major or a fatal error, but it's not so great for informational or even just warning messages.
So there's a threaded logger.
It's built on top of an ILogMsg base class:
class ILogMsg
{
public:
virtual ~ILogMsg ();
virtual void getFormattedOutput(std::ostream& outStream) const = 0;
};
which is handled by a LogMsgQueue class, which uses a condition variable to handle waiting for messages to process:
class LogMsgQueue
{
public:
LogMsgQueue () {}
void
push (std::unique_ptr<ILogMsg>&& inMsg)
{
{
std::lock_guard lock (m_mutex);
m_queue.push (std::move(inMsg));
}
m_condvar.notify_one();
}
std::unique_ptr<ILogMsg> pop()
{
using namespace std::literals;
while (m_queue.empty() && !m_token.stop_requested())
{
std::unique_lock lk(m_mutex);
m_condvar.wait(lk, m_token, [&]{ return !m_queue.empty() || m_token.stop_requested(); });
if (m_token.stop_requested())
return std::make_unique<NullLogMsg>();
std::unique_ptr<ILogMsg> rval(std::move(m_queue.back()));
m_queue.pop();
return rval;
}
return std::make_unique<NullLogMsg>();
}
void setToken(std::stop_token inToken) { m_token = inToken; }
bool stopRequested() { return m_token.stop_requested(); }
private:
std::mutex m_mutex;
std::condition_variable_any m_condvar;
std::queue<std::unique_ptr<ILogMsg>> m_queue;
std::stop_token m_token;
};
The ThreadedLogger has access to a unique queue and a stop source:
class ThreadedLogger : public ILogger
{
public:
~ThreadedLogger () override;
void log (const Severity inSeverity, const std::string &inVal) const override;
void log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const override;
void log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const override;
static void Initialize(const std::string& inFilename);
static void SignalStop();
private:
static inline std::stop_source s_StopSource;
static inline LogMsgQueue s_Queue;
};
On logging, the data is simply pushed to the queue --
void ThreadedLogger::log (const Severity inSeverity, const std::string &inVal) const
{
s_Queue.push (std::make_unique<StringLogMsg> (
inVal, std::chrono::system_clock::now (), inSeverity));
}
void ThreadedLogger::log (const Severity inSeverity, const std::string &inVal,
const std::source_location &inLocation) const
{
s_Queue.push (std::make_unique<LocationLogMsg> (
inVal, std::chrono::system_clock::now (), inSeverity, inLocation));
}
void ThreadedLogger::log (const Severity inSeverity, const std::string &inVal,
const std::error_code inError) const
{
s_Queue.push (std::make_unique<ErrorCodeLogMsg> (
inVal, std::chrono::system_clock::now (), inSeverity, inError));
}
-- for actual processing on a separate thread:
void
ThreadedLogger::Initialize (const std::string &inFilename)
{
s_Queue.setToken (s_StopSource.get_token ());
std::thread t1 ([&] () {
std::ofstream str (inFilename);
if (!str)
throw std::runtime_error ("Could not open " + inFilename
+ " for logging");
while (!s_Queue.stopRequested ())
{
std::unique_ptr<ILogMsg> msg = s_Queue.pop ();
if (!s_Queue.stopRequested ())
msg->getFormattedOutput (str);
else
msg.reset(nullptr);
}
});
t1.detach ();
}
The log messages capture the data to be logged as cheaply as possible, with one constraint: the time of logging is captured on the originating thread. Formatting is deferred until the point of actual logging. E.g.:
class StringLogMsg : public ILogMsg
{
public:
StringLogMsg(const std::string& inMsg,
const std::chrono::time_point<std::chrono::system_clock> inTimestamp,
const Severity inSeverity):
m_msg(inMsg),
m_timestamp(inTimestamp),
m_severity(inSeverity)
{ }
~StringLogMsg () override;
void getFormattedOutput(std::ostream& outStream) const override;
private:
std::string m_msg;
std::chrono::time_point<std::chrono::system_clock> m_timestamp;
Severity m_severity;
};
void StringLogMsg::getFormattedOutput(std::ostream& outStream) const
{
constinit static LoggingFormatter formatter;
formatter.PrintTimestamp(outStream, m_timestamp);
formatter.Convert(outStream, m_severity, m_msg);
}
The threaded logger has been used, but not really stress-tested under real conditions. As is usual with threaded class which haven't undergone a real trial by fire, it probably has gaps...
There is an application which extends the logger model to generate GTK popup dialogs as well as writing to file. But that is outside our immediate scope.
Comments
Post a Comment