Table of Contents

This blog post will show you how to create a robust and scalable logging library using lots of Modern C++ techniques. The author successfully used this code on Arduino embedded environment and various other production areas.

Let’s dive right in.

Written by Stephen Dolley

Stephen works with C++ commercial and government development teams to upgrade their skills and improve the expressiveness and robustness of their code. He is semi-retired and has enough work, so he keeps a low profile.

Requirements  

The origins of this library lie in my embedded systems development work. I needed a flexible and easy-to-use logging system for collecting usage and performance data during product development. I found it so helpful that I created a version (described in this post) for non-embedded systems which use the STL. (It is a cause of deep frustration for many that the STL is unsuitable for embedded systems due to the way exceptions have been implemented. A solution has been proposed by Herb Sutter.)

  • The requirement was for a logger class that would permit me to have several different active loggers for different purposes, for instance, logging to console and logging to several different files.
  • I needed string and number formatting, insertion of the date/time, and automatic tab insertion.
  • I also needed to support the insertion of UDT’s into the log, such that they would write their state in a pre-formatted way.
  • Furthermore, for time-critical logging where file buffering and possible interleaving of logs can be a problem, I also needed an option to write to my own buffer to give me better control.

The streaming idiom was the obvious choice, so I wrote my operator overloads to implement this for my embedded environment (Arduino).

The STL provides a well-known and easily extensible stream infrastructure, so implementing it using the STL is fairly straightforward.

Usage  

To get the idea and motivation of what we want to achieve, here’s a small code sample that shows how to use the library.

First we open the logging namespace and provide Meyers-singletons to provide access to our logger objects. In this example, two loggers are created:

namespace logging {
  Logger& logger() {
     static Console_Logger std_log{};
     return std_log;
  }

  Logger& file1_logger() {
    static File_Logger logFile{ R"(C:\LF1_)", L_flush};
    return logFile;
  }
}

The first logger shown uses the defaults providing a clog console which starts as a null-logger. The file-logger defaults to mirroring the file-log to a clog-console. The L_flush flag activates the logger (which otherwise starts as a null-logger).

int main(){
  logger() << L_time << "Console_Logger is null" << endl;
  logger().activate();
  logger() << L_location << "Console_Logger is active\n";
  file1_logger() << L_tabs << "Start" << "File" << 1 << L_flush;
}

Manipulation Flags  

In addition to the STL string manipulation flags such as endl, left, hex and setw we support the following:

  • L_time insert current date & time,
  • L_location insert file-name, function name etc,
  • L_tabs insert tabs between fields,
  • L_concat remove L_tabs flag,
  • L_cout for derived classes, only log to cout,
  • L_flush an endl with flush-buffer.

These flags are all cleared by an endl or flush or streaming L_clearFlags.

The logger is constructed with its initial flag state. For instance, L_null starts it as a null-logger which can then be activated or deactivated with a call to .activate(bool). L_startWithFlushing starts it with flushing at every endl until an explicit flush (L_flush or .flush()) is called (typically early in main()). This aids debugging during start-up.

Flush on every endl can be set by streaming the L_allwaysFlush flag.

So, starting at the top of the logging header file we have:

enum Flags { 
    L_clearFlags, 
    L_concat, 
    L_time, 
    L_flush, 
    L_endl, 
    L_startWithFlushing, 
    L_null, 
    L_cout = 8, 
    L_tabs = 16, 
    L_allwaysFlush = 32 
};

Enum member scope has to be considered, as names should be constrained to the scope in which they are used (c-style enum member names escape the scope of the enum body). The options are to use the c-style enum or a C++11 class-enum and give it a namespace-scope or a class scope. For ease of use, the logger object must be available as a namespace-scope object and the flags available without further scoping. That eliminates both class enums and making the enum a logger-class member. To constrain the scope of the enum members, we use a logging namespace which the client can expose with a using directive:

using namespace logging;

The first eight member values (L_clearFlags, L_concat, L_time, L_location, L_flush, L_endl, L_startWithFlushing, L_null) are consumed once processed and take default compiler-supplied values. The remaining 3 (L_cout, L_tabs, L_allwaysFlush) are not consumed; they are given powers-of-two values so that they may be combined as flags. We thus have a combination of standard enum and flag enum. Flag enums do not get direct support in C++, but we can easily write the operators we wish to support to allow semantic addition and subtraction of flags:

inline Flags operator +=(Flags & l_flag, Flags r_flag) { 
    return l_flag = static_cast<Flags>(l_flag | r_flag); 
}

inline Flags operator -=(Flags & l_flag, Flags r_flag) { 
    return l_flag = static_cast<Flags>(l_flag & ~r_flag); 
}

L_location is handled differently. It is a #define macro expanded to a function-call with the current location as arguments. Depending on the compiler c++20 compliance (discovered using __cpp_lib_source_location from <version>), this will be either __FILE__, __LINE__ and __func__ or the C++20 source_location::current(). The macro could be avoided by streaming the function-call location(), but to maintain consistency, I want to stream only a name. If anyone can offer a C++ mechanism that avoids using a macro, I would be pleased to hear of it.

Logger  

The basic Logger class provides null-logging and is derived from to create functional logging classes; it is constructed with the initial flags to set the start-up condition, defaulted to L_null - the null-logger:

using Streamable = std::ostream;

class Logger {
public:
    void activate(bool makeActive = true) { 
        makeActive ? _flags -= L_null : _flags += L_null;
    }

    Flags addFlag(Flags flag) { return _flags += flag; }
    Flags removeFlag(Flags flag) { return _flags -= flag; }

    virtual void flush() { 
        stream().flush(); 
        _flags -= L_startWithFlushing; 
    }

    virtual bool open() { return false; } 

    template<typename T> Logger& log(T value);

    Logger& operator <<(Flags);
    Logger& operator <<(decltype(std::endl<char, std::char_traits<char>>)) {
        return *this << L_endl;
    }
  
    Logger& operator <<(decltype(std::hex) manip) {
       stream() << manip; 
       return *this;
    }

    Logger& operator <<(decltype(std::setw) manip) {
        stream() << manip; return *this;
    }

    virtual Streamable& stream();

    using ostreamPtr = Streamable*;

    virtual Logger* mirror_stream(ostreamPtr& mirrorStream) {
        mirrorStream = nullptr; 
        return this; 
    }

protected:
    Logger(Flags initFlag = L_null) : _flags{ initFlag } {}
    Logger(Flags initFlag = L_null, Streamable& = std::clog)
        : _flags{ initFlag } {}

    virtual Logger& logTime();

    template<class T> 
    friend Logger& operator <<(Logger& logger, T value);

    bool is_tabs() const { return _flags & L_tabs || has_time(); }
    bool is_null() const { return _flags == L_null; }
    bool is_cout() const { return _flags & L_cout; }
    bool has_time() const { return (_flags & 7) == L_time; }

    friend class FileNameGenerator;

    static tm* getTime();

    struct Log_date {
        unsigned char dayNo;
        unsigned char monthNo;
    } inline static log_date{ 0,0 };

    Flags _flags = L_startWithFlushing;
};

In addition to streaming general values, flags, and std:: manipulators, the public interface provides member functions for activating and deactivating the logger, adding and removing flags, and flushing.

Streaming Operators  

The manipulator streaming operators make use of decltype to deduce the types for std::hex, dec & oct which are functions, similarly for setw, setprecision and many other manipulators that take an integer argument:

Logger& operator <<(Flags);
Logger& operator <<(decltype(std::hex) manip) {
  stream() << manip; return *this;
}

Logger& operator <<(decltype(std::setw) manip) {
  stream() << manip; return *this;
}

std::endl is also a function call and requires its own operator. Contrary to common practice, the C++ core guidelines say that endl should only be used where a flush is required since it is defined as performing a flush. Instead, \n should be used for non-flushing “endlines”. In my logging class, flush is only called when explicitly asked for, so std::endl is captured and replaced by the L_endl flag, which streams a \n.

Logger& operator <<(decltype(std::endl<char,
std::char_traits<char>>)) {
  return *this << L_endl;
}

Logging of general values is provided by the templated log() member function (described next) and is made streamable by the global streaming operator:

template<typename T>
Logger& operator <<(Logger& logger, T value) {
  return logger.log(value);
}

The public interface is completed with stream() returning the underlying ostream and mirror_stream() which may be used by derived classes to mirror the log to another stream (typically clog for file-loggers):

virtual Streamable& stream(){ return null_ostream; }
using ostreamPtr = Streamable*;
virtual Logger* mirror_stream(ostreamPtr& mirrorStream){
    mirrorStream = nullptr; return this;
}

A static getTime() function populates a static Log_date struct to support log-file naming using the date. These are described later.

log()  

The templated member function, log() allows streaming of any type that provides its own streaming operator. It inserts a tab if required and then sends the supplied value into the required stream. It performs these operations on all mirror_streams in a do-loop:

template<typename T>
Logger& Logger::log(T value) {
    if (is_null()) return *this;
    auto streamPtr = &stream();
    Logger* logger = this;;
    do {
        if (is_tabs()) {
            *streamPtr << "\t";
        }
        *streamPtr << value;
        logger = logger->mirror_stream(streamPtr);
    } while (streamPtr);
    removeFlag(L_time);
    return *this;
}

log() is an example of the Template Method Pattern (nothing to do with template<> functions!). Templated functions cannot be virtual, but can still exhibit polymorphic behavior, as this one does. It does so by calling virtual functions (stream() and mirror_stream()).

Null-Logger  

A null-logger is created by providing a null-buffer to ostream. The Null_Buff class specialises std::streambuf by initialising it with null-pointers and specialising the overflow function to always return not eof. We will return to this function later when we look at the ram-logger.

Ostream provides a constructor taking a streambuf argument, so we construct our null-stream object using our null_buff object.

class Null_Buff : public std::streambuf { 
// derive because std::streambuf constructor is protected
public:
    Null_Buff() { setp(nullptr, nullptr); }
private:
    int_type overflow(int_type ch) override {
return std::char_traits<char>::not_eof(0); 
}
} inline null_buff{};

inline Streamable null_ostream{ &null_buff };

We make use of the C++17 feature inline variables.

This implementation shares a common null_buff and null_ostream object across all logger objects. In a multi-threaded context, this might not be desirable, in which case null_ostream could be made a class member of Logger.

The base Logger class is of no use on its own (since it only provides null-logging), so its constructors are protected, making Logger abstract.

Console_Logger  

Console_Logger is our concrete console-logging class. For efficiency purposes, it defaults to using std::clog - which is buffered and only flushed when full or explicitly flushed.

Alternatively, cout (usually flushed every new line) or cerr (flushes on every operation) may be used.

Console_Logger specialises mirror_stream() to return its _ostream the first time it is called, and then return nullptr.

UDT-streaming operator  

To facilitate streaming of a UDT, all we need to do is provide a suitable namespace-scope operator which takes and returns a Logger reference:

struct Widget { int val = 5;};

Logger& operator <<(Logger& log, const Widget& w) {
    log << "Widget-Object val: " << w.val;
    return log;
}
...
auto widget = Widget{};
logger() << widget << endl;

We turn now to Logging_console.cpp.

Flag handling  

The streaming operator that takes Flags values processes flags in a switch statement:

Logger & Logger::operator <<(Flags flag) {
    if (is_null()) return *this;
    switch (flag) {
    case L_time: logTime(); break;
    case L_flush: 
        _flags = static_cast<Flags>(_flags & L_allwaysFlush); 
        *this << " |F|\n"; 
        flush();
        break;
    case L_endl: {
        if (_flags & L_allwaysFlush) { *this << " |F|"; } 
        else if (_flags == L_startWithFlushing) { 
            *this << " |SF|"; 
        }
        auto streamPtr = &stream();
        Logger* logger = this;
        do {
            *streamPtr << "\n";
            logger = logger->mirror_stream(streamPtr);
        } while (streamPtr);
        if (_flags & L_allwaysFlush || _flags == L_startWithFlushing) 
            flush();
        }
        [[fallthrough]];
    case L_clearFlags:
        if (_flags != L_startWithFlushing) {
            _flags = static_cast<Flags>(_flags & L_allwaysFlush);
        }
        break;
    case L_allwaysFlush: _flags += L_allwaysFlush; break;
    case L_concat:    removeFlag(L_tabs); break;
    default:
        addFlag(flag);
    }
    return *this;
}

You will notice that flushing is logged by inserting |F| or |SF| (Startup-Flush).

  • L_flush inserts an end-line and calls flush() on the stream. It also clears any flags, except L_allwaysFlush.
  • L_endl inserts \n into each mirrored stream. It also performs a flush, and logs it, if L_allwaysFlush or L_startWithFlushing is set.

Logging Time  

The getTime() function obtains system time from ctime using std::localtime.

logTime() makes use of the streaming io-manipulator, std::put_time:

tm* Logger::getTime() {
    std::time_t now = std::time(nullptr);
    auto localTime = std::localtime(&now);
    log_date.dayNo = localTime->tm_mday;
    log_date.monthNo = localTime->tm_mon + 1;
    return localTime;
}

Logger& Logger::logTime() {
    *this << std::put_time(getTime(), "%d/%m/%y %H:%M:%S");
    _flags += L_time;
    return *this;
}

logTime() sets the L_time flag so that log() (above) knows to insert a tab before the value. Having done that, it clears the flag.

For C++20 code, we might want to use the latest Chrono date and calendar support (but it was not fully available at the point of writing this article and the library).

File_Logger  

File_Logger is constructed with a full or partial file path. If no extension is included, .txt is added. File names are generated from the provided filename plus month and day numbers.

Each day a new file is created.

File_Logger provides for mirror-logging either to its templated base-class (which is defaulted to the Console_Logger) or to another logger provided via its constructor:

template<typename MirrorBase = Console_Logger>
class File_Logger : public MirrorBase {
public:
File_Logger(const std::filesystem::path& filePath) 
: File_Logger(fileNameStem, L_null) {}
    File_Logger(const std::filesystem::path& filePath
, Flags initFlags
, Streamable& mirrorStream = std::clog);

    File_Logger(const std::filesystem::path& filePath
, Flags initFlags
, Logger& mirror_chain) 
: File_Logger(fileNameStem, initFlags) {
_mirror = &mirror_chain; 
}

    Streamable& stream() override;
void flush() override;
    Logger* mirror_stream(Logger::ostreamPtr& mirrorStream) override;
    bool open()override;

private:
Logger& logTime() override;

    FileNameGenerator _fileNameGenerator;
    Logger* _mirror = this;
    std::ofstream _dataFile;
};

template<typename MirrorBase>
File_Logger<MirrorBase>::File_Logger(
const std::filesystem::path& fileNameStem
, Flags initFlags
, Streamable& mirrorStream)
    : MirrorBase{ initFlags, mirrorStream }
    , _fileNameGenerator{ filePath }    {
        MirrorBase::stream() << "\nFile_Logger: "
<< _fileNameGenerator.stem() << std::endl;
    }

stream() checks the L_cout flag, and if set only streams to the mirror. Otherwise it checks the file is open:

template<typename MirrorBase>
Streamable& File_Logger<MirrorBase>::stream() {
    if (MirrorBase::is_cout() || !open()) {
        Logger::ostreamPtr streamPtr = &_dataFile;
        mirror_stream(streamPtr);
        return *streamPtr;
    } else return _dataFile;
}

If the day has changed since the current file-name was generated, a new file name is generated:

template<typename MirrorBase>
bool File_Logger<MirrorBase>::open() {
    if (_fileNameGenerator.isNewDay(*this)) _dataFile.close();
    if (!_dataFile.is_open()) {
        _dataFile.open(_fileNameGenerator(*this), std::ios::app)    }
    return _dataFile.good();
}

Generating File Names

File names are delegated to the functor class FileNameGenerator:

class FileNameGenerator {
public:
    static constexpr int FILE_NAME_LENGTH = 8;
    FileNameGenerator(const std::filesystem::path& filePath);
    std::string stem() const { return _fileNameStem; }
    bool isNewDay(Logger& logger) const {
return _fileDayNo != logger.log_date.dayNo; 
}
    int dayNo() const { return _fileDayNo; }
    std::string operator()(Logger& logger);
private:
    std::string _fileNameStem;
    std::filesystem::path _filePath;
    unsigned char _fileDayNo = 0;
};

inline 
FileNameGenerator::FileNameGenerator(const std::filesystem::path& filePath) :
    _filePath{ filePath }    {
    _fileNameStem = _filePath.filename().string();
    _fileNameStem.resize(FILE_NAME_LENGTH - 4);
    if (!_filePath.has_extension()) _filePath += ".txt";
}

inline 
std::string FileNameGenerator::operator()(Logger & logger) {
    if (logger.log_date.dayNo == 0) logger.getTime();
    _fileDayNo = logger.log_date.dayNo;
    auto fileName = std::stringstream{};
    fileName << _fileNameStem << std::setfill('0') << std::setw(2)
<< (int)logger.log_date.monthNo << std::setw(2) 
<< (int)_fileDayNo;
    _filePath.replace_filename(fileName.str()) +=
_filePath.extension();
    return _filePath.string();
}

logTime() is overridden to insert the file-stem before the time for all mirrored streams.

Likewise, flush() is overridden to perform a flush on all mirrored streams.

mirror_stream()  

The polymorphic mirror_stream function is overridden to provide the mirror-stream through its reference argument and pass back the mirror-logger in its return value. Where no mirror-stream has been provided through the constructor, the base-class is the mirror (defaulted to Console_Logger).

mirror_stream checks if the base is the mirror and returns the appropriate values:

template<typename MirrorBase>
Logger* File_Logger<MirrorBase>::mirror_stream(
Logger::ostreamPtr& mirrorStream) {
bool isChainedMirror = this != _mirror;
    if (isChainedMirror) {
        mirrorStream = &_mirror->stream();
        return _mirror;
    } else {
        return MirrorBase::mirror_stream(mirrorStream);;
    }
}

Any number of file-loggers may be chained together through the constructors.

Ram_Buffer  

To support our Ram_Logger we make use of the fact that we can set the underlying stream buffer for an ostream to our own buffer. But to do this we need to create our own Ram_Buffer class derived from std::streambuf because its constructor is protected.

class Ram_Buffer : public std::streambuf {
public:
    Ram_Buffer(char* start, size_t size, Logger& logger)
: _logger(&logger) { setp(start, start + size); }
    
void empty_buffer() { setp(pbase(), epptr()); }
    auto start() const { return pbase(); }
    auto pos() const { return pptr(); }
private:
    int_type overflow(int_type ch) override {
        _logger->flush();
        sputc(ch);
        return std::char_traits<char>::not_eof(0);
    }
    Logger* _logger;
};

The constructor body sets the streambuf pointers to our buffer using setp().

empty_buffer() also uses setp() to reset the pointers to the empty-state.

The crucial part of this class is the override for overflow(). This function is called by the ostream whenever the buffer is full. Its argument is the character it was unable to place in the stream. So we call flush() to write the buffer to the file, then insert the guilty character with sputc() and return a not-at-end-of-file value using the not_eof function to ensure we return a value that will not be interpreted as aneof.

RAM_Logger  

Like File_Logger, Ram_Logger provides mirror-logging to its templated base-class - this time defaulted to the null-logging Logger. It also flushes to a disk file on request or whenever the buffer is full.

The buffer is built on the heap - the class can easily be modified if the class should not take responsibility for allocating the buffer:

template<typename MirrorBase = Logger>
class RAM_Logger : public File_Logger<MirrorBase> {
public:
    RAM_Logger(uint16_t ramFile_size, 
const std::string& fileNameStem, 
Flags initFlags, 
Streamable& ostream = std::clog);

    Streamable& stream() override { return _stream; }
    void flush() override;
private:
    std::unique_ptr<char[]> _ramFile;
    Ram_Buffer _ramBuffer;
    Streamable _stream;
};

The constructor gets the buffer-memory and sets up the Ram_Buffer and ostream:

template<typename MirrorBase>
RAM_Logger<MirrorBase>::RAM_Logger(uint16_t ramFile_size
, const std::string& fileNameStem
, Flags initFlags
, Streamable& ostream)
    : File_Logger<MirrorBase>(fileNameStem, initFlags, ostream)
    , _ramFile(std::make_unique<char[]>(ramFile_size))
    , _ramBuffer(_ramFile.get(), ramFile_size, *this)
    , _stream(&_ramBuffer) 
{}

Flush streams the buffer into the disk-file and resets the buffer:

template<typename MirrorBase>
void RAM_Logger<MirrorBase>::flush() {
    for (char* c = _ramBuffer.start(); c < _ramBuffer.pos(); ++c){
        File_Logger<MirrorBase>::stream() << *c;
    }
    _ramBuffer.empty_buffer();
}

Usage & Examples  

Once everything is completed, let’s try to run this thing :)

First we open the logging namespace and provide Meyers-singletons to provide access to our logger objects:

namespace logging {
    Logger& logger() {
        static Console_Logger std_log{};
        return std_log;
    }

    Logger& file1_logger() {
        static File_Logger logFile{ R"(C:\LF1_)", L_flush};
        return logFile;
    }
}

The first logger shown uses the defaults, so we get a clog console which starts as a null-logger. The second is a file-logger that mirrors to a clog-console, and is immediately activated by a L_flush.

int main(){
    logger() << L_time << "Console_Logger is null" << endl;
    logger().activate();
    logger() << L_location << "Console_Logger is active\n";
    file1_logger() << L_tabs << "Start" << "File" << 1 << L_flush;
}

Next we chain two file-loggers together, and create a 50-byte Ram_logger:

namespace logging {    
    Logger& file2_logger() {
        static File_Logger logFile{ 
"LF2_"
, L_startWithFlushing
, file1_logger() };
        return logFile;
    }    
    
    Logger& ram_logger() {
        static RAM_Logger<Console_Logger> logFile{ 
50, "Ram", L_allwaysFlush };
        return logFile;
    }
}

File2_logger will mirror to file1_logger() which in turn mirrors to the console. Ram_logger mirrors to the console and flushes to a file named “Ram*ddmm*”:

int main(){
    file2_logger() << L_flush << "StartFile2" << endl;
    file2_logger() << L_time << "File2 time" << endl;
    ram_logger() << L_time << "Ram data" << endl;
}

See https://wandbox.org/permlink/apP5xWrq9q6Lk3u7 for working examples.

Summary  

We have seen how the so-called streaming operator can be overloaded both globally and as a class-member function to provide easy-to-use logging facilities. We have seen how the STL formatting options can be extended with our own flags to insert time, location, and automatic tabbing. We have also seen how the base Logger class can be easily extended through inheritance / polymorphism to provide loggers for specific purposes.

Along the way we have encountered design patterns such as:

  • Meyers Singletons (to ensure proper global UDT construction during start-up),
  • template-method pattern,
  • flag-enums
  • null-logging,
  • and modern language features such as
    • raw-string-literals,
    • decltype and auto,
    • constexpr,
    • constructor delegation,
    • in-class inilitialisers, brace-initialisation,
    • unique_ptr and std::make_unique
    • chrono, put_time etc. etc. from C++11.
    • inline static-storage variables,
    • [[fallthrough]] attribute,
    • std::filesystem from C++17,
    • source_location and <version> from C++20.

I’m sure there is much room for improvement, but I hope this blog has stimulated some thought and hopefully discussion about expressive programming in modern C++.

If there is sufficient interest in the Arduino version of this library, perhaps another post might be in order.

Back to you

  • Do you found this logger library valuable? What are the most practical code techniques described?
  • Do you have your custom logger libraries?
  • Or maybe you use some third-party code?

Let us know in the comments below the article.