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.

Those pesky evil macros

I've always been suspicious of Absolutes. Well, not always; after all, that's what our formative years are for - to be filled with certainties that we'll eventually replace with doubt throughout the rest of our lives. Anyway...

When I started developing, one of the first Absolutes I included in the "suspicious" category was the "X is evil" statement. And these days, with all the good sources of information available (stackoverflow, isocpp.org, or reddit/cpp, to name a few), I believe there's little reason for an Absolute like this. With a few exceptions, most "X is evil" statements need some qualifying, such as "X is evil, except in these cases, where it's perfectly acceptable", and it's this qualified (and quality) information that needs to be spread around, and not some utter hogwash Absolute.

So, let's tackle some evil, shall we?

I've been doing some research on C++ macros. Well, C macros, actually, but let's not get worked up over it. Namely, something like this, which would allow me to write this:

// YES, ONE DAY I'LL LOOK INTO BOOST PREPROCESSOR

#define FE_1(WHAT, X) WHAT (X)

#define FE_2(WHAT, X, ...) WHAT (X) FE_1(WHAT, __VA_ARGS__)

#define FE_3(WHAT, X, ...) WHAT (X) FE_2(WHAT, __VA_ARGS__)

#define FE_4(WHAT, X, ...) WHAT (X) FE_3(WHAT, __VA_ARGS__)

#define FE_5(WHAT, X, ...) WHAT (X) FE_4(WHAT, __VA_ARGS__)

#define GET_MACRO(_1,_2,_3,_4,_5,NAME,...) NAME

#define FOR_EACH(action,...) \

  GET_MACRO(__VA_ARGS__,FE_5,FE_4,FE_3,FE_2,FE_1)(action,__VA_ARGS__)

#define MYPC_LOG(level, ...) \

    BOOST_LOG_TRIVIAL(level) \

    FOR_EACH(<<, __VA_ARGS__)

MYPC_LOG(info, "info message: ", GetCode(), "some more info");
MYPC_LOG(info, "another info message: ", GetCode(), "some more info: ", 42);
MYPC_LOG(error, "error: ", GetCode(), "error info: ", 42, 12);

Why this solution? Because it's a simple way (once you understand it) to translate function call syntax (comma-separated list of values) into stream syntax. That means I can further isolate my code from the knowledge of how the logger works, and that's a Good Thing(TM).

Ah, but I can almost hear you say: "You don't need macros for that". And you're absolutely right, I don't. So, macros being - generally speaking and, you know, in a qualified way - evil, and there being better alternatives, why macros?

For two reasons, actually.

1. As I've written in previous posts, I'm using __FILE__ and __LINE__, and the preprocessor relies on their position in the code to generate their values. So, I need these to be at the actual call site, and not on some function (even inline).
2. One fundamental property of logging code is to generate as little overhead as possible. Look at this: MYPC_LOG(info, "info message: ", GetCode(), "some more info"). See the GetCode() in there? Ideally, we want to evaluate this only if it will be logged, i.e., if our logging level is INFO or lower (I'm ignoring other possible filters, here). I couldn't do this if MYPC_LOG() were a function.

Well, regarding point #2, yes, I could, using lambdas or functors. However, that would lead to a more complex solution and I'd still have point #1 to deal with.

Finally, with regards to spreading qualified information, here it goes. Note that logging/debugging with __FILE__ and __LINE__ shows up a few times as a perfectly good reason for using macros.

So, whenever someone berates you for using "evil constructs", do some research and see what your peers are saying. If it turns out there's a better alternative, learn and adapt; otherwise, sometimes you're stuck with some degree of evil. Just don't get used to it, or you could end up like this fellow, who only turned out all right in the end by sheer luck; or, as someone put it, because of someone else's pity.

Logger wrapper concluded... for now

The result of this latest redesign is ready, and you can get it here.

lib_logger.h has grown quite a bit. In order to properly take advantage of __FILE__ and __LINE__ I needed to go with macros. Lots of macros, but the work in creating all these macros was softened by a little bit of perl scripting.

Note: I considered using __func__, as well, but since POCO's Logger doesn't support it, I'd have to manage that in my own Logger. However, I believe that my Logger's design goals don't include this kind of management; it's a bridge to an actual implementation, it should own nothing, and it should impose little to no unwanted weight on the client code. So, I've decided that if the client code needs __func__, it'll have to take care of it. __FILE__ and __LINE__ should be enough to follow a trail, if needed.

Another reason for this macro growth was that I wanted this to work with both GCC and MSVC. There is a difference between LoggerBridge<bool condition, etc> and the LoggerBridge<false, etc> specialization - the latter has no template functions. This poses no problem with GCC; since template functions have default template parameters, the call is similar for both template and non-template functions. On MSVC, however, template functions don't have default template parameters. Therefore, the call is object.function<type>() for one and object.function() for the other.

My first instinct was te change the specialization, changing its functions to template functions. But, after considering it further, I decided not to. Default template parameters for template functions are in the Standard, and (hopefully) sooner or later will also be in MSVC. Until then, the MSVC code will have more preprocessor "magic".

I've tested this in Qt Creator and MSVC, with my Logger (wrapper around POCO's Logger) and LoggerCout (minimum interface implementation), with values of 1 and 0 for WANT_LOGGING. All went as expected.

So, when all is said and done, what are the requirements for a client app that wants to replace the default Logger? Look at class LoggerCout for the minimum interface:

class LoggerCout

{

public:

    explicit LoggerCout(std::string const&, char const* = nullptr);

    static void CreateLogger(std::string const&, std::string const&);

    bool IsCritical() const;

    bool IsDebug() const;

    bool IsError() const;

    bool IsFatal() const;

    bool IsInformation() const;

    bool IsNotice() const;

    bool IsTrace() const;

    bool IsWarning() const;

    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);

};

I don't think that's unreasonable. Of course, any other functions you need will have to be added to LoggerBridge manually. Since I've started this redesign, I've seen Herb Sutter's 2012 concurrency presentation, and was intrigued by the wrapper design he presented, especially the part about the wrapper being completely oblivious to the wrapee's interface. I'll certainly investigate if I can adapt it here, although the absence of inlining (via the use of functors/function pointers) may make it unsuitable. Anyway, for now, this is what we have.

There's one final question I'll need to answer, and that's what I'll be working on next: How does this affect performance? I'll prepare some testing with the following scenarios:

• No logging
• Logging with this solution
• Bypassing this solution and logging directly with POCO's Logger

As variations, some runs will have trivial processing, where logging should take up most of the work, and in others I'll simulate some heavy work, probably by use of sleep(). And I'll also test the use of POCO's AsyncChannel. This will give me some idea of what to expect.

Yep, I know, I finish a lot of these posts with a "Next, I'll do such and such". The truth is there's always work to be done. I like it that way.

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.