Logger

Overview

A logging framework, with configurable loggers via logging namespaces. Loggers output to C++ streams specified via the logging namespace configuration. Logging namespaces inherit their parent configuration via a cascading inheritance.

Logging namespaces are configured via standard environment configuration syntax. This can be supplied statically (via a logging configuration file), or dynamically by calling the logging system configure method.

Quick start

#include <Balau/Logging/Logger.hpp>

Environment configuration: logging

Logging messages

Logging to Balau loggers is similar to that of other logging systems.

			// A debug message.
			log.debug("An object: {}", obj);

			// An info message.
			log.info("Hello, world!");

			// An error message.
			log.error("Something went wrong. Data: {} / {}", data1, data2);

The first argument is a const char * or std::string_view string that specifies the message. The {} placeholders in the message are replaced by the string conversions of the remaining arguments.

If source code file and line number information is required, the logging macros should be used instead. The definitions of these macros contain the standard __FILE__ and __LINE__ macros that provide file and line number information.

			// A debug message with file and line number information.
			BalauLogDebug(log, "An object: {}", obj);

			// An info message with file and line number information.
			BalauLogInfo(log, "Hello, world!");

			// An error message with file and line number information.
			BalauLogError(log, "Something went wrong. Data: {} / {}", data1, data2);

If you do not wish to see the prefix Balau on each of your logging statements, new defines can be created which alias these macros.

There are six logging levels: trace, debug, info, warn, error, and none.

Whether a log message is output to the logging stream depends on whether the logging namespace is enabled for that logging level. This depends on the logging configuration.

The {} placeholders are replaced with the result of the toString call of the object(s) supplied in the logging call. It is thus necessary that suitable toString functions are defined for all object types passed to logging calls.

In order for the compiler to pick up the correct toString functions during the function template instantiation, the header file(s) containing the function(s) must be included before the Logger.hpp header is included.

In addition to the standard logging methods that accept a variable number of parameters, there is a function based logging method for each logging level. These methods accept a function that is used to generate the message to log.

			// An info message via a lambda.
			log.info([&v1, &v2] () { return toString("Value = ", v1 * v2); });

The function based logging methods are useful when derived arguments need to be logged. If a function based logging method were not used, the code used to derive the arguments would execute, regardless of whether the message is needed or not, as prescribed by the logging level of the logger.

In order to use loggers, there are two tasks required:

configure the logging system namespaces (optional);
obtaining references to loggers.

These tasks are discussed in reverse order below.

Logger references

Loggers are identified via logging namespaces. A logging namespace is a string of dot delimited idenfiers. Typically, the application name or the reverse domain name of the company is used as the logging namespace prefix, i.e. "balau" or "com.borasoftware". Namespaces are case sensitive.

Loggers are owned by the logging system and can be obtained by reference, by calling the Logger::getLogger function.

			// Get a logger for the "balau.network" logging namespace.
			Logger & log = Logger::getLogger("balau.network");

Logger references are typically set up as static fields of classes, but instance references and local variables are also possible if the use case requires it.

			////////// In header file. //////////

			class A {
				// Static member logger reference declaration.
				private: static Balau::Logger & log;
			};

			/////////// In body file. ///////////

			// Static member logger reference definition.
			Balau::Logger & A::log = Balau::Logger::getLogger("balau.network");

Logging configuration

The configuration of loggers is determined by the configuration of the logging namespaces. Logging namespaces inherit their parent configuration via a cascading priority inheritance.

By default, the logging system configures itself automatically to log info and warn level messages to stdout, and error level messages to stderr.

The default logging message format is:

			%Y-%m-%d %H:%M:%S [%thread] %LEVEL - %namespace - %message

Details of the message format placeholders are provided in the detailed documentation.

There are two ways of providing a custom logging configuration:

create a balau-logging.hconf configuration file in the same folder as the application's executable;
call Balau::Logger::configure(std::string) within the application.

If a logging configuration file is provided, the contained configuration will be used from the start of the application's execution. If logging configuration is provided via a Balau::Logger::configure call, the logging system will use the default configuration until the call is made.

The logging configuration is standard environment configuration. Composite property names specify the logging namespaces. The value properties defined within a composite property provide the logging configuration for that namespace.

Usage

Configuration

There are two ways to supply the logging configuration.

The implicit way to configure the logging system is to provide a balau-logging.hconf configuration file in the application binary directory. This will be automatically picked up by the logging system.

The explicit way to configure the logging system is to provide logging configuration via a call to:

			Balau::Logger::configure(const std::string & conf);

The string argument passed in the call contains the logging configuration. This logging configuration can be read from a file in a custom location, or may be generated by the application as deemed appropriate by the caller.

The logging system can be reconfigured via subsequent calls to the above function. Calling the following function will lock the configuration for the lifetime of the application execution:

			Balau::Logger::lockConfiguration(bool throwOnReconfigure = false);

Subsequent calls to the configure function will then either be ignored (default behaviour) or will throw a LoggingConfigurationException if throwOnReconfigure is set to true.

Logging reconfiguration provides eventual consistency. Logging during reconfiguring will result in stable but non-deterministically configured logging. The logging format of a particular logger during reconfiguration will either be the previous configuration or the new configuration, but not a mixture of the two. Similarly, the stream(s) written to by a logger during reconfiguration may be the previously specified ones or the newly specified ones.

Logging configuration calls can be made in static contexts, including within static initialisation blocks that are each executed in a non-deterministic order.

If no balau-logging.hconf file is found and no call to configure is made, the logging system will log INFO and WARN level messages to stdout and ERROR messages to stderr.

If the parsed logging configuration from balau-logging.hconf is invalid, an error message will be written to stderr and loggers associated with the affected namespaces will be configured to write to stdout for all invalidly configured logging levels. If the format specification for a namespace contains an invalid format specifier, an error message will be written to stderr and the the invalid specifier will be output verbatim in subsequent log messages to affected loggers.

Logger instances

Loggers are obtained via the static getLogger call in the logger class:

			Balau::Logger & logger = Balau::Logger::getLogger(const std::string & loggingNamespace);

The parameter 'loggingNamespace' is the logging namespace that determines the configuration of the logger (logging level, streams, message format).

The Logger class also contains a static function globalLogger(). This logger references the logger associated with the global namespace. This logger may be useful when logging to the global namespace is all that is required.

Calls to getLogger() can be in static or instance contexts. Normally such calls are placed in static contexts.

			//////////// Header file ////////////

			class A {
			    // The class' logger.
			    private: static Balau::Logger & logger;

			    // main class declaration..
			};

			///////////// Body file /////////////

			// Get the logger associated with the logging namespace "A".
			Balau::Logger & A::logger = Balau::Logger::getLogger("A");

Loggers should always be maintained as references. Loggers are not owned by the caller, and must not be deleted or placed within pointer containers.

The Balau logging system will not throw any exceptions from the getLogger call, other than if there is a fatal error such as an out of memory issue.

Startup and shutdown

The logging system is first configured when the first call to Logger::getInstance or Logger::configure is made. Subsequent calls to Logger::configure will reconfigure the logging system.

The logging system state is maintained in a lazy singleton that is instantiated on the first call to Logger::getInstance or Logger::configure. It is thus safe to use loggers inside static initialisation blocks. However, if such logging is made via another statically initialised logger reference, that statically initialised logger reference may not be initialised yet, and the application will crash. Due to this, the safe way of logging from within static initialisation blocks is done by obtaining the logger from inside the initialisation block by calling Logger::getInstance. This will always obtain a valid logger reference.

Logging system shutdown happens from the destructor of the statically allocated singleton. The C++ standard states that the order of destruction of statically allocated objects is non-deterministic. Logging from inside the destructors of statically allocated objects is thus not safe and should not be performed, as the logging system may have already been shut down by the time the destructor runs.

Logging messages

To log a message, the logger has five sets of templated methods that accept a variable number of parameters. Each set corresponds to a logging level { trace, debug, info, warn, error }.

The templated methods accept any types as const references. Each parameter is converted to a string via the Balau universal to-string function (see the documentation on the universal to-string function for more information). It is sufficient to ensure that a toString function has been defined for the type of each parameter at the point of template function instantiation, and the logger will use it to stringify the parameter.

It is often more convenient to add an incomplete class Logger; declaration in the header file where a logger reference is defined, and include the Logger.hpp header in the body file instead. This ensures that verification of header include order is confined to the single body file instead of propagating to all files that include the header containing the logger reference.

The log message passed to the call should contain the same number of parameter placeholders as is passed to the function. A parameter placeholder has the form of a pair of curly braces "{}". Each placeholder is then replaced during the log call by the associated parameter.

Writing a log message thus has the following form:

			ComplexObject results = process();

			LOG.info("The results of run {}/{} are: {}", runIndex, runCount, results);

In order to output source code file names, file paths, and/or line numbers of log message locations, it is necessary to call the logging functions that take file path and line information via a SourceCodeLocation instance:

			LOG.info(SourceCodeLocation(__FILE__, __LINE__), "blah");

			LOG.info(SourceCodeLocation(__FILE__, __LINE__), "blah {} {}", one, two);

			LOG.info(SourceCodeLocation(__FILE__, __LINE__), [&o1, &o2] () {
				return toString("value = ", one * two);
			});

The __FILE__ and __LINE__ macros are the standard C++ preprocessor macros that provide file path and line information. They must be physically placed in the source code line.

A better alternative to explicitly specifying the file path and line macros, Logger.hpp contains a set of convenience macros that define the source code file paths and line macros implicitly:

			#define BalauLogTrace(LOGGER, ...)
			#define BalauLogDebug(LOGGER, ...)
			#define BalauLogInfo(LOGGER, ...)
			#define BalauLogWarn(LOGGER, ...)
			#define BalauLogError(LOGGER, ...)

These are used as function calls that take the logger as the first argument and the message/parameters as subsequent arguments:

			BalauLogInfo(LOG, "blah");

			BalauLogInfo(LOG, "blah {} {}", one, two);

			BalauLogInfo(LOG, [&o1, &o2] () { return toString("value = ", one * two); });

Use of these macros is recommended in preference to the explicit calls.

If you do not wish to see the Balau prefix on each logging line of your code, create a set of your own macros which delegate to the above macros:

			#define MyAppLogTrace(LOGGER, ...)  BalauLogTrace(LOGGER, __VA_ARGS__)
			#define MyAppLogDebug(LOGGER, ...)  BalauLogDebug(LOGGER, __VA_ARGS__)
			#define MyAppLogInfo(LOGGER, ...)   BalauLogInfo(LOGGER, __VA_ARGS__)
			#define MyAppLogWarn(LOGGER, ...)   BalauLogWarn(LOGGER, __VA_ARGS__)
			#define MyAppLogError(LOGGER, ...)  BalauLogError(LOGGER, __VA_ARGS__)

Logging namespaces

The logging framework uses hierarchical logging namespaces to determine the logging configuration for each logger. Logging namespaces are dot delimited names with the following syntax:

			[a-zA-Z][a-zA-Z0-9_]*(\.[a-zA-Z][a-zA-Z0-9_]*)*

Logging namespaces work in a hierarchical manner by inheriting the configuration of the nearest ancestor unless overridden in the immediate logger namespace configuration. For example, if the logging configuration supplied during the configuration of the logging system is:

			com.borasoftware {
				level: info
			}

			com.borasoftware.a {
				level: debug
			}

then a logger instantiated with the com.borasoftware namespace:

			Balau::Logger & logger = Balau::Logger::getLogger("com.borasoftware");

will log to info level. If a logger is instantiated with the com.borasoftware.a namespace:

			Balau::Logger & logger = Balau::Logger::getLogger("com.borasoftware.a");

then it will log to debug level. If a logger is instantiated with the com.borasoftware.b.c namespace (i.e. a namespace that is not directly specified in the configuration but has ancestor com.borasoftware):

			Balau::Logger & logger = Balau::Logger::getLogger("com.borasoftware.b.c");

then this logger will log to the level specified by com.borasoftware.

If a logger is instantiated with an unknown namespace with no known ancestors, the global logging namespace configuration will be used. The global namespace may also be configured in the logging configuration by using the special "." namespace.

Configuration file

Overview

The configuration file format is standard environment configuration. Each composite property defines a namespace key and a set of configuration value properties within.

The logging system can be configured via a standalone configuration file, or can be configured from the injector's loaded environment configuration by obtaining a suitable EnvironmentProperties instance from the injector and calling the Logger::configure(EnvironmentProperties) function.

In addition to the following documentation, the logging environment configuration pages provide reference documentation on each logging value property.

The global logging namespace is specified via the special "." key. This namespace can be configured in the same way as any other namespace, and forms the global ancestor to all namespaces. It is thus useful to place any configuration applicable to all loggers in the global namespace.

Here is an example of a simple logging configuration:

			. {
				level  = warn
				format = %Y-%m-%d %H:%M:%S [%thread] %level - %namespace - %message
			}

			com.borasoftware {
				level = info
			}

			com.borasoftware.a {
				level = debug
			}

This example configuration configures three logging namespaces. The global namespace logging level is set to warn. Two other descendant namespaces' levels are also set. All loggers will log to the default stdout/stderr streams.

The example configuration configures the global namespace with a logging message format. Unless this is reconfigured in a descendant namespace, all loggers will use this format.

Configuration macros

Logging configurations may contain the following macro placeholders in the output stream specifications. With the exception of the ${date} placeholder, these placeholders are expanded during logging system configuration.

Placeholder	Expansion
${user.home}	The path to the user's home directory in file URI format (example: file:///home/bob).
${executable}	The name of the executable.
${date}	The current date.

For example, the logging system could be configured to log all output to a file contained within the user's home directory and with the same name as the executable by using the following stream option:

			. {
				stream = ${user.home}/${executable}.log
			}

The date placeholder

This functionality is not yet implemented.

Unlike the other placeholders, the ${date} placeholder is not expanded before configuration parsing. Instead, the ${date} placeholder is processed later on by the stream class.

Basic usage

When a stream URI contains the ${date} placeholder, the logging system will automatically change the stream URI each day with the ${date} placeholder updated to the new current date. This will result in the logging output changing at midnight each day. This can be useful when a new logging file is required each day, without requiring an application restart.

As this functionality is implemented in the FileLoggingStream class, custom logging stream classes are responsible for implementing this functionality if required. If a custom logging stream implementation is specified in the logging configuration, the associated custom logging stream class will need to be programmed with the necessary logic to recognise and expand the ${date} placeholder, and close/open the relevant output streams each day.

The previous configuration example with with the ${date} placeholder added to the file logging stream is:

			. {
				stream = ${user.home}/${executable}-${date}.log
			}

Date options

Date placeholders may take up to two options. These options are placed within the {} brackets of the placeholder, after the date placeholder keyword. The options are whitespace delimited.

The options are as follows.

Option	Description
Compress	When the "compress" option is specified, the previous logging file is compressed when the day advances.
Date format	The text format of the date used in the logging file names. When not specified, the default %F is used. Permitted flags are: aAbBcCdeFgGhjmuUVwWyY. Permitted characters between flags are '-' and '_'.

Information on the date flags is available in the HH date library's documentation. See the DateTime documentation for more details on the date library.

Configuration options

The following configuration options are currently defined.

OPTION NAME	DESCRIPTION
level	Logging level
format	Message format specification
flush	Whether to automatically flush after each message (default is to flush)
stream	Output stream specification for all logging levels
trace-stream	Output stream specification for trace logging
debug-stream	Output stream specification for debug logging
info-stream	Output stream specification for info logging
warn-stream	Output stream specification for warn logging
error-stream	Output stream specification for error logging

Logging level

The logging level option value is just the level (trace, debug, info, warn, error, none). The value text is case insensitive.

Format specification

The message format specification consists of a printf like format string that contains text and format specifiers. The available format specifiers are:

Specifier	Description
%Y	the year as four digits
%y	the year as two digits
%m	the month as two digits
%d	the day of the month
%H	the hour as two digits
%M	the minute as two digits
%S	the seconds as two digits followed by six digits representing the microsecond remainder
%thread	the thread name if one has been set or the thread id otherwise
%level	the logging level in lowercase
%LEVEL	the logging level in uppercase
%namespace	the logger's logging namespace
%ns	an abbreviation of the logger's logging namespace, created by printing each identifier's first letter only, apart from the last identifier which is printed in its entirety
%filename	the source code file name
%filepath	the full path to the source code file
%line	the line number in the source code file
%message	the message, after stringification and combination of all arguments
%%	the percent character
%"	the double quotation character

For the %thread specifier, the thread name can be set by calling Util::ThreadName::setName(name) from the thread. The Util::ThreadName class is a utility that stores a thread-local name that is used by the logging system for the purpose of replacing the thread id with a meaningful name. Note that currently, the name of a thread can only be set from within the thread itself.

The default format specification if none is supplied or inherited for a particular namespace is:

			%Y-%m-%d %H:%M:%S [%thread] %LEVEL - %namespace - %message

An alternative to the default logging format that includes the filename and line number could be:

			%Y-%m-%d %H:%M:%S %filename:%line - [%thread] %LEVEL - %namespace - %message

Log messages resulting from this format would be similar to the following:

			2018-03-26 18:19:59.904675835 LoggerTest.cpp:139 - [main] INFO  -  - hello bob
			2018-03-26 18:19:59.904699204 LoggerTest.cpp:140 - [main] INFO  - com.borasoftware - hello C++

Flush

The flush option allows automatic flushing to be selectively disabled for different logging namespaces.

By default, loggers automatically flush the writer stream after writing a logging line. This ensures that logging is physically written to output streams promptly. Automatic flushing can be disabled for a namespace by specifying flush: false in the namespace configuration.

Stream specifications

The stream specification options specify the output stream(s) to be created and written to for the logging namespace. The value of the options is a URI:

			stream         = [uri]
			[level]-stream = [uri]

where [uri] is a real or pseudo URI identifying a stream to write to. Stream URIs are supported by logging system plugins.

URIs that are handled by default are:

standard localhost file URLs (file:///path/to/file);
stdout/stderr file descriptor pseudo schemes.

Built in stream configuration examples:

			stream       = file:///path/to/file
			warn-stream  = stdout
			error-stream = stderr

Output streams for other types of URI are instantiated by logging system plugins (see next section).

The file descriptor pseudo schemes log to the application's standard output and error streams.

For a particular stream specification, the logging system will instantiate an output stream if the stream type is recognised by the logging system or one of the registered plugins. If a stream specification is not recognised, the logging system will configure the logger to the null output stream and will log an error message to the output stream of the global logging namespace.

The different stream specification options correspond to non-level specific and level specific stream configurations. The non-level specific stream option sets a single stream for all logging levels. All log output for a particular namespace will log to this stream when this option is specified with no other stream options.

The level specific [level]-stream options allow different output streams to be configured for different logging levels. Each level specific stream option configures the log output of that level.

When one or more level specific [level]-stream options are specified and the non-level specific stream option is not specified, the streams of levels that do not have any stream specification will be determined via the stream configurations of adjacent levels. In this case, the priority of the adjacent level specific stream configurations is first downwards, then upwards. For example, if the info level is configured via a level specific stream configuration to log to stdout and the error level is configured via a level specific stream configuration to log to stderr, the warn level will be implicitly configured to log to stderr and the trace and debug levels will be implicitly configured to log to stdout.

If the non-level specific stream option is specified along with one or more level specific [level]-stream options, all levels without level specific [level]-stream options will be configured to the non-level specific stream setting.

Some additional examples will make this concept more clear:

			com.borasoftware {
				warn-stream  = stdout
				error-stream = stderr
			}

The above specification will configure the com.borasoftware logger to output all trace, debug, info, and warn level log messages to stdout, and all error level log messages to stderr.

			com.borasoftware {
				debug-stream = ${user.home}/.bora/${executable}/debug.log
				warn-stream  = stdout
				error-stream = stderr
			}

The above specification will configure the com.borasoftware logger to output all trace and debug level log messages to the specified file, all info and warn level log messages to stdout, and all error level log messages to stderr.

If, for example the user home directory is /home/bob and the executable name is BalauTests, the resulting debug stream for the above example would be file:///home/bob/.bora/BalauTests/debug.log.

			com.borasoftware {
				stream       = stdout
				error-stream = stderr
			}

The above specification will configure the com.borasoftware logger to output all logging to stdout apart from the error stream, which will be configured to output to stderr.

Logging stream plugins

Additional logging streams may be registered with the logging system before reconfiguring the system with schemes referencing these custom logging streams. This is achieved by deriving a new class from the LoggingStream base class, and creating a factory function with the same signature as specified by the LoggingStreamFactory typedef.

The LoggingStream base class has the following virtual methods:

			class LoggingStream {
				public: virtual void write(const std::string & str) = 0;
				public: virtual void flush() = 0;
			};

The string passed to the write method is the pre-formatted message.

The signature for logging stream factory functions is:

			using LoggingStreamFactory = LoggingStream * (*)(const std::string & uri);

The logging system is a pointer container for the logging streams, thus the logging stream factories return a raw pointer instead of a pointer container.

The URI passed to logging stream factory functions is the URI from the logging configuration text, with all macro placeholders expanded apart from the ${date} placeholder. If the URI specified in the logging configuration contains one or more occurrences of the ${date} macro placeholder, this placeholder will be present in the URI .

The factory function for the custom logging stream needs to be registered with the logging system by calling:

			Logger::registerLoggingStreamFactory(const std::string & scheme, LoggingStreamFactory factory);

The uri string of the custom logging stream is not specified by the logging system. The custom logging stream class must parse the supplied uri with its own DSL.

Design

This section provides a summary of the design of the logging system. It is not necessary to read this section in order to use the logging system.

Overview

The logging system is based around the public Logger class and the private LoggingState class. The LoggingState class is instantiated as a lazy singleton. The logging state contains a tree of loggers, plus pools for logging streams, log items, and composed log item vectors. The logging system contains a mutex that is locked when a logger is requested and when a reconfiguration is performed. Logging does not lock the mutex, hence concurrent logging and reconfiguration is supported.

Logging configuration text supplied to the logging system is parsed via the standard hierarchical properties parser.

The logging system is configured at application startup, in the first call to either Logger::getInstance or Logger::configure.

If a call to Logger::getInstance is the first call, the following procedure occurs:

a default logging configuration is created;
an override logging configuration is created from the contents of the balau-logging.hconf file if it exists;
the logging configuration created from balau-logging.hconf (if it exists) is cascaded onto the default logging configuration;
the properties of each resulting parent logger are propagated onto the children;
the logging levels of the loggers are set from the resulting level properties;
the streams of the loggers are set from the stream properties;
the message format item vectors of the loggers are set from the message format properties.

If a call to Logger::configure is the first call or on any subsequent call to Logger::configure, the following procedure occurs:

a default logging configuration is created;
an override logging configuration is created from the contents of the string passed to the configure() method;
the new logging configuration is cascaded onto the default logging configuration;
the properties of each resulting parent logger are propagated onto the children;
the properties of the existing loggers are wiped, ready for the new properties;
the logging levels of the loggers are set from the resulting level properties;
the streams of the loggers are set from the stream properties;
the message format item vectors of the loggers are set from the message format properties.

Concurrency

Configuration of the logging system is covered by a mutex. Only a single configuration execution may take place at any one time. The mutex is not locked on normal logging calls.

During configuration or reconfiguration, all missing streams, log items, and log item vectors are created and pooled. Subsequently, the atomic fields of new or existing loggers are set. This two stage process allows concurrent configuration and logging to occur without invalidating any of the existing loggers' state. In addition, the pooling ensures that there is no duplication of identical logging state, minimising the memory requirements of the logging system when reconfigured.

Due to TSO memory ordering, the atomic reads performed when logging are free reads on x86/x86-64 platforms.

The Logger class has the following fields that are read when logging a message. All mutable fields are implemented as atomic fields.

Field name	Comments
namespace	Doesn't change for the lifetime of the logger.
ns	Doesn't change for the lifetime of the logger.
level	Logging levels are read with std::memory_order_relaxed semantics.
stream[x]	The set of stream pointers is kept within a std::array<std::atomic<LoggingStream *>, 5>. Pointers are read with std::memory_order_relaxed semantics.
loggerItems	The entire log item vector is iterated over when logging a message. A pointer to the vector is read before iteration. The pointer is read with std::memory_order_acquire semantics.

All mutable logger state is updated with std::memory_order_seq_cst semantics during reconfiguration.