Logging In C++

Going Generic

Another issue with the implementation we built so far is that the code is hardwired to log to stderr, only stderr, and nothing but stderr. If your library is part of a GUI application, it would make more sense to be able to log to an ASCII file. The client (not the library) should specify what the log destination is. It's not difficult to parameterize Log to allow changing the destination FILE*, but why give Log a fish when we could teach it fishing? A better approach is to completely separate our Log-specific logic from the details of low-level output. The communication can be done in an efficient manner through a policy class. Using policy-based design is justified (in lieu of a more dynamic approach through runtime polymorphism) by the argument that, unlike logging level, it's more likely you decide the logging strategy upfront, at design time. So let's change Log to define and use a policy. Actually, the policy interface is very simple as it models a simple string sink:

static void Output(const std::string& msg);

The Log class morphs into a class template that expects a policy implementation:

template <typename OutputPolicy>
class Log
{
  //...
};
template <typename OutputPolicy>
Log<OutputPolicy>::~Log()
{
  OutputPolicy::Output(msg.str());
}

That's pretty much all that needs to be done on Log. You can now provide the FILE* output simply as an implementation of the OutputPolicy policy; see Listing Two.

Listing Two

class Output2FILE // implementation of OutputPolicy
{
   public:
   static FILE*& Stream();
   static void Output(const std::string& msg);
};
inline FILE*& Output2FILE::Stream()
{
   static FILE* pStream = stderr;
   return pStream;
}
inline void Output2FILE::Output(const std::string& msg)
{
   FILE* pStream = Stream();
   if (!pStream)
       return

   fprintf(pStream, "%s", msg.c_str());
   fflush(pStream);
}
typedef Log<Output2FILE> FILELog;
#define FILE_LOG(level) \
if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \
else FILELog().Get(messageLevel)

The code below shows how you can change the output from the default stderr to some specific file (error checking/handling omitted for brevity):

FILE* pFile = fopen("application.log", "a");
Output2FILE::Stream() = pFile;
FILE_LOG(logINFO) << ...;

A note for multithreaded applications: The Output2FILE policy implementation is good if you don't set the destination of the log concurrently. If, on the other hand, you plan to dynamically change the logging stream at runtime from arbitrary threads, you should use appropriate interlocking using your platform's threading facilities, or a more portable wrapper such as Boost threads. Listing Three shows how you can do it using Boost threads.

Lising Three

#include <boost/thread/mutex.hpp>
class Output2FILE
{
public:
    static void Output(const std::string& msg);
    static void SetStream(FILE* pFile);
private:
    static FILE*& StreamImpl();
    static boost::mutex mtx;
};

inline FILE*& Output2FILE::StreamImpl()
{
    static FILE* pStream = stderr;
    return pStream;
}
inline void Output2FILE::SetStream(FILE* pFile)
{
    boost::mutex::scoped_lock lock(mtx);
    StreamImpl() = pFile;
}
inline void Output2FILE::Output(const std::string& msg)
{
    boost::mutex::scoped_lock lock(mtx);
    FILE* pStream = StreamImpl();
    if (!pStream)
        return;
    fprintf(pStream, "%s", msg.c_str());
    fflush(pStream);
}

Needless to say, interlocked logging will be slower, yet unused logging will run as fast as ever. This is because the test in the macro is unsynchronized—a benign race condition that does no harm, assuming integers are assigned atomically (a fair assumption on most platforms).

Compile-Time Plateau Logging Level

Sometimes, you might feel the footprint of the application increased more than you can afford, or that the runtime comparison incurred by even unused logging statements is significant. Let's provide a means to eliminate some of the logging (at compile time) by using a preprocessor symbol FILELOG_MAX_LEVEL:

#ifndef FILELOG_MAX_LEVEL
#define FILELOG_MAX_LEVEL logDEBUG4
#endif
#define FILE_LOG(level) \
  if (level > FILELOG_MAX_LEVEL) ;\
  else if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \
   else FILELog().Get(level)

This code is interesting in that it combines two tests. If you pass a compile-time constant to FILE_LOG, the first test is against two such constants and any optimizer will pick that up statically and discard the dead branch entirely from generated code. This optimization is so widespread, you can safely count on it in most environments you take your code. The second test examines the runtime logging level, as before. Effectively, FILELOG_MAX_LEVEL imposes a static plateau on the dynamically allowed range of logging levels: Any logging level above the static plateau is simply eliminated from the code. To illustrate:

bash-3.2$ g++ main.cpp
bash-3.2$ ./a.exe DEBUG1
- 22:25:23.643 DEBUG:	A loop with 3 iterations
- 22:25:23.644 DEBUG1:	the counter i = 0
- 22:25:23.645 DEBUG1:	the counter i = 1
- 22:25:23.645 DEBUG1:	the counter i = 2
bash-3.2$ g++ main.cpp -DFILELOG_MAX_LEVEL=3
bash-3.2$ ./a.exe DEBUG1
- 22:25:31.972 DEBUG:	A loop with 3 iterations