NAV

The pid-log package implement the runtime logging facility of PID. By logging we mean generating messages that inform about the state of a running program. These messages can be read from standard outputs or files and may be useful to notify some tools of interesting events, to provide debug information to developpers, or traces of program execution.

pid-log intend to provide a powerful but easy to configure logging tool for developpers with features:

  • possibility to deactivate logs for a the whole program. Useful when you want to get real-time compatible performance and log is not required.
  • filtering log messages either according to their severity or depending on their emitting place (component, package, framework).
  • generating various log outputs from the same global log trace in a program. For instance usefull to discriminate errors or debug traces from other information.
  • formatting of log messages is standardized and can be configured to get various information such as: calling site information (line in source file, calling function), runtime trace generation (date, thread) or PID related information (framework, package, component of the emitting component).
  • easy configuration of logger system at global level. This way libraries can be completely agnostic from the way logs they generate are finally managed.

The basics on using the log library can be found in this tutorial.

The following sections provide more in depth explanations on how the logging system is configured and used.

The LOGGABLE property of components

A component is defined as LOGGABLE is it can be identified as the emitter of specific log traces. To tell PID to identify the component as loggable, in CMake:

...
PID_Component(  my-component 
                ...
                LOGGABLE)
...

The LOGGABLE property tells PID to generate a specific header file that will be included in public headers (for components having public interface) or sources (e.g. for applications). This header file will be used by the PID system to identify the emitting component at runtime. LOGGABLE is particularly usefull for libraries because we sometime want to filter log messages coming from a given package or component and LOGGABLE is used to automatically deduce the calling site. So by default any library that generates log traces using pid-log should be a loggable object.

The generated header file has pattern name <package>_<component>.h and is located in the pid/log subfolder of:

  • component include folder if it is a component with public headers (header, static or shared library).
  • component source folder otherwise (module, test or application).

Its content looks like:

#pragma once

#ifdef LOG_pid_log_pid_log_test_hdr

#include <pid/log.h>

#undef PID_LOG_FRAMEWORK_NAME
#undef PID_LOG_PACKAGE_NAME
#undef PID_LOG_COMPONENT_NAME

#define PID_LOG_FRAMEWORK_NAME "pid"
#define PID_LOG_PACKAGE_NAME "pid-log"
#define PID_LOG_COMPONENT_NAME "pid-log-test-hdr"

#endif

Values for PID_LOG_FRAMEWORK_NAME, PID_LOG_PACKAGE_NAME and PID_LOG_COMPONENT_NAME is adapted depending of component and package information and is automatically generated by PID using CMake description.

The only thing that remain to be done by the developer is to include this header in its source file, respecting these constraints:

  • this header must be the last one included in your source or header files. Indeed this is the only way you are ensured that this code will not be overwritten by a header of another included loggable component.
  • as far as possible include this header only in sources, not in headers. A notable exception is when public headers contain template code that generates log traces.

Configuring log traces generation

The log library tutorial explains how to write log traces, how to deactivate them and how to filter them using default provided configurations. But the real power of pid-log comes when you want to filter traces for applications with many dependencies. To do that you need to understand how the logging system works and how to configure it.

Base concepts

First of all, you need to understand a few concepts that are relevant for log trace generation and configuration:

  • The logger refers to the unique global object that controls the generation of log messages. It can be configured and controlled at runtime. It is accessed either via the pid::logger() function or via the PID_LOGGER macro.
  • A component is loggable if it can be identified at runtime by the logger. At CMake definition time, it is declared as LOGGABLE, see previous section.
  • A proxy refers to the object used to generate log traces. Each loggable component is bound to a specific proxy object. There is also a global anonymous proxy for non loggable components. Proxies are accessed in code using the pid_log macro. This macro automatically retrieves the adequate proxy for a given component, or if none found, uses the anonymous proxy.
  • A filter is an object in charge of filtering log traces according to some rules. The logger has a global filter that is empty by default (i.e. every log message is valid) and can be configured.
  • A sink is an objec in charge of generating output from log traces. A sink has:

  • a filter that is used to filer log messages coming from proxies.
  • a formatter used to format the output with additional information
  • a set of outputs streams, that are the streams where the filtered messages are written with specific format.

Sinks and global filter need to be configured in order for the logger to work properly (i.e. generate outputs from log traces). This is achieved either directly using the pid-log API or by using configuration files, which is obviously the preferred way.

Configuring the logger

The log library tutorial explains how to use the configure method of PID_LOGGER object to control control how logs are filetered, using default provided configuration files. These configuration files are setting the values for global filter and sinks and also if the logger is activated.

For instance:

  • the configuration file deactivated_logs.yaml is like this:
activate: false

The logger is basically deactivated so no log trace is written.

  • the configuration file only_errors_logs.yaml is like this:
activate: true
accept:
  severity: [error, critical]
sinks:
 - outputs: [STD]
   format: [date, severity]

The logger global filter only accepts logs with error and critical severity. If message are of one of those severities then they are forwarded to the only sink defined. This later define no filter and write everything only to standard output (using outputs: [STD]) and the formatted logs contains date of log generation and its severity (using format: [date, severity]).

User is encouraged to write its own usefull configuration files for their applications. Each configuration file should be defined as a runtime ressource of the configuring component (typically the application), this way everything will be more or less automatic by calling configure function with the runtime resource relative path. For instance:

...
PID_Component(  my-app 
                ...
                RUNTIME_RESOURCES my-app_logs_config)
...

with my-app_logs_config the folder containing the possible configuration for your application logs. And in sources:

#include <my/component.h>//global header for my-component
#include <pid/log.h>

int main(int argc, char * argv[]){
    ...
	PID_LOGGER.configure("my-app_logs_config/my_usefull_config.yaml");
	...
}

with my-my_usefull_config.yaml the configuration file you just wrote.

Writing custom configuration file can be very usefull to avoid printing information you do not care about and that are generated by various libraries. This is particularly true when you application use a big number of libraries.

Writing configuring files

To understand how to write logger configuration file, let’s start with this simple example:

activate: true
accept:
  severity: debug
reject:
  frameworks: [a_framework, another_framework]
sinks:
 - outputs: [STD]
   format: [date, source]

In this example, the logger will remove any message that is not a debug message (due to the global accept rule), then any message coming from components belonging to frameworks a_framework or another_framework is also removed (due to the global reject rule). All messages allowed by the global filter are then forwarded to the unique sink. This later simply writes to the standard output messages with labels specifying source code that made the call, and date when message has been generated.

Here are the possible yaml fields available:

  • activate is used to tell if the logger is activated dor not. In later case no output traces will be generated.
  • accept is used to define which traces are accepted. Any log message with at least one adequate property among those listed will be accepted. In the example any debug message is accepted. Any log message whose property does not match any of the accepted properties will be rejected.
  • reject is used to define which messages, among those that are accepted, is rejected. In the example, any message coming from a component belonging either to framework a_framework or to framework another_framework will be rejected.
  • sinks is the set of sinks used by the logger. Each sink must define at least one output stream (using outputs keyword).

accept and reject can be used either at global scope (like in the example) or at sink scope. If used at global scope, they will configure the global filter, otheriwse they configure the sink specific filter. The global filter is used to remove messages before forwarding the messages to the sinks, so every message rejected at global level will never appear in any sink. At sink scope, they are used to filter messages that will be finally printed in outputs. From yaml perspective accept and reject are maps with following subproperties:

  • severity is the set of severity matched by the filter. Value for this field can be either a scalar (e.g. with value chosen in info, debug, warning, error and critical) or a sequence of scalars. If the message matches one of the specified severities, the filter condition is satisfied.
  • frameworks is the set of frameworks matched by the filter. Value for this field can be either a scalar (e.g. with name of target framework as value) or a sequence of scalars. If the message matches one of the specified frameworks, the filter condition is satisfied.
  • packages is the set of packages matched by the filter. Value for this field can be either a scalar (e.g. with name of target package as value) or a sequence of scalars. If the message matches one of the specified packages, the filter condition is satisfied.
  • components is the set of packages matched by the filter. Value for this field can be either a scalar (e.g. with name of target component as value) or a sequence of scalars. If the message matches one of the specified components, the filter condition is satisfied.

Each sink defined by sinks is an element of a sequence. It defines:

  • outputs: this mandatory property defines where the sink will generate output traces from logged messages. Possible values are STD (standard output), ERROR (error output), LOG (log output), FILE (file output). The LOG output write in linux system log (i.e. /var/log/syslog). FILE specifies a path to a file where data will be written, this path being a PID_PATH (either an absolute path or a path being a runtime resource of a component, basically the application).
  • accept and reject are used to define the sink specific filter. They follow same rules as for global filter.
  • format is used to define the format of the generated output. It is a scalar or sequence of scalar used to specify output using specific values: date (printing timing info), severity (printing severity info), source (printing info about source code that generated the log), function (printing info about function that generated the log message), thread (printing info about the thread that generated the log message), framework, package and component (printing info about PID component that generated the log message).

Here are some more examples:

activate: true
reject:
  severity: info
sinks:
 - outputs: 
   - STD
   - FILE: +my-app_logs/log_everything_except_info.txt
   format: [source, severity]
   accept:
     frameworks: my-framework

This configuration reject every info message then for the others it forward it to a unique sink that:

  • write both to standard output and to a file my-app_logs/log_everything_except_info.txt where my-app_logs is supposed to be a runtime resource of the application.
  • will only accept messages coming from components belonging to the framework my-framework.
  • finally prints messages with a header including source information and severity, something that could look like:
{my-package/src/my_component/my_component.cpp:48}[debug]debug message
{my-package/src/my_component/my_component.cpp:158}[error]my error message
{my-package/src/my_other_component/super_code.cpp:158}[warning] possible mistake
...

We suppose here that logs are produced by two components my-component and my-other-component bioth belonging to same package my-package and so implicitely belonging to a same framework my-framework. The source header is particularly usefull for debugging purpose letting you understand which line of code generated the logged message.

Another interesting feature is to discriminate information into different sinks:

activate: true
sinks:
 - outputs: 
   - FILE: +my-app_logs/log_everything_except_info.txt
   format: [source, severity]
   accept:
     frameworks: my-framework
	 severity: [critical, error, debug, warning]
   - STD
   format: [severity]
   accept:
	 package: my-package
   reject:
	 severity: debug

The first sink will write every potential problem coming from a component of my-framework into the file log_everything_except_info.txt. It can be used for instance for debugging purpose, letting your understand problems that could come various packages belonging to my-framework.

The second sink will write non debug messages coming from my-package to standard output, which can be potentially usefull to understanrd the behavior of the package your are currently developping.