Logging Macros in C++

Tutorial on setting up compiler macros for common logging functions in C++.

When you want to know why a program did something, the first place to look is usually the logs. In Linux this may involve running systemd, this might involve calling to search for specific messages or catting a file somewhere in /var/log. In developing applications, you need a library and methodology to somehow generate these logging messages.

C++ happens to have my favorite approach to logging. This article documents my thinking, process, and solution. It should be noted that as a fairly recent convert to the language, I am not necessarily speaking with the right or authoratative terms. My needs have a somewhat more limited scope that the general body of C++ programmers. Additionally, it should be noted that I have started learning on C++17, and cannot speak at all to older standards and practices.

Context

In most languages there are several ways to handle logging and a lot of the time these methods are much more extensive than my needs require. Therefore, I think it's important to note the context in which I'm approaching projects.

I am not a systems programmer or a kernel developers or really doing anything that expressly raises performance needs requiring a language like C or C++. The greeater majority of my development involves command-line applications and utilities that anyone in their right mind or under time constraints would develop in Python, Ruby or JavaScript and be happy.

Given that I am not under any sort of time constraint and given that I enjoy the intellectual challenge of trying a more complicated and performant approach, I decided to do my work in a language that compiles to native code.

Command-line utilities don't require complicated logging operations.

I don't need it to write to file, it also only needs to report warnings, errors and critical failures in standard usage. Messages for trace, debugging, and info are only necessary in development.

Logging Levels

For logging levels I laid out the following scheme:

Level Description

Trace

Information for developer on every operation in every function

Debug

Information for developer on what's happening as function executes

Info

Information for user on general steps as the program runs

Warn

Information for user indicating something minor went wrong

Error

Information for user indicating that something failed and won't deliver in results

Fatal

Information for user indicating that the program crashed and why

Compiler Macros

The method I decided on for handling logging is to use compiler macros. This is the root of why C++ is my favorite language for logging. It allows me to set specific levels at compile time for trace or debugging and when it's compiled for general use only warnings and above generate messages.

Compiler macros for logging are set using #define. In a log.hpp file I might write something like,
#define WARN(msg) std::cerr << msg << std::endl

Then, somewhere in my code I call the macro:

WARN("The application has fallen on its face");

Notice the #define line above does not feature a semicolon. When the application compiles, it automatically replaces the WARN() instance with the defined code. So, the above comes out of the preprocessor as:

std::cerr << "The application has fallen on its face" << std::cerr;

So, a gratuitous semicolon would cause errors.

Logging Levels

The preprocessor can also use macros conditionally. For instance,

// INFO Macro to use when Debugging is Off 
#ifndef ENABLE_DEBUG

#define INFO(msg)

// INFO Macro to use when Debugging is On
#else

#define INFO(msg) std::cerr << msg << std::endl

#endif

When the compiler runs the preprocessor, it checks if a value has been set on the ENABLE_DEBUG macro. If the value has not been set, it uses the first INFO() macro, which removes all code passed to it. If the value has been set, it print messages passed to INFO() to standard error.

To turn on debugging, pass the message to the compiler using -DENABLE_DEBUG. Or, if you're like me and prefer simpler commands, have SCons do it for you:

options = ['-std=c++17']
if ARGUMENTS.get("debug", False):
  options.append('-DENABLE_DEBUG')

env = Environment(
  CXX='g++',
  CXXFLAGS=options)

Then, run SCons with debug turned on:

user@hostname$ scons debug=true

Logging Labels

The label in a logging message is the bit of text at the start that provides the logging level. For instance, [ INFO ] or [ WARN ]. Given that this process is tedious, I'd like to only have to write this string once and let the compiler sort it out.

Fortunately, compiler macros can be strung together to further simplify the process.

#define INFO_LABEL_TEXT "[ INFO ]: "
...

#define INFO(msg) std::cerr << INFO_LABEL_TEXT << msg << std::endl

The compiler then renders the INFO_LABEL_TEXT string then the INFO() macro together.

Colorize Output

Last task of this build is to colorize the messages so that the different levels clearly stand out. The reason for this is that having a load of trace messages spewing into stderr makes it more difficult to spot the important lines.

Initially I went looking for a library to handle this, but the first result to come up provided escape codes for setting colors in bash. To put these to use I wrote a new macro for each logging level that contained the string for the color configuration and the label text.

#define DEBUG_LABEL_TEXT
...

#define DEBUG_LABEL "\[34m" << DEBUG_LABEL_TEXT

Since I don't want to leave open color settings in the output, I also wrote a new macro for closing logging messages that would reset the color before running the endline.

#define END_LOG "\e[m" << std::endl

Reason for this is that I don't know that these escape sequences will work on all operating systems or all shell environments, so to avoid conflict I set it a conditional macro to disable them.

Filename and Line Number

When building a binary for debugging and trace, I need a little more information than just the message the code generates. Personally, I find it also helpful if the logging message tells me the file emitting the message and the line in the file where the message was called.

Normally, I don't reuse logging messages that often, so I could just grep for what I want; but it's much faster to open vim and run <num>gg to go right to the line.

Fortunately, g++ provides a number of built in macros for this purpose.

  • __FILE__: Provides the name of the file in which it occurs

  • __LINE__: Provides the line in which it occurs

Passing these into a logging message renders a string with the filename and line number.

#define INFO(msg) std::cerr << "[ INFO ]: " << msg << " (" << __FILE__ << " on line " << __LINE__ << ")" << std::endl

Final Logging Code

/* util.hpp - Utility functions and macros
*
* Author: Kenneth P. J. Dyer
* Version: 2019.1
*
* Copyright (c) 2019, Kenneth P. J. Dyer <kenneth@avoceteditors.com>
* All rights reserved.
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions are met:
*
* * Redistributions of source code must retain the above copyright notice, this
*   list of conditions and the following disclaimer.
* * Redistributions in binary form must reproduce the above copyright notice,
*   this list of conditions and the following disclaimer in the documentation
*   and/or other materials provided with the distribution.
* * Neither the name of the copyright holder nor the name of its
*   contributors may be used to endorse or promote products derived from
*   this software without specific prior written permission.
*
* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
* AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
* LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
* CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
* SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
* INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
* CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
* ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
* POSSIBILITY OF SUCH DAMAGE.
*/

#ifndef LOG_UTIL_GUARD
#define LOG_UTIL_GUARD


/******************************** TERMINAL COLORS *****************************/

#define TRACE_LABEL_TEXT "[ TRACE ]: "
#define DEBUG_LABEL_TEXT "[ DEBUG ]: "
#define INFO_LABEL_TEXT "[ INFO ]: "
#define WARN_LABEL_TEXT "[ WARN ]: "
#define ERROR_LABEL_TEXT "[ ERROR ]: "
#define FATAL_LABEL_TEXT "[ FATAL ]: "


#ifndef DISABLE_TERM_COLOR

  #define END_LOG "\e[m" << std::endl

  #define TRACE_LABEL "\e[36m" << TRACE_LABEL_TEXT
  #define DEBUG_LABEL "\e[34m" << DEBUG_LABEL_TEXT
  #define INFO_LABEL "\e[32m" << INFO_LABEL_TEXT
  #define WARN_LABEL "\e[33m" << WARN_LABEL_TEXT
  #define ERROR_LABEL "\e[31m" << ERROR_LABEL_TEXT
  #define FATAL_LABEL "\e[35m" << FATAL_LABEL_TEXT
  
#else
  #define END_LOG std::endl

  #define TRACE_LABEL TRACE_LABEL_TEXT
  #define DEBUG_LABEL DEBUG_LABEL_TEXT
  #define INFO_LABEL INFO_LABEL_TEXT
  #define WARN_LABEL WARN_LABEL_TEXT
  #define ERROR_LABEL ERROR_LABEL_TEXT
  #define FATAL_LABEL FATAL_LABEL_TEXT

#endif

/******************************** LOGGING  OPERATIONS *****************************/

// LOGGING CONFIGURATION

#ifndef ENABLE_DEBUG // Debugging Off

   #ifndef ENABLE_TRACE    // Debugging Off & Trace Off
       #define LOG_LEVEL 0
   #else                   // Debugging Off & Trace On
       #define LOG_LEVEL 2
   #endif                  

#else                   // Debugging On
   #ifndef ENABLE_TRACE    // Debugging On & Trace Off
       #define LOG_LEVEL 1
   #else                   // Debugging On and Trace On
       #define LOG_LEVEL 2
   #endif                 
#endif                  


// BASIC LOGGING 
#if LOG_LEVEL == 0
   #define TRACE(MSG)
   #define DEBUG(MSG)
   #define INFO(MSG)
   #define WARN(MSG) std::cerr << WARN_LABEL << MSG << END_LOG 
   #define ERROR(MSG) std::cerr << ERROR_LABEL << MSG << END_LOG
   #define FATAL(MSG) std::cerr << FATAL_LABEL << MSG << END_LOG 
#endif

// DEBUG LOGGING
#if LOG_LEVEL == 1
   #define TRACE(MSG)
   #define DEBUG(MSG) std::cerr << DEBUG_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define INFO(MSG) std::cerr << INFO_LABEL <<  MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define WARN(MSG) std::cerr << WARN_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define ERROR(MSG) std::cerr << ERROR_LABEL << MSG <<  " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define FATAL(MSG) std::cerr << FATAL_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
#endif

// TRACE LOGGING
#if LOG_LEVEL == 2
   #define TRACE(MSG) std::cerr << TRACE_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define DEBUG(MSG) std::cerr << DEBUG_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define INFO(MSG) std::cerr << INFO_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define WARN(MSG) std::cerr << WARN_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define ERROR(MSG) std::cerr << ERROR_LABEL << MSG <<" (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
   #define FATAL(MSG) std::cerr << FATAL_LABEL << MSG << " (" << __LINE__ << ":" << __FILE__ << ")" << END_LOG
#endif

#endif