Boost.Log Library

By Kevin Heifner, OCI Principal Software Engineer

May 2016

Introduction

I was recently updating an application from 32-bit Microsoft Visual Studio 2010 (VC10) to 64-bit Microsoft Visual Studio 2013 (VC12). The application used Apache log4cxx for logging. Since Apache log4cxx has not been updated in a number of years, I decided to switch to Boost logging. Boost was already used by the project, so it seemed like this would be an easy switch. However, Boost.Log v2 took a bit more effort to set up than I would have initially guessed. If you are moving from Apache log4cxx or similar Log4J-style logging (e.g., log4cpp), or if you are just new to Boost.Log, I hope you find this article helpful for getting started.

The focus of this article is setting up Boost.Log in a similar manner as log4cxx. Specifically, we want to be able to initialize the logging via a config file so that it can be modified without having to recompile and redeploy our application. Boost.Log is very flexible and provides numerous logging capabilities. Please see the Boost.Log documentation for all the various features. Although this is not an exhaustive overview of Boost.Log, it should be sufficient for you to add logging to your application. The full source may be found at https://github.com/oci-labs/BoostLog.

Log Macros

Like most C++ logging libraries, we set up some macros to make logging easier. There are a couple of different ways the macros may be set up: either as macros with arguments, or as a macro that expands as the start of a chain of << insertion operators.

// Use a macro with argument ARG.
#define LOG_TRACE(ARG)  BOOST_LOG_SEV(sysLogger::get(), boost::log::trivial::trace) << ARG

// Use a macro with no argument.
#define LOG_TRACE  BOOST_LOG_SEV(sysLogger::get(), boost::log::trivial::trace)

I chose to use the first option (using a macro with an argument) since it allows us to easily remove all associated code by simply defining the macro as empty. Also, since the existing log4cxx logging macros used arguments, I was able to just redefine the application's existing log4cxx macros without having to touch any of the usages of the macros.

// Previous log4cxx macro replaced
#define LOG_TRACE(ARG)  LOG4CXX_TRACE(Logger::getSysLogger(), ARG)

The macros are used for logging in application code.

    for (int i = 0; i < 10; ++i) {
      LOG_TRACE("i: " << i);
    }

Boost.Log Set Up

Let us now look at what is involved in setting up this type of Boost.Log logging.

//  logger.hxx
 
#ifndef LOG_LOGGER_HXX
#define LOG_LOGGER_HXX
#pragma once
 
#include <boost/log/trivial.hpp>
#include <boost/log/sources/global_logger_storage.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#include <boost/log/attributes/mutable_constant.hpp>
#include <boost/log/utility/manipulators/add_value.hpp>
#include <string>
 
BOOST_LOG_GLOBAL_LOGGER(sysLogger,
  boost::log::sources::severity_channel_logger_mt<boost::log::trivial::severity_level>);
BOOST_LOG_GLOBAL_LOGGER(dataLogger,
  boost::log::sources::severity_channel_logger_mt<boost::log::trivial::severity_level>);

sysLogger - Used for general application information logging. Will include file, line, and function in log output.
dataLogger - Used for logging of user-generated business data.

There are a number of loggers available from Boost.Log. Here we set up two severity channel loggers with default trivial levels. severity_channel_logger is a Boost.Log provided implementation of a logger that supports logging various severity levels. The Boost.Log documentation shows how you can set up your own severity levels, but the levels provided by Boost.Log's trivial implementation (trace, debug, info, warning, error, fatal) suits most needs. There is also a boost::log::sources::severity_channel_logger if your application is single threaded and does not need the thread safe *_mt version.

Any number of loggers of various types may be created. Here we use two different loggers. Two loggers are included in this example to illustrate how log statements are separated into different log files. Of course, if you only need general system level logging then you only need the sysLogger.

The BOOST_LOG_GLOBAL_LOGGER macro creates a global sysLogger class definition with a singleton sysLogger::get() function that provides access to the logger. We will use this later in our set up of the loggers.

Logger Class Definition

The following Logger class allows us to encapsulate the initialization of Boost.Log. This could also be a namespace since it contains only static members. However, the original log4cxx implementation was a class and did maintain state.

class Logger {
public:
  /// Init with default trivial logging
  static void init();
 
  /// @param configFileName config ini file that contains boost logging properties.
  ///        If configFileName.empty() then default initialization.
  static void initFromConfig(const std::string& configFileName);
 
  /// Disable logging
  static void disable();
 
  /// Add a file sink for LOG_DATA_* for >= INFO.
  /// This file sink will be used along with any configured via Config in init().
  static void addDataFileLog(const std::string& logFileName);
};

Two different initializations are provided: one from a config ini file, line 26, and one for default initialization, line 22. The Logger class also provides an addDataFileLog function for programmatically adding additional target log files for the dataLogger. The focus of this example is setting up Boost.Log via a config ini file. However, it is useful to also see how set up may be done programmatically.

#define LOG_LOG_LOCATION(LOGGER, LEVEL, ARG)            \
  BOOST_LOG_SEV(LOGGER, boost::log::trivial::LEVEL)     \
    << boost::log::add_value("Line", __LINE__)          \
    << boost::log::add_value("File", __FILE__)          \
    << boost::log::add_value("Function", __FUNCTION__) << ARG;
 
/// System Log macros.
/// TRACE < DEBUG < INFO < WARN < ERROR < FATAL
#define LOG_TRACE(ARG) LOG_LOG_LOCATION(sysLogger::get(), trace, ARG);
#define LOG_DEBUG(ARG) LOG_LOG_LOCATION(sysLogger::get(), debug, ARG);
#define LOG_INFO(ARG)  LOG_LOG_LOCATION(sysLogger::get(), info, ARG);
#define LOG_WARN(ARG)  LOG_LOG_LOCATION(sysLogger::get(), warning, ARG);
#define LOG_ERROR(ARG) LOG_LOG_LOCATION(sysLogger::get(), error, ARG);
#define LOG_FATAL(ARG) LOG_LOG_LOCATION(sysLogger::get(), fatal, ARG);
 
/// Data Log macros. Does not include LINE, FILE, FUNCTION.
/// TRACE < DEBUG < INFO < WARN < ERROR < FATAL
#define LOG_DATA_TRACE(ARG) BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::trace) << ARG
#define LOG_DATA_DEBUG(ARG) BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::debug) << ARG
#define LOG_DATA_INFO(ARG)  BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::info) << ARG
#define LOG_DATA_WARN(ARG)  BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::warning) << ARG
#define LOG_DATA_ERROR(ARG) BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::error) << ARG
#define LOG_DATA_FATAL(ARG) BOOST_LOG_SEV(dataLogger::get(), boost::log::trivial::fatal) << ARG
 
#endif /* LOG_LOGGER_HXX */

As mentioned in the introduction of log macros above, preprocessor macros provide the main interface for interacting with the logging library. Lines 36-40 define the LOG_LOG_LOCATION macro. This macro is used to simplify the LOG_* macros on lines 44-49. boost::log::add_value allows us to add an attribute value to a log record. Here we use it to add the line, file, and function name to the log output. These attribute values may be referenced in the formatter as we will see later. The values are metadata and are not automatically added in the output.

Line 60 wraps up our logger.hxx header file.

Logger Class Implementation

//  logger.cxx
 
#include "logger.hxx"
 
#include <boost/algorithm/string/predicate.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/log/core.hpp>
#include <boost/log/common.hpp>
#include <boost/log/sinks.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/expressions/keyword.hpp>
#include <boost/log/attributes.hpp>
#include <boost/log/utility/exception_handler.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/setup/filter_parser.hpp>
#include <boost/log/utility/setup/formatter_parser.hpp>
#include <boost/log/utility/setup/from_stream.hpp>
#include <boost/log/utility/setup/settings.hpp>
#include <boost/log/sinks/sync_frontend.hpp>
#include <boost/log/sinks/text_ostream_backend.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/shared_ptr.hpp>
#include <boost/make_shared.hpp>
 
#include <fstream>
#include <string>

First, the required #includes are shown here for completeness. Boost.Log is broken up into a number of files to only include the features you need.

BOOST_LOG_GLOBAL_LOGGER_CTOR_ARGS(sysLogger,
  boost::log::sources::severity_channel_logger_mt<boost::log::trivial::severity_level>,
  (boost::log::keywords::channel = "SYSLF"));
 
BOOST_LOG_GLOBAL_LOGGER_CTOR_ARGS(dataLogger,
  boost::log::sources::severity_channel_logger_mt<boost::log::trivial::severity_level>,
  (boost::log::keywords::channel = "DATALF"));

The BOOST_LOG_GLOBAL_LOGGER_CTOR_ARGS macro is used here to define the construction of our two severity channel loggers declared in logger.hxx lines 14-17 above. We use the macro to pass in the name of the channel: SYSLF to sysLogger and DATALF to dataLogger. The channel name may be used to filter out log records. By passing in the channel name here, we do not need to pass it along with each log record like we did with line, file, and function name.

// Custom formatter factory to add TimeStamp format support in config ini file.
// Allows %TimeStamp(format=\"%Y.%m.%d %H:%M:%S.%f\")% to be used in ini config file for property Format.
class TimeStampFormatterFactory :
  public boost::log::basic_formatter_factory<char, boost::posix_time::ptime>
{
public:
  formatter_type create_formatter(const boost::log::attribute_name& name, const args_map& args) {
    args_map::const_iterator it = args.find("format");
    if (it != args.end()) {
      return boost::log::expressions::stream 
        << boost::log::expressions::format_date_time<boost::posix_time::ptime>(
             boost::log::expressions::attr<boost::posix_time::ptime>(name), it->second);
    } else {
      return boost::log::expressions::stream 
        << boost::log::expressions::attr<boost::posix_time::ptime>(name);
    }
  }
};

Boost.Log does not come with a way to specify TimeStamp format in a config ini file. However, we can add that capability by providing our own custom formatter factory. If the args to TimeStamp include "format" then take the format string and pass it along to format_date_time, otherwise just pass it along as normal. Since all property values in the config ini file require quotes, we have to escape the quotes around the format string as shown in the comment on line 38.

// Custom formatter factory to add Uptime format support in config ini file.
// Allows %Uptime(format=\"%O:%M:%S.%f\")% to be used in ini config file for property Format.
// boost::log::attributes::timer value type is boost::posix_time::time_duration
class UptimeFormatterFactory :
  public boost::log::basic_formatter_factory<char, boost::posix_time::time_duration>
{
public:
  formatter_type create_formatter(const boost::log::attribute_name& name, const args_map& args)
  {
    args_map::const_iterator it = args.find("format");
    if (it != args.end()) {
      return boost::log::expressions::stream
        << boost::log::expressions::format_date_time<boost::posix_time::time_duration>(
        boost::log::expressions::attr<boost::posix_time::time_duration>(name), it->second);
    } else {
      return boost::log::expressions::stream
        << boost::log::expressions::attr<boost::posix_time::time_duration>(name);
    }
  }
};

Similar to TimeStamp above, we add the ability to specify format in a config ini file for the Uptime attribute. As we will see in initFromConfig below, "Uptime" is a boost::log::attributes::timer of type boost::posix_time::time_duration. Again we use format_date_time to do the heavy lifting of supporting Boost.Date_Time I/O format flags.

void
Logger::init() {
  initFromConfig("");
}

For initialization of our logging without an ini config file, we provide Logger::init(). It simply calls our initFromConfig so that all initialization is contained in one function.

void
Logger::initFromConfig(const std::string& configFileName) {
  // Disable all exceptions
  boost::log::core::get()->set_exception_handler(boost::log::make_exception_suppressor());
 
  // Add common attributes: LineID, TimeStamp, ProcessID, ThreadID
  boost::log::add_common_attributes();
  // Add boost log timer as global attribute Uptime
  boost::log::core::get()->add_global_attribute("Uptime", boost::log::attributes::timer());
  // Allows %Severity% to be used in ini config file for property Filter.
  boost::log::register_simple_filter_factory<boost::log::trivial::severity_level, char>("Severity");
  // Allows %Severity% to be used in ini config file for property Format.
  boost::log::register_simple_formatter_factory<boost::log::trivial::severity_level, char>("Severity");
  // Allows %TimeStamp(format=\"%Y.%m.%d %H:%M:%S.%f\")% to be used in ini config file for property Format.
  boost::log::register_formatter_factory("TimeStamp", boost::make_shared<TimeStampFormatterFactory>());
  // Allows %Uptime(format=\"%O:%M:%S.%f\")% to be used in ini config file for property Format.
  boost::log::register_formatter_factory("Uptime", boost::make_shared<UptimeFormatterFactory>());
 
  if (configFileName.empty()) {
    // Make sure we log to console if nothing specified.
    // Severity logger logs to console by default.
  } else {
    std::ifstream ifs(configFileName);
    if (!ifs.is_open()) {
      // We can log this because console is setup by default
      LOG_WARN("Unable to open logging config file: " << configFileName);
    } else {
      try {
        // Still can throw even with the exception suppressor above.
        boost::log::init_from_stream(ifs);
      } catch (std::exception& e) {
        std::string err = "Caught exception initializing boost logging: ";
        err += e.what();
        // Since we cannot be sure of boost log state, output to cerr and cout.
        std::cerr << "ERROR: " << err << std::endl;
        std::cout << "ERROR: " << err << std::endl;
        LOG_ERROR(err);
      }
    }
  }
 
  // Indicate start of logging
  LOG_INFO("Log Start");
}

We start by disabling exceptions during the creation of log records. Most of our logging is used to indicate exceptional conditions, and the last thing we want is for the logging itself to throw exceptions. When we used log4cxx, our LOG_* macros actually contained try-catch statements to prevent exceptions from killing our application.

#define LOG_TRACE(ARG) \
   try { LOG4CXX_TRACE(Logger::getSysLogger(), ARG) } catch (const log4cxx::helpers::Exception&) {}

The try-catch macros were added after our application crashed when logging was configured to log to a network share. The network share would sporadically cause log4cxx to throw an exception indicating a write failure. It is nice that Boost.Log provides a simple way to disable exceptions while logging.

boost::log::add_common_attributes() is a helper function that adds some commonly used values to each log record. The attributes are then available for use in log output formatting. We also add Uptime attribute, which is a Boost.Log provided timer class, globally so that it is available to add to our logs.

Lines 92 and 94 are needed to allow "Severity" in the config ini file Format and Filter property statements. Similarly, lines 96 and 98 register our custom formatters for "TimeStamp" and "Uptime". With our custom formatters, it is possible to pass along Boost.Date_Time format I/O flags to Boost.Log formatter.

For the case where no Boost.Log config ini file is available, we want the default to log to the console. It turns out that is the default behavior of boost::log::sources::severity_channel_logger. However, if you don't use the severity_channel_logger, you can easily add console logging via boost::log::add_console_log.

Line 111 is at the heart of our initFromConfig function. Here we pass boost::log::init_from_stream a file stream of the specified boost config ini file. There is also a boost::log:init_from_settings if you want to initialize with boost::log::settings. This may be useful if you want to pre-process the properties that are passed on to boost::log. We actually use the boost::log:init_from_settings method in our production code as we allow environment variables to be used in our config ini file. The environment variables are expanded before passing them on to Boost.Log.

The call to boost::log::init_from_stream is wrapped in a try-catch because the exception suppressor on line 85 only suppresses exceptions during the creation of log records, not during initialization. If an exception is thrown we log it to std::cout and std::cerr because we don't know what state Boost.Log is in. The LOG_ERROR on line 71 may fail.

Line 124 is a simple indication that logging is set up and working. I like to have a log statement at the start of the application and at the end so that it is easy to always see run time by looking at the log.

void
Logger::disable() {
  boost::log::core::get()->set_logging_enabled(false);
}

Boost.Log provides a simple way to turn off all logging. We use this to turn off logging during unit testing, otherwise it may be difficult to identify actual errors, since our unit tests generate numerous error conditions.

void
Logger::addDataFileLog(const std::string& logFileName) {
  // Create a text file sink
  boost::shared_ptr<boost::log::sinks::text_ostream_backend> backend(
    new boost::log::sinks::text_ostream_backend());
  backend->add_stream(boost::shared_ptr<std::ostream>(new std::ofstream(logFileName)));
 
  // Flush after each log record
  backend->auto_flush(true);
 
  // Create a sink for the backend
  typedef boost::log::sinks::synchronous_sink<boost::log::sinks::text_ostream_backend> sink_t;
  boost::shared_ptr<sink_t> sink(new sink_t(backend));
 
  // The log output formatter
  sink->set_formatter(
    boost::log::expressions::format("[%1%][%2%] %3%")
    % boost::log::expressions::attr<boost::posix_time::ptime>("TimeStamp")
    % boost::log::trivial::severity
    % boost::log::expressions::smessage
    );
 
  // Filter by severity and by DATALF channel
  sink->set_filter(
    boost::log::trivial::severity >= boost::log::trivial::info &&
    boost::log::expressions::attr<std::string>("Channel") == "DATALF");
 
  // Add it to the core
  boost::log::core::get()->add_sink(sink);
}

Logger::addDataFileLog provides a way to add a log file programmatically. The purpose of this article is to demonstrate how to set up Boost.Log via a config ini file similar to a log4cxx set up. However, we will briefly look at how it may be done via code.

First, we create a text file stream on lines 135-137. We specify that we want each log record flushed to the file so no buffered IO is used. A boost::log::sinks::synchronous_sink is then associated with the text file stream. We could have also used a boost::log::sinks::asynchronous_sink if we wanted the writes to happen on a different thread.

Lines 147-152 specifies the format to use for each log record in the log file. Each line will contain a time stamp, an indication of severity, and the log message.

Lines 155-157 provide the filter for our log file. Any log record with severity of info or greater will be logged, as long as the log record was logged via the LOG_DATA_* macros, since we also filter by channel "DATALF".

`logconfig.ini` Boost Configuration File

Now it is time to look at an example configuration file that may be used with our Logger::initFromConfig("logconfig.ini"). It is important to remember that, unlike most other property files you may be familiar with, all property values should be enclosed in quotes "".

Each of the configuration file properties are described via comments. The file is presented here in its entirety.

#
# See http://www.boost.org/doc/libs/1_60_0/libs/log/doc/html/log/detailed/utilities.html#log.detailed.utilities.setup.filter_formatter
#
# Many of the property values have to be in quotes, best to just use quotes for all of them.
#
# SYSLF is the System Log File for logging standard 'debug' type info.
# DATALF is the Data log File for logging modification to business data.
#
[Core]
# Set DisableLogging to true to disable all logging.
DisableLogging="false"
 
# SYSLF - system log
[Sinks.SYSLF]
Destination="TextFile"
# If Asynchronous true then thread dedicated to writing to log, otherwise blocks main thread to write.
Asynchronous="true"
# If AutoFlush is true then non-buffered output
AutoFlush="true"
# Line Formats available: TimeStamp, Uptime, Severity, LineID (counter), ProcessID, ThreadID, Line, File, Function
# TimeStamp and Uptime support boost date time format:
#    http://www.boost.org/doc/libs/1_60_0/doc/html/date_time/date_time_io.html#date_time.format_flags
Format="[%TimeStamp(format=\"%Y-%m-%d %H:%M:%S.%f\")%][%Uptime(format=\"%O:%M:%S.%f\")%][%Severity%] %File%(%Line%) %Function%: %Message%"
# Target directory in which rotated files will be stored.
Target="c:/temp"
# FileName pattern to use. %N is a counter for files.
FileName="app_syslog_%N.log"
# RotationSize in bytes, File size, in bytes, upon which file rotation will be performed.
# Time based rotation also available via RotationInterval and RotationTimePoint see boost log docs.
RotationSize="10485760"
# Matching used so that only files matching FileName pattern are deleted.
ScanForFiles="Matching"
# MaxSize - Total size of files in the target directory in bytes upon which the oldest file will be deleted.
#MaxSize=100485760
# MinFreeSpace - Minimum free space in the Target directory in bytes. Above this value oldest file is deleted.
#MinFreeSpace=1485760
# Specify level of log, options are: trace, debug, info, warning, error, fatal
# Since Channel not part of filter all log output will be included.
# If only SYSLF logging desired, change to: Filter="%Severity% >= trace & %Channel% matches \"SYSLF\""
Filter="%Severity% >= trace"
 
# DATALF - data log
[Sinks.DATALF]
Destination="TextFile"
# If Asynchronous true then thread dedicated to writing to log, otherwise blocks main thread to write.
Asynchronous="true"
# If AutoFlush is true then non-buffered output
AutoFlush="true"
# Line Formats available: TimeStamp, Uptime, Severity, LineID (counter), ProcessID, ThreadID
# TimeStamp and Uptime support boost date time format:
#    http://www.boost.org/doc/libs/1_60_0/doc/html/date_time/date_time_io.html#date_time.format_flags
Format="[%TimeStamp(format=\"%Y-%m-%d %H:%M:%S.%f\")%][%Uptime(format=\"%O:%M:%S.%f\")%][%Severity%] %Message%"
# Target directory in which rotated files will be stored.
Target="c:/temp"
# FileName pattern to use. %N is a counter for files.
FileName="app_datalog_%N.log"
# RotationSize in bytes, File size, in bytes, upon which file rotation will be performed.
# Time based rotation also available via RotationInterval and RotationTimePoint see boost log docs.
RotationSize="10485760"
# Matching used so that only files matching FileName pattern are deleted.
ScanForFiles="Matching"
# MaxSize - Total size of files in the target directory in bytes upon which the oldest file will be deleted.
#MaxSize=100485760
# MinFreeSpace - Minimum free space in the Target directory in bytes. Above this value oldest file is deleted.
#MinFreeSpace=1485760
# Specify level of log, options are: trace, debug, info, warning, error, fatal
# Specify Channel otherwise all log output will be included.
Filter="%Severity% >= trace & %Channel% matches \"DATALF\""
 
# Console log, logs both DATALF and SYSLF
[Sinks.Console]
# Remove the following lines to disable console logging
Destination="Console"
# If AutoFlush is true then non-buffered output
AutoFlush="true"
# Line Formats available: TimeStamp, Uptime, Severity, LineID (counter), ProcessID, ThreadID
# TimeStamp and Uptime support boost date time format:
#    http://www.boost.org/doc/libs/1_60_0/doc/html/date_time/date_time_io.html#date_time.format_flags
Format="[%TimeStamp(format=\"%Y-%m-%d %H:%M:%S.%f\")%][%Uptime(format=\"%O:%M:%S.%f\")%][%Severity%] - %Message%"
# Specify level of log, options are: trace, debug, info, warning, error, fatal
Filter="%Severity% >= info"

Summary

I hope you find this gentle introduction to Boost.Log useful. The full source may be found on GitHub: https://github.com/oci-labs/BoostLog.

References

[1] SETT Article Example Code on GitHub
https://github.com/oci-labs/BoostLog
[2] Apache log4cxx
https://logging.apache.org/log4cxx/
[3] Boost
http://www.boost.org/
[4] Boost.Log v2
http://www.boost.org/doc/libs/1_60_0/libs/log/doc/html/index.html
[5]Boost.Date_Time I/O Flags
http://www.boost.org/doc/libs/1_60_0/doc/html/date_time/date_time_io.html#date_time.format_flags
[6] log4cpp
http://log4cpp.sourceforge.net/
[7] Log4J
http://logging.apache.org/log4j/2.x/
[8] MPC - Used to generate Visual Studio project files
https://objectcomputing.com/products/mpc/

Software Engineering Tech Trends (SETT) is a regular publication featuring emerging trends in software engineering.