Logger Abstraction (PoC)

I've finally uploaded my logging macros to github, along with a sample program (you must have either Boost Log or Poco installed to run it). In this post, I'll detail its design.

 

My original requirements were prompted by a particular "use-case" - adding reusable classes to an application and allowing those classes to use the application's logging implementation, instead of whatever implementation was originally used. So, in this scenario, my requirements translate to: 1) The reusable classes must be used with no changes; and 2) The application developer should only need to create a header file with a list of well-defined macros that will invoke the app's logging implementation, thus causing the reusable classes to invoke that same implementation.

 

I've divided this into several header files, keeping in mind requirement #2. Let's take a look at these header files, then. 

 

Macro Overloading - macro_overload_base.h

This is the foundation of it all. It's a group of macros that allow overloading based on the number of arguments, up to a limit of 16.

 

My first design required the distinction between zero arguments, one argument, and more than one argument. However, the complexity of correctly detecting zero arguments was more than I was willing to accept, so I've worked around that requirement. Detecting invocations with one argument proved to be good enough, and the resulting macros, although still ugly, are a lot simpler.

 

I've been all over the web while searching for this, and I've been a bit beyond my knowledge quite some times (which was one of the reasons why I decided to work around the zero arguments requirement); These were my starting points, in case you're interested.

 

Detecting the number of arguments is up to the PCBASE__MOVERLOAD_SELECT_VALUE macro. In order to make it work, you must call it with the correct list of values. PCBASE__MOVERLOAD_ONE_ARG_OR_MORE calls it like this

#define PCBASE__MOVERLOAD_ONE_ARG_OR_MORE(...) \

    PCBASE__MOVERLOAD_SELECT_VALUE(__VA_ARGS__,\

    2,2,2,2,2,2,2,2,2,2,2,2,2,2,2,1)

 

because we just want to know if we have one argument or more than one argument.

OTOH, PCBASE__MOVERLOAD_VA_NUM_ARGS calls it like this

 

#define PCBASE__MOVERLOAD_VA_NUM_ARGS(...) \

    PCBASE__MOVERLOAD_SELECT_VALUE(__VA_ARGS__, \

    16,15,14,13,12,11,9,8,7,6,5,4,3,2,1)

because we need to know the exact number of arguments. PCBASE__MOVERLOAD_FOR_EACH does something similar, but passes as arguments the names of the macros that will allow to apply an action to each argument. E.g.,

   

PCBASE__MOVERLOAD_FOR_EACH(<<, "[", __FILE__, ":", __LINE__, "] ", 

    "Blimey! I didn't expect the Spanish Inquisition!", 

    chiefWeapons, mill.Trouble(), 42);

 

becomes

   

<< "[" << __FILE__ << ":" << __LINE__ << "] " 

    << "Blimey! I didn't expect the Spanish Inquisition!" 

    << chiefWeapons << mill.Trouble() << 42

 

You may have noticed the macro names look quite ugly. Since there's no namespace partitioning with macros, I've decided to make these names as ugly as I possibly can, to minimize name clashing.

 

Now, Let's move up one layer.

 

Logging Interface Type Abstraction - li_concat.h / li_outop.h

Here, we build on macro_overload_base.h to create the macros that will receive the logging arguments and call the user-supplied macros (USMs), which will, in turn, call the logging implementation.

 

There is an abstraction leak at this point. At some point in this "macro chain", we have to invoke the USMs. This means we have a contact point, similar to this: 

 

#define PCBASE__LAMOVERLOAD_LOG_IMPL_1(level, ...) \

    PCBLUESY__##level(__VA_ARGS__)

#define PCBASE__LAMOVERLOAD_LOG_IMPL_2(level, x, ...) \

    PCBLUESY__##level((x) PCBASE__MOVERLOAD_FOR_EACH(+, __VA_ARGS__))

 

On the left-hand side we have the names from the logging abstraction macros, on the right-hand side we have the USMs.

 

I considered three locations for this contact point:

1. Place it in the logging abstraction headers, i.e., in li_concat.h and li_outop.h. I rejected this idea because it would require the user to edit an extra header file, thus going against requirement #2.
2. Place it in the user-supplied header.
3. Create a separate header just for these macros.

While I don't like the fact the we'll have references to "abstraction names" in the user-supplied header, it seemed the best alternative, so I went for alternative #2.

 

li_output.h is quite simple - for each argument, prepend a "<<" to it. li_concat.h is more complex, because we can't add a "+" to a single argument.

 

In fact, li_output.h is so simple it could almost be dispensed with; however I couldn't come up with a design clean enough without it. Besides, keeping it maintains the parallelism between the design for these two interfaces, concatenation and stream.

 

NOTE: Concatenation is working, but it doesn't actually respect requirement #1 (read why here), because it's not automatically converting its arguments to string.

 

Logging Interface Type Selection - log_interface_type.h

This is where we define the interface type, which can be one of:

• Comma. Function call interface with several arguments, such as we would have in a printf()-like output function. I have not implemented this.
• Stream output operator (operator<<).
• Concatenation (using +). Function call interface with only one argument, created from the concatenation of several arguments. Since it's a binary operator, it requires a more complex implementation, because it needs to distinguish between two different cases: one argument, which must not involve any concatenation ("a" + is not a valid expression); and more than one argument, which must be concatenated.

This header file will also #include the correct header file for the interface type chosen. For now, it's a choice of either li_concat.h or li_outop.h. Both are described above.

 

We use this it by adding a #define to the project file/makefile, defining which interface type we want. E.g., on Qt Creator, to use the stream output operator, we'd do something like this on the .pro file:

DEFINES += "PCBLUESY__LOGINTERFACETYPE=3"

The default type (if we haven't #defined PCBLUESY__LOGINTERFACETYPE anywhere) is the stream output operator.

For now, I'll leave this header specific to the application, i.e., I'll have to create a new header for each application. I suspect this is not the best design, but I'll wait until I've used it a few times to see how it turns out.

 

Logging implementation - e.g., poco_log.h or boost_log.h

This is where we define the macros that will directly invoke the required functionality in the logging implementation (e.g., Poco or Boost).

The way I've set it up, we have a macro to get the logger (e.g., for Boost Log):

#define PCBLUESY__GETLOGGER(PCBLUESY_LOG_NAME) \

    src::severity_logger<boost::log::trivial::severity_level> \

    PCBLUESY__BOOSTLOG

Then, we have the top level logging macro, i.e., the macro that will get used in all the logging statements in the code:

#define PCBLUESY__LOG(level, ...) \

    PCBASE__LOG_ABSTRACTION(level, __VA_ARGS__)

These are the only two macros used in the application code. We then have the actual logging macros, i.e., the macros that call the logging implementation. Again, example for Boost Log:

#define PCBLUESY__PCBLUESY__TRACE(...) \

    BOOST_LOG_SEV(PCBLUESY__BOOSTLOG, \

    boost::log::trivial::severity_level::trace) __VA_ARGS__

Why the PCBLUESY__ repetition? This is the way the macro is used in the code:

   

PCBLUESY__LOG(PCBLUESY__ERROR, \

    "Blimey! I didn't expect the Spanish Inquisition ERROR!", \

    chiefWeapons, mill.Trouble(), 42);

 

I'm using PCBLUESY__ERROR as logging level in order to distinguish it from any other *ERROR* defined "out there". Since these names are defined in this header and won't be used anywhere else, I figured a little uglyness would be harmless, and could actually be useful.

 

Finally...

 

How do we use this? I've set up an example on my "SimpleSampleTuts" github. You'll need Boost Log and/or Poco C++ to see it in action. And if you use any other logging lib, provided it has an interface compatible with the ones discussed here, you should be able to create a header like poco_log.h/boost_log.h and start using it.

 

One final detail - initializing the logger. If you use a different implementation, you'll have to add that code, too.

Logging - The argument for the stream interface

Of all the things mentioned in my "resurface" post, I've been dedicating attention to my "logging macro front-end". To recap, the goal is to abstract the user code from the logging implementation used, thus allowing to substitute for another logging implementation with no changes to the code.

 

I want something like this:

 

LOG_FUNCTION_MACRO(ERROR_DEFINE_MACRO, 

    "Blimey! I didn't expect the Spanish Inquisition!", 

    chiefWeapons, mill.Trouble(), 42);

This is then "translated" into whatever interface the logging implementation provides for logging. So, with Boost Log, this could become something like this:

 

BOOST_LOG_SEV(someLog, boost::log::trivial::severity_level::error) 

    << __FILE__ << __LINE__ 

    << "Blimey! I didn't expect the Spanish Inquisition!" 

    << chiefWeapons << mill.Trouble() << 42;

 

Or, using Poco Logger's stream interface:
 

if (someLogRef.rdbuf()->logger().error())

    someLogRef.error() << __FILE__ << __LINE__

        << "Blimey! I didn't expect the Spanish Inquisition!" 

        << chiefWeapons << mill.Trouble() << 42 << endl;

else (void) 0;

 

Since I prefer a stream interface, that's where I began my work. Then, I moved on to what I call the "concatenation interface", where everything is concatenated into a single string. This was my first attempt, a few months ago, when I was using Poco Logger, but wasn't aware of Poco LogStream. The reason I settled on this was because I'm not a fan of the "format string" interface (i.e., printf()-like).

 

So, starting from our logging macro:

 

LOG_FUNCTION_MACRO(ERROR_DEFINE_MACRO, 

    "Blimey! I didn't expect the Spanish Inquisition!", 

    chiefWeapons, mill.Trouble(), 42);

we'd have something similar to this:

 

poco_error(someLogRef, __FILE__ + __LINE__ 

    + "Blimey! I didn't expect the Spanish Inquisition!" 

    + chiefWeapons + mill.Trouble() + 42);

And while I always preferred the stream interface, as I worked more on concatenation, I became aware it was not just a matter of preference; the stream interface is vastly superior. What do I mean by "superior"?

 

Let's look at this:

 

someStream << __FILE__ << __LINE__

    << "Blimey! I didn't expect the Spanish Inquisition!" 

    << chiefWeapons << mill.Trouble() << 42

 

__FILE__ and "Blimey! etc..." are char* (I'll ignore constness here), and work right out of the box. Ditto for __LINE__ and 42. So, our wildcards here are mill.Trouble() and chiefWeapons; for the sake of argument, let's assume mill.Trouble() returns a float and chiefWeapons is a container that defines its own operator<<(). This means close to 84% of our logging line works with no work required on our part. Our only additional work is defining operator<<() for whatever type chiefWeapons happens to be. And we probably would define it anyway, since output to a stream is always a handy feature, IMHO.

 

Now, let's look at this:

__FILE__ + __LINE__

    + "Blimey! I didn't expect the Spanish Inquisition!" 

    + chiefWeapons + mill.Trouble() + 42

  

This is supposed to be concatenation; concatenation assumes some string type. Since none of these arguments is a string type, we'd need to convert them. That's not difficult, but the question is - where would the conversion occur?

We don't want to place it in the original logging line, because we want it to be interface-agnostic. However, that's the only place where we know the type of each argument; we certainly couldn't place it in our macro mechanism, because macro parameters have no type.

We could create a family of template functions for this, and solve our problem through specialization - if we pass a string type, just return the string itself (yes, I'm ignoring the several string types in C++ libs and the necessity to copy those into a single type); if we pass a char*, build a string with it; if we pass an int, call to_string() (or similar); etc, meaning, every type we use would need a way to convert to string. And, while we might not require a template specialization for each type (e.g., we could use to_string() for int, long, or float), we'd be pretty close to that mark.

So, assuming this could be pulled off, with a proper design, it's still more work than taking advantage of a group of core types that have an already-functioning operator<<(), and only adding this to other types that require it.

Then, there is the question of performance - unless we use some mechanism like QstringBuilder, concatenation will be much more expensive than streaming output.

 

Finally, there is one last point that makes me prefer the stream interface, one that I've come upon as my logging usage became more "complex" - no conversions necessary. Conversions are one of the sources of problems in C/C++, and while we can mark them as explicit, I prefer sticking to a simple rule of defining no unnecessary conversions. If I only need a conversion to string when I'm outputting to log, then it is an unnecessary conversion.

 

So, where does this leaves my "logging macro front-end"? I'm going to finish my work and publish it with only the stream interface functional. The concatenation interface will be semi-functional, meaning no provision for conversion to string. I realize this is mostly self-defeating, since this means I probably won't use it. But I have two good options with operator<<() at the moment, so I'll stick to it, for the time being.

 

Adapting to Boost Log

I've decided to see how Boost Log implements its non-evaluation magic. And, as far as I can see, it turns out to be clever, but it's not magic.

I've built Boost 1.54.0 beta1, and changed the trivial logging example to this:

int GetCode()
{
    static int val = 0;

    return ++val;
}

int main(int argc, char *argv[])

{

    boost::log::core::get()->set_filter(

        boost::log::trivial::severity >= boost::log::trivial::info);

    BOOST_LOG_TRIVIAL(trace) << "trace message: " << GetCode();

    BOOST_LOG_TRIVIAL(debug) << "debug message: " << GetCode();

    BOOST_LOG_TRIVIAL(info) << "info message: " << GetCode();

    BOOST_LOG_TRIVIAL(warning) << "warning message: " << GetCode();

    BOOST_LOG_TRIVIAL(error) << "error message:" << GetCode();

    BOOST_LOG_TRIVIAL(fatal) << "fatal message: " << GetCode();

    return 0;

}

And this was the output:

[2013-06-15 20:26:00.401384] [0x000010ec] [info]    info message: 1
[2013-06-15 20:26:00.411384] [0x000010ec] [warning] warning message: 2
[2013-06-15 20:26:00.411384] [0x000010ec] [error]   error message:3
[2013-06-15 20:26:00.421384] [0x000010ec] [fatal]   fatal message: 4

So, this means that the calls to GetCode()in these lines didn't run:

BOOST_LOG_TRIVIAL(trace) << "trace message: " << GetCode();

BOOST_LOG_TRIVIAL(debug) << "debug message: " << GetCode();

Looking at the preprocessor output, this is what we have (edited for readability):

for 

(

    BLR _boost_log_record_23 =  

        (BLT::logger::get()).open_record((BLK::severity = BLT::trace)); 

    !!_boost_log_record_23;

)

    BLA::make_record_pump((BLT::logger::get()), _boost_log_record_23).stream()

        << "trace message: " << GetCode();

where

BLR = ::boost::log::record

BLT = ::boost::log::trivial

BLK = ::boost::log::keywords

BLA = ::boost::log::aux

It uses a for so it can initialize the record and test the initialization in the same expression. That's where the filter is applied (I didn't know the !!, but from what I've read, it's a safe way of converting to bool), and if the record fails the filter, the body of the for is not executed.

Comparing Boost and Poco loggers, I like Boost's stream syntax better. I find it more convenient, since it frees the client app from having to worry about string formatting/concatenation. OTOH, I look at Poco's implementation, and not only can I understand most of it, but I can also reason about the bits I find more challenging. Not so much with Boost, so far.

I also prefer Poco's organization - e.g., all the convenience macros are in Poco/Logger.h. The idea I got from Boost (and I'm still checking this) is that there is no simplified way of getting a list of what's available (and judging from Qt Creator's auto-complete list, there is a lot available).

I won't give up my goal of being able to change logger implementations with little effort, but I may have to give up the goal of not burdening the client code with my code's requirements, if using Boost Log. I'm still trying to figure out if this will pose a problem, and, if so, how to solve it.

One thing is certain - I'll keep on using macros. I won't give up __FILE__ and __LINE__, and I certainly don't want to have to write both all over the place, so I need actual textual replacement, and that's something only the preprocessor can give me.

Next stop: Getting a better understanding of Boost Log.

Ever a duh! moment

So, after coming up with a great design I rode off into the sunset.

Of course, after the sunset there's always a sunrise. This particular sunrise caught me merrily peppering logging statements all over my SSH code, basking in the warm light of my brilliant design. Or maybe it was the warm light of the sunrise, I tend to get confused about which is which. And, suddenly (isn't that always the case?), something went click, like a brain cell waking up.

I'm using POCO Logger's poco_* macros. Convenient little buggers, actually. Here, take a look at one of them:

#define poco_debug(logger, msg) \

    if ((logger).debug()) (logger).debug(msg, __FILE__, __LINE__); \

    else (void) 0

Note the __FILE__ and __LINE__. Cool, heh? And now, note how my brilliant design cunningly takes advantage of it:

2013-05-14 13:26:18.228 [Debug] ... [../Logger/logger.h:46] LibClassSupport ctor ID: 11
2013-05-14 13:26:18.250 [Debug] ... [../Logger/logger.h:46] LibClassUtility1 ctor ID: 1
2013-05-14 13:26:18.283 [Debug] ... [../Logger/logger.h:46] LibClassSupport ctor ID: 21
2013-05-14 13:26:18.306 [Debug] ... [../Logger/logger.h:46] LibClassUtility2 ctor ID: 1
2013-05-14 13:26:18.412 [Debug] ... [../Logger/logger.h:46] LibClassMain ctor ID: 1
2013-05-14 13:26:18.474 [Debug] ... [../Logger/logger.h:46] LibClassSupport ctor ID: 12
2013-05-14 13:26:18.508 [Debug] ... [../Logger/logger.h:46] LibClassUtility1 ctor ID: 2
2013-05-14 13:26:18.541 [Debug] ... [../Logger/logger.h:46] LibClassSupport ctor ID: 22
2013-05-14 13:26:18.574 [Debug] ... [../Logger/logger.h:46] LibClassUtility2 ctor ID: 2
2013-05-14 13:26:18.608 [Debug] ... [../Logger/logger.h:46] LibClassMain ctor ID: 2

Yep, looking from this log excerpt, one would get the impression my code spends an awful lot of time in line 46 of logger.h (a definite performance bottleneck, if I ever saw one). One would be forgiven for such an impression, even though one would be wrong; in case you're wondering, this last one would be me.

Ah, well, back to the old drawing board. Still, if it wasn't for mistakes, how would I learn, right?

Hey, if it happens to Wile E. Coyote, super-genius, why wouldn't it happen to me?

Logger wrapper continued

So, we have our logger all figured out, and now we want to use it. We also want to control the inclusion/exclusion of logging code in our build, like this:

#if WANT_LOGGING

    // Logging code

#endif

And, as I said in the previous post, we'd like this to be centralized somewhere, so that we don't have to spread these #ifs all over our code. Since the logging code requires the #include of lib_logger.h, that's a good candidate for this centralization:

#if WANT_LOGGING

#define CREATE_LOGGER(logger_name, config_file) \

    LibLogger::CreateLogger(logger_name, config_file)

#define GET_LOGGER(logger_name) LibLogger LIB_LOGGER(logger_name)

#define LOG_INFORMATION(msg) LIB_LOGGER.Information(msg)

#define LOG_DEBUG(msg) LIB_LOGGER.Debug(msg)

#else

#define CREATE_LOGGER(logger_name, config_file) ((void)0)

#define GET_LOGGER(logger_name) ((void)0)

#define LOG_INFORMATION(msg) ((void)0)

#define LOG_DEBUG(msg) ((void)0)

#endif

So, all we have to do is use CREATE_LOGGER, GET_LOGGER, etc. in our code, and it'll be automatically taken care of with a single #define.

There's a certain comfort in the use of macros, when it comes to code inclusion/exclusion, since the rules are simple. Still, I've always wanted to try some simple template meta-programming (TMP), and this looked like the perfect opportunity.

So, let's change our template class to this:

template <bool condition, typename LoggerImpl>

class LoggerBridge

{

public:

    explicit LoggerBridge(std::string const& loggerName);

    static void CreateLogger(std::string const& loggerName, 

        std::string const& configFile);

    void Critical(std::string const& msg);

    void Debug(std::string const& msg);

    void Error(std::string const& msg);

    void Fatal(std::string const& msg);

    void Information(std::string const& msg);

    void Notice(std::string const& msg);

    void Trace(std::string const& msg);

    void Warning(std::string const& msg);

private:

    LoggerImpl l;

};

We've added a bool argument to our template. Our goal is that when that argument is true, the compiler generates logging code; and when it's false, it doesn't. In order to achieve that, we'll add a specialization.

template <typename LoggerImpl>

class LoggerBridge<false, LoggerImpl>

{

public:

    explicit LoggerBridge(std::string /*const& loggerName*/) {}

    static void CreateLogger(std::string /*const& loggerName*/,  

        std::string const& /*configFile*/) {}

    void Critical(std::string const& /*msg*/) {}

    void Debug(std::string const& /*msg*/) {}

    void Error(std::string const& /*msg*/) {}

    void Fatal(std::string const& /*msg*/) {}

    void Information(std::string const& /*msg*/) {}

    void Notice(std::string const& /*msg*/) {}

    void Trace(std::string const& /*msg*/) {}

    void Warning(std::string const& /*msg*/) {}

};

When the bool parameter is false, our class will contain nothing, and it will do - quite unsurprisingly - nothing.

So, if we change lib_logger.h to this

#include "logger.h"

#include "loggerbridge.h"

typedef Lib::LoggerBridge<false, Lib::Logger> LibLogger;

and rebuild, running the .o files through nm will show no sign of Logger. You'll still find Logger symbols on the .exe because we didn't exclude Logger.h and Logger.cpp from the build, but if you do it (e.g., commenting their lines on the SOURCES and HEADERS variables, in Qt Creator's .pro file), then this: nm Logger.exe | grep -i 3lib6logger will produce no results.

The funny-looking 3lib6logger identifies Lib::Logger symbols, after mangling occurs. E.g.:

00403c70 T __ZN3Lib6Logger12CreateLoggerERKSsS2_

00403a60 T __ZN3Lib6LoggerC1Ev

You can run these symbols through c++filt, to demangle them

>c++filt __ZN3Lib6Logger12CreateLoggerERKSsS2_

Lib::Logger::CreateLogger(std::basic_string<char, std::char_traits<char>, 

    std::allocator<char> > const&, std::basic_string<char, std::char_traits<char>, 

    std::allocator<char> > const&)

>c++filt __ZN3Lib6LoggerC1Ev

Lib::Logger::Logger()

BTW, when running c++filt on valid mangled names (say, a name you got from nm's output or out of the disassembly window in a debugging session), if you're getting no results and if the name has leading underscores, use the -n option.

So, compiling LoggerBridge with false gives us the same result as using macros, and with an amount of TMP small enough not to overwhelm a beginner like me.

Now, we can do something like this in lib_logger.h:

#include "logger.h"

#include "loggerbridge.h"

typedef Lib::LoggerBridge<WANT_LOGGING, Lib::Logger> LibLogger;

According to the value we #define for WANT_LOGGING, 1 (true) or 0 (false), we'll instantiate the general LoggerBridge template (with logging functionality) or our specialization (with no functionality).

We could add further complexity to these rules. If we used a char instead of a bool, we could define specializations based on logging level - logging levels 0 and MAX would be the false and true cases above, and the levels in-between would require further specializations, with some methods having empty bodies and others performing actual logging. E.g. (assuming 1 is Fatal and 8 is Trace):

template <typename LoggerImpl>

class LoggerBridge<4, LoggerImpl>

{

public:

    explicit LoggerBridge(std::string /*const& loggerName*/) {}

    static void CreateLogger(std::string /*const& loggerName*/, 

        std::string const& /*configFile*/) {}

    void Critical(std::string const& msg);

    void Debug(std::string const& /*msg*/) {}

    void Error(std::string const& msg);

    void Fatal(std::string const& msg);

    void Information(std::string const& /*msg*/) {}

    void Notice(std::string const& /*msg*/) {}

    void Trace(std::string const& /*msg*/) {}

    void Warning(std::string const& msg);

private:

    LoggerImpl l;

};

So, we get logging code for Fatal, Critical, Error, and Warning, and all other functions are empty. I don't see much use for this, so I'll stick with the bool version.

You can find the code here.