Logging

Goals and Approach

Logging is an important feature of many applications. It can be used for debugging during the development process and to trace how a program executes once it is deployed. Crucial features of a logging framework are:

• Performance
  High peformance can only be achieved if formatting of log records is avoided for disabled log statements. The costs boil down to an atomic integer comparison, and a branch. Further, logging can be disabled at compile time with via the preprocessor, in which case no instruction at all will be generated.
  
  
• Thread-safety
  It is obvious that any modern library needs to be thread-safe. However, great care needs to be taken that synchronization overhead does not affect performance.
  
  
• Easy Formatting
  In order to minimize the impact of a logging framework on the size of the source code, logging statements should be easy to write. This library allows to format log records with stream output operator just like for std::ostream.
  
  
• Configuration
  The logging system should be configurable by both, API calls and configuration files. It must provide fine grained control in which parts of the application logging is enabled. It must be possible route the log records to different logs, for example the console or log files. The format of the records in the log should be configurable, and only contain the required information, which leads to smaller logs and a higher performance.
  
  
• Usable during static initialization and deinitialization
  For example, logging statements may be executed indirectly when global objects are constructed or destructed. This should result in a static initialization fiasco.
  
  
• Portability
  This library is extremly portable and has minimal dependencies. It requires only standard C++ and a standard C++ library.

Logger Configuration

The heart of the logging framwork is a hierarchy of log targets, which have a unique string ID. Applications format log records and use logger objects to write them to a target. Each target is configured with a threshold log level. Only records with a log level above or equal to the threshold are logged. In this case, the log records are written to the targets channel. Targets can log to the same channel, in fact, often all targets log to the same channel. The log channels perform output of log records i.e. to the console, if a console channel is selected or to a file if a file channel is selected, respectively. The threshold log level and channel of each log target in the hierarchy can be configured at runtime. Here is a typical example:

                           <root> id: ""
                             |    channel: console://
                             |    level: info
                             |
                             |
                           <app> id: "app"
                             |   channel: INHERIT
                             |   level: INHERIT
                             |
                             |
        .--------------------+-------------------.                
        |                                        |      
        |                                        |
    <module1> id: "app.module1"              <module2> id: "app.module2"
              channel: file:///log.txt                 channel: INHERIT
              level: trace                             level: INHERIT

In this setup, three log targets are created. The root target is always persent and has the special empty string ID. The root target has one direct child, the target named "app". In this case, no log channel and level have been explicitly set for the target, so it inherits the attributes from its parent. The target "app" has two children, named "app.module1" and "app.module2". The string IDs indicate the position (path) of the target in the hierarchy. The target "app.module2" inherits all attributes from it parent, while the target "app.module1" overrides the log channel and level. With this mechanism based on inheritance, the parts of interest of the hierarchy can be enabled, while other parts of the hierarchy are suppressed.

Applications can use the API to set the threshold log levels and the channels of the targets. Possible log levels are:

• Pt::System::Fatal
• Pt::System::Error
• Pt::System::Warn
• Pt::System::Info
• Pt::System::Debug
• Pt::System::Trace

Channels are configured by a channel URL. Possible channel URLs are:

• file:///mylog.log?size=1000000&files=5
• console://

The first opens a file channel writing to the file mylog.log. If the file size of 1000000 bytes is reached it will be renamed, and logging continues to a newly created mylog.log file. The parameter 'files' limits file rolling to a total number of five files. The second URL opens a channel to log to the console.

The format of the logging records can be configured with a format pattern string. The format pattern can contain text and specifiers, which are placeholders for the various elements of the log records. Specifiers are escaped with a percent sign in the format pattern string. For example, the pattern "%t %m" would write the time and the message for each log record separated by a space.

Here is a list of possible specifiers:

• %c logging category
• %d current date
• %l log level (severity)
• %m message text
• %t current time
• %F file where the record was logged
• %L line number where the record was logged
• %M method/function where the record was logged

TODO:

• %T thread id
• %P process id

The following code example above changes the log level and channel of the target named "app" to write records with a threshold level of Pt::System::Info to a log file:

Pt::System::Logger::setLogLevel("app", Pt::System::Info);
Pt::System::Logger::setChannel("app", "file:///myfile.log");
Pt::System::Logger::setPattern("[%c] %t - %m");

A log record pattern is applied to print the target ID, the time and the message text of the records to the logs.

Logging From Programs

Macros are provided to make logging more convenient. The easiest way to log is to use the logging macros for a static logger instance. A logger instance can be defined for a compilation unit and then logged to:

PT_LOG_DEFINE("app.module")

void foobar(int n)
{
    PT_LOG_INFO("foobar was called with: " << n);
}

The advantage of the macros is that they will expand to nothing if NLOG is defined, so logging support can be conditionally compiled. Macros exist for the various log levels:

• PT_LOG_FATAL()
• PT_LOG_ERROR()
• PT_LOG_WARN()
• PT_LOG_INFO()
• PT_LOG_DEBUG()
• PT_LOG_TRACE()

The disadvantage of these macros is that they do not allow more than one logger instance per compilation unit and the logger definition can not be placed in a public header file. A similar set of macros allows to define global logger instances:

#include <Pt/System/Logger.h>

PT_LOG_DEFINE_INSTANCE(mullog, "app.calc.multiply")
PT_LOG_DEFINE_INSTANCE(divlog, "app.calc.divide")

int multiply(int a, int b)
{
    PT_LOG_INFO_TO(mullog, "multipy " << a << " by " << b)
    return a*b;
}

int divide(int a, int b)
{
    PT_LOG_INFO_TO(divlog, "divide " << a << " by " << b)
    return a/b;
}

Again, these logging statements can be conditionally compiled and the logging macros expand to nothing if NLOG is defined. Here is a list of the macros for the various log levels:

• PT_LOG_FATAL_TO()
• PT_LOG_ERROR_TO()
• PT_LOG_WARN_TO()
• PT_LOG_INFO_TO()
• PT_LOG_DEBUG_TO()
• PT_LOG_TRACE_TO()

The alternative to using the macros is to use logger objects directly in the code. To do so, a Logger object must be instanciated, for example as a class member variable and then messages can be written to it:

#include <Pt/System/Logger.h>

class Calculator
{
    public:
        Calculator()
        : _logger("app.calc")

        int multiply(int a, int b)
        {
            Pt::System::LogMessage(_logger, Pt::System:Info)
                << "multipy " << a << " by " << b << Pt::System::endlog;
            return a*b;
        }

    private:
        Pt::System::Logger _logger;
};

Note that the code above is somewhat inefficient, because the log record is formatted even if its log level is below the threshold of the logger target. It is more efficient if the log level is checked before the record is formatted:

if( _logger.enabled(Pt::System:Info) )
{
    Pt::System::LogMessage(_logger, Pt::System:Info) << "multipy " << a << " by " << b;
}

The library offers a set of macros that can be used with logger instances and implement this check:

logger_begin_info(_logger) << "multipy " << a << " by " << b;

Here is the list of the available macros:

• logger_begin_fatal()
• logger_begin_error()
• logger_begin_warn()
• logger_begin_info()
• logger_begin_debug()
• logger_begin_trace()

Expansion of these macros is not affected by defining NLOG. These macros can not be used with loggers defined by the previous macros, because construction of global loggers is not trivial when the the static initialization fiasco has to be avoided. Definition of global loggers with the macros does not simply result in global variables.

Although it generates more code, it can still make sense to work with log message and log record objects directly. These can improve performance, if the same record has to be logged multiple times, because formatting has to be done only once:

Pt::System::Logger logger("app.module");
Pt::System::LogMessage msg(logger, Pt::System::Info);
msg << "pi is: " << 3.1415;
 
// log for the first time...
msg.log();
 
// ... and later the second time
msg.log();

Similarily, a log record can be sent multiple times to a logger or to several loggers:

Pt::System::Logger logger1("app.module1");
Pt::System::Logger logger2("app.module2");
    
Pt::System::LogRecord record(Pt::System::Info);
msg << "pi is: " << 3.1415;
 
logger1.log(record);
logger2.log(record);