Boost C++ Libraries

PrevUpHomeNext

Adding more information to log: Attributes

In previous sections we mentioned attributes and attribute values several times. Here we will discover how attributes can be used to add more data to log records.

Each log record can have a number of named attribute values attached. Attributes can represent any essental information about the conditions in which the log record occurred, such as position in the code, executable module name, current date and time, or any piece of data relevant to your particular application and execution environment. An attribute may behave as a value generator, in which case it would return a different value for each log record it's involved in. As soon as the attribute generates the value, the latter becomes independent from the creator and can be used by filters, formatters and sinks. But in order to use the attribute value one has to know its name and type, or at least a set of types it may have. There are a number of commonly used attributes implemented in the library, you can find the types of their values in the documentation.

Aside from that, as described in the Design overview section, there are three possible scopes of attributes: source-specific, thread-specific and global. When a log record is made, attribute values from these three sets are joined into a single set and passed to sinks. This implies that the origin of the attribute makes no difference for sinks. Any attribute can be registered in any scope. When registered, an attribute is given a unique name in order to make it possible to search for it. If it happens that the same named attribute is found in several scopes, the attribute from the most specific scope is taken into consideration in any further processing, including filtering and formatting. Such behavior makes it possible to override global or thread-scoped attributes with the ones registered in your local logger, thus reducing thread interference.

Below is the description of the attribute registration process.

Commonly used attributes

There are attributes that are likely to be used in nearly any application. Log record counter and a time stamp are good candidates. They can be added with a single function call:

logging::add_common_attributes();

With this call attributes "LineID", "TimeStamp", "ProcessID" and "ThreadID" are registered globally. The "LineID" attribute is a counter that increments for each record being made, the first record gets identifier 1. The "TimeStamp" attribute always yields the current time (i.e. the time when the log record is created, not the time it was written to a sink). The last two attributes identify the process and the thread in which every log record is emitted.

[Note] Note

In single-threaded builds the "ThreadID" attribute is not registered.

[Tip] Tip

By default, when application starts, no attributes are registered in the library. The application has to register all the necessary attributes in the library before it starts writing logs. This can be done as a part of the library initialization. A curious reader could have wondered how trivial logging works then. The answer is that the default sink doesn't really use any attribute values, except for the severity level, to compose its output. This is done to avoid the need for any initialization for trivial logging. Once you use filters or formatters and non-default sinks you will have to register the attributes you need.

The add_common_attributes function is one of the several convenience helpers described here.

Some attrubutes are registered automatically on loggers construction. For example, severity_logger registers a source-specific attribute "Severity" which can be used to add a level of emphasis for different log records. For example:

// We define our own severity levels
enum severity_level
{
    normal,
    notification,
    warning,
    error,
    critical
};

void logging_function()
{
    // The logger implicitly adds a source-specific attribute 'Severity'
    // of type 'severity_level' on construction
    src::severity_logger< severity_level > slg;

    BOOST_LOG_SEV(slg, normal) << "A regular message";
    BOOST_LOG_SEV(slg, warning) << "Something bad is going on but I can handle it";
    BOOST_LOG_SEV(slg, critical) << "Everything crumbles, shoot me now!";
}

[Tip] Tip

You can define your own formatting rules for the severity level by defining operator << for this type. It will be automatically used by the library formatters. See this section for more details.

The BOOST_LOG_SEV macro acts pretty much like BOOST_LOG except that it takes an additional argument for the open_record method of the logger. The BOOST_LOG_SEV macro can be replaced with this equivalent:

void manual_logging()
{
    src::severity_logger< severity_level > slg;

    logging::record rec = slg.open_record(keywords::severity = normal);
    if (rec)
    {
        logging::record_ostream strm(rec);
        strm << "A regular message";
        strm.flush();
        slg.push_record(boost::move(rec));
    }
}

You can see here that the open_record can take named arguments. Some logger types provided by the library have support for such additional parameters and this approach can certainly be used by users when writing their own loggers.

More attributes

Let's see what's under the hood of that add_common_attributes function we used in the simple form section. It might look something like this:

void add_common_attributes()
{
    boost::shared_ptr< logging::core > core = logging::core::get();
    core->add_global_attribute("LineID", attrs::counter< unsigned int >(1));
    core->add_global_attribute("TimeStamp", attrs::local_clock());

    // other attributes skipped for brevity
}

Here the counter and local_clock components are attribute classes, they derive from the common attribute interface attribute. The library provides a number of other attribute classes, including the function attribute that calls some function object on value acquisition. For example, we can in a similar way register a named_scope attrubute:

core->add_global_attribute("Scope", attrs::named_scope());

This will give us the ability to store scope names in log for every log record the application makes. Here is how it's used:

void named_scope_logging()
{
    BOOST_LOG_NAMED_SCOPE("named_scope_logging");

    src::severity_logger< severity_level > slg;

    BOOST_LOG_SEV(slg, normal) << "Hello from the function named_scope_logging!";
}

Logger-specific attributes are no less useful than global ones. Severity levels and channel names are the most obvious candidates to be implemented on the source level. Nothing prevents you from adding more attributes to your loggers, like this:

void tagged_logging()
{
    src::severity_logger< severity_level > slg;
    slg.add_attribute("Tag", attrs::constant< std::string >("My tag value"));

    BOOST_LOG_SEV(slg, normal) << "Here goes the tagged record";
}

Now all log records made through this logger will be tagged with the specific attribute. This attribute value may be used later in filtering and formatting.

Another good use of attributes is the ability to mark log records made by different parts of application in order to highlight activity related to a single process. One can even implement a rough profiling tool to detect performance bottlenecks. For example:

void timed_logging()
{
    BOOST_LOG_SCOPED_THREAD_ATTR("Timeline", attrs::timer());

    src::severity_logger< severity_level > slg;
    BOOST_LOG_SEV(slg, normal) << "Starting to time nested functions";

    logging_function();

    BOOST_LOG_SEV(slg, normal) << "Stopping to time nested functions";
}

Now every log record made from the logging_function function, or any other function it calls, will contain the "Timeline" attribute with a high precision time duration passed since the attribute was registered. Based on these readings, one will be able to detect which parts of the code require more or less time to execute. The "Timeline" attribute will be unregistered upon leaving the scope of function timed_logging.

See the Attributes section for detailed description of attributes provided by the library. The complete code for this section is available here.

Defining attribute placeholders

As we will see in the coming sections, it is useful to define a keyword describing a particular attribute the application uses. This keyword will be able to participate in filtering and formatting expressions, like the severity placeholder we have used in previous sections. For example, to define placeholders for some of the attributes we used in the previous examples we can write this:

BOOST_LOG_ATTRIBUTE_KEYWORD(line_id, "LineID", unsigned int)
BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", severity_level)
BOOST_LOG_ATTRIBUTE_KEYWORD(tag_attr, "Tag", std::string)
BOOST_LOG_ATTRIBUTE_KEYWORD(scope, "Scope", attrs::named_scope::value_type)
BOOST_LOG_ATTRIBUTE_KEYWORD(timeline, "Timeline", attrs::timer::value_type)

Each macro defines a keyword. The first argument is the placeholder name, the second is the attribute name and the last parameter is the attribute value type. Once defined, the placeholder can be used in template expressions and some other contexts of the library. More details on defining attribute keywords are available here.


PrevUpHomeNext