A Lightweight Logger for C++

http://www.drdobbs.com/cpp/a-lightweight-logger-for-c/240147505?pgno=1

Building a lightweight, thread-safe logger that can be redirected to different I/O channels.

In this article, I want to discuss the importance of providing a logging component in your software project. From a very general point of view, any software can be developed in a way that allows the running code to provide a trace of its execution in a log file, then depending on the life phase of the product (development or production), it may be released with a different level of logging set. Having a logger becomes crucial when debugging is not possible or is inconvenient. Under some circumstances, debugging is not possible — for example, because the application runs on specific hardware or the problem is completely unclear. In those cases, collection and analysis of logs is crucial to pinpointing a problem.

At Nokia Siemens Networks, I developed the firmware running on NSN's Base Transceiver Station (BTS). A BTS is very complex hardware driven by impressive firmware. When something does not work (especially in a real network), there is no way to check where the problem traces back other than reading the BTS logs, a common logging platform every subsystem shares with all the other components, which provides prints on different severity levels.

A logger should be effective, efficient, and able to provide clear data. Most importantly, it has to guarantee proper functioning even when the whole system crashes. It makes no sense to write logs if the logger stops running at every crash. The logging platform, like the captain of a sinking ship, must "survive" until the end.

In this article, I develop a small logger that provides two levels of logging and three types of log severity (Error, Warning, and Debug). The code has been used in different projects of different sizes, is thread-safe, computationally lightweight, and easily customizable to work with different log output (to allowing remote logging for example).

Dr. Dobb's has previously published another implementation of a good C/C++ logger (seeLogging In C++ and Logging In C++: Part 2). There are few important differences between what you'll see here and that solution. First and most important, the logger discussed here will flush the log messages immediately and will not buffer them, which is crucial when a serious destabilizing event occurs. (The implementation provided in Logging In C++: Part 2provides the ability to enable or disable a single log print at runtime. The way this feature is implemented is very clever and I encourage you all to take a look at both articles.) Another difference in my implementation is that I use only C++ and STL functionalities (no Boost libraries). To understand the code presented, I expect that you'll be familiar with the variadic template concept of the new C++ standard.

First Look

What a logger should print depends on the kind of application it's written for. In my projects, I've used it to provide at least: the sequential numbering for the logged lines, date, and execution time elapsed since the beginning of the logging period (expressed in ms, it is also very useful to check the execution time for single operations), and some information about the severity of the logged item.

Making a call to the log function should be easy. The logger should be as little invasive as possible, both for the programmer than for the code. If you take a look at Listing One, you'll see how to invoke the logger function just by using the proper c-style macro:

Listing One: logger.hpp.

#ifndef LOGGER_HPP
#define LOGGER_HPP

#include "log.hpp"

static logging::logger< logging::file_log_policy > log_inst( "execution.log" );

#ifdef LOGGING_LEVEL_1

#define LOG log_inst.print< logging::severity_type::debug >
#define LOG_ERR log_inst.print< logging::severity_type::error >
#define LOG_WARN log_inst.print< logging::severity_type::warning >

#else

#define LOG(...) 
#define LOG_ERR(...)
#define LOG_WARN(...)

#endif

#ifdef LOGGING_LEVEL_2

#define ELOG log_inst.print< logging::severity_type::debug >
#define ELOG_ERR log_inst.print< logging::severity_type::error >
#define ELOG_WARN log_inst.print< logging::severity_type::warning >

#else

#define ELOG(...) 
#define ELOG_ERR(...)
#define ELOG_WARN(...)

#endif

#endif

Line 4 shows a static instantiation of the logger class. The logger is a template that needs to be parameterized with a logging policy. In this case, I'm using a file logging policy, which means that all the output of the logger will be directed to a file on the physical disk.

Lines 6-8 and 15-17 are where the logging macros are defined. As you can see, there are two logging levels (the second level may be enabled to have a more verbose output), and three severity levels. The preferred logging level may be enabled or disabled by toggling theLOGGING_LEVEL_x definition. When those macro definitions are absent, a log invocation attempt will be resolved by the preprocessor in the usage of the definitions visible at lines 10-12 and 19-21, which do no logging.

Listing Two shows an example of the logger usage and the relative output:

Listing Two: Example.

#define LOGGING_LEVEL_1
#include "logger.hpp"

int main()
{
   LOG("Starting the application..");
   for( short i = 0 ; i < 3 ; i++ )
   {
   LOG("The value of 'i' is ", i , ". " , 3 - i - 1 , " more iterations left ");
   }
   LOG_WARN("Loop over");
   LOG_ERR("All good things come to an end.. :(");
   return 0;
}

Output:

0000000 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :Starting the application..
0000001 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 0. 2 more iterations left 
0000002 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 1. 1 more iteration left 
0000003 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <DEBUG> :The value of 'i' is 2. 0 more iterations left 
0000004 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <WARNING> :Loop over
0000005 < Wed Jan 09 12:33:18 2013 - 0000005 > ~ <ERROR> :All good things come to an end.. :(

The Logging Policy

Listing Three shows the policy interface and the implementation for the file policy, which uses a C++ ofstream to direct the log messages to the disk.

Listing Three: Log policy.

class log_policy_interface
{
       public:
       virtual void		open_ostream(const std::string& name) = 0;
       virtual void		close_ostream() = 0;
       virtual void		write(const std::string& msg) = 0;
};

class file_log_policy : public log_policy_interface
{
       std::unique_ptr< std::ofstream > out_stream;
    public:
        file_log_policy() : out_stream( new std::ofstream ) {}
        void open_ostream(const std::string& name);
        void close_ostream();
        void write(const std::string& msg);
        ~file_log_policy();
};

A logging policy should use a pure abstract class to describe how the interface for the policy works (line 5). This logger "policy" provides functionality related to the log writing, as the logger does not know where its output will be directed: Whether to disk, RAM, or even tunneled by a socket to a remote computer, it just calls a "write" function in the provided policy.

The policy interface simply provides three functions to open and close an output stream and a write operation. For the file logging policy, the code will use the C++ std::ofstream to direct the output to the disk. The complete implementation for the file logging policy is visible in the Listing Four.

Listing Four: The file log policy implementation.

void file_log_policy::open_ostream(const std::string& name)
{
   out_stream->open( name.c_str(), std::ios_base::binary|std::ios_base::out );
   if( !out_stream->is_open() ) 
   {
        throw(std::runtime_error("LOGGER: Unable to open an output stream"));
   }
}

void file_log_policy::close_ostream()
{
    if( out_stream )
    {
        out_stream->close();
    }
}

void file_log_policy::write(const std::string& msg)
{
    (*out_stream)<<msg<<std::endl;
}

file_log_policy::~file_log_policy()
{
    if( out_stream )
    {
        close_ostream();
    }
}

There's nothing special to comment on here. If the stream-opening operation fails, the function throws a std::runtime_error (line 6). Obviously, a different behavior can be provided.

In this implementation, an exception is thrown exception because the logging facility in my applications is not optional, but crucial (as it is for the firm I work for). In fact, the logging functionalities are seen as features of the software that the customer will use, so if this feature is not working properly, then it is often right to abort the application startup.

The Core Printing Functionality

Every call to a logging macro will be expanded in an invocation of the print function of the logger instance. This function actually does some formatting activities on the log message and use the write function from the used policy to stream out the log string. The Listing Five shows the print function implementation.

Listing Five: The print function.

template< typename log_policy >
    template< severity_type severity , typename...Args >
void logger< log_policy >::print( Args...args )
{
    write_mutex.lock();
    switch( severity )
    {
        case severity_type::debug:
             log_stream<<"<DEBUG> :";
             break;
        case severity_type::warning:
             log_stream<<"<WARNING> :";
             break;
        case severity_type::error:
             log_stream<<"<ERROR> :";
             break;
    };
    print_impl( args... );
    write_mutex.unlock();
}

Here, you should be familiar with the variadic functions: print is a variadic, which actually accepts as formal argument the parameter pack Args and one more template argument,severity. Actually, severity is an enum, which can be one of three values as shown in Listing Six:

Listing Six: The severity_type enum.

enum severity_type
{
   debug = 1,
   error,
   warning
};

The severity provided as a template parameter is used in the switch statement at line 6 of Listing Five to add the proper severity description to the log message: debug ,warning, orerror. The variable log_stream used in the print function implementation is an attribute of the logger class, actually of a std::stringstream type. The first operation at line 5 is a lock request to write_mutex, this is needed to ensure thread safety by guaranteeing that no more than one print operation is performed at the same time. This lock is released at line 19 after the operation has finished. Please note that the locking request is a blocking operation if the mutex is already acquired by a different thread, a wait-free version can use a buffering system to store the log messages until the lock is released. The call to print_impl at line 18 is show next in Listing Seven.

Listing Seven: print_impl implementation.

template< typename log_policy >
void logger< log_policy >::print_impl()
{
    policy->write( get_logline_header() + log_stream.str() );
    log_stream.str("");
}

template< typename log_policy >
    template<typename First, typename...Rest >
void logger< log_policy >::print_impl(First parm1, Rest...parm)
{
    log_stream<<parm1;
    print_impl(parm...);	
}

If you're not familiar with the variadic functions, you might not be able to understand why this function has two bodies. It's done this way to access the parameters in the variadic parameter pack. If you look at line 12, you'll see that the function is recursive, and at every call the first argument expanded from parm... is used to, let's say, fill parm1, while all the others are filling the argument pack Rest... .

The value of parm1 is stored at line 11, then the recursion happens again with one parameter less. At a certain point, Rest... will be empty, the last value will be printed and the last call to print_impl performed. If parm... is empty, the recursion is ended by an invocation of the print_impl version that started at line 1. This print_impl version just makes a call to the write function of the logging policy, passing a std::string consisting of a log message preceded by the header, which contains data like the timestamp, the log line number, and so on.

The Logger Template

Now, let's look at the logger template body (Listing Eight), and at the implementation of the support functions that are used by the print operation.

Listing Eight: Logger template body.

template< typename log_policy >
class logger
{
    unsigned log_line_number;
    std::string get_time();
    std::string get_logline_header();
    std::stringstream log_stream;
    log_policy* policy;
    std::mutex write_mutex;

    //Core printing functionality
    void print_impl();
    template<typename First, typename...Rest>
    void print_impl(First parm1, Rest...parm);
public:
    logger( const std::string& name );

    template< severity_type severity , typename...Args >
    void print( Args...args );

    ~logger();
};

Lines 4-9 provide a private function and visible attributes such as log_line_number just to keep track of the current line number; for each print invocation the number will be increased by one. Get_time and get_logline_header are support functions used to format the log message header, and they are implemented in Listing Nine.

Listing Nine: get_time and get_logline_header implementation.

template< typename log_policy >
std::string logger< log_policy >::get_time()
{
    std::string time_str;
    time_t raw_time;
    time( & raw_time );
    time_str = ctime( &raw_time );
    //without the newline character
    return time_str.substr( 0 , time_str.size() - 1 );
}

template< typename log_policy >
std::string logger< log_policy >::get_logline_header()
{
    std::stringstream header;
    header.str("");
    header.fill('0');
    header.width(7);
    header << log_line_number++ <<" < "<<get_time()<<" - ";
    header.fill('0');
    header.width(7);
    header <<clock()<<" > ~ ";
    return header.str();
}

Going back to Listing Eight, at line 10-13, the declaration of print_impl is visible, followed at line 15 by the logger-constructor declaration. Lisiting Ten shows the constructor and destructor bodies.

Listing Ten: The logger constructor and destructor.

template< typename log_policy >
logger< log_policy >::logger( const std::string& name )
{
   log_line_number = 0;
   policy = new log_policy;
   if( !policy )
    {
       throw std::runtime_error("LOGGER: Unable to create the logger instance"); 
    }
    policy->open_ostream( name );
}

template< typename log_policy >
logger< log_policy >::~logger()
{
    if( policy )
    {
       policy->close_ostream();
       delete policy;
    }
}

Note that if the allocation at line 5 fails and it is not possible to create a log_policy object, then a std::runtime_error is thrown. As previously explained, no exception handling is performed here — after all, if this small logger is not able to allocate the amount of memory required by log_policy, then something very weird is happening.

Conclusion

The simple logger described in this article can be used easily in any project to track code behavior during runtime, I think that its Achilles' heel is actually the need to lock the writing mutex in the print function. From one perspective, this is unavoidable because not all operating systems are able to provide atomic stream operations, but it introduces a source of inefficiency.

I think that a good logger should always provide a near constant execution time in any circumstance, which is problematic when threads might have to wait for mutexes to be released. However, in practice, unless numerous threads are logging, the operations are fast enough that there is no significant delay.

The source code for this article was tested with g++ 4.7.2 and requires the C++11 multithread functionality support to work properly; refer to http://tehsausage.com/mingw-std-thread-gcc-4-7 if you get into trouble when compiling this project.