Jan 6, 2021

Adding Context to Your Application Log

Introduction

The BDE 3.71 release adds new features to the ball logging framework, the most important of which is the ability to add attributes to log records.

 int processData(const bsl::string&        security,
                 const bsl::vector<char>&  data)
 {
      ball::ScopedAttribute securityAttribute("mylibrary.security", security);

      // ...

      int rc = reticulateSplines(data);

      return rc;
 }

 int reticulateSplines(data)
 {
     // ...

     if (0 != rc) {
         BALL_LOG_ERROR << "Error computing splines (" << rc << ")";
     }
     return rc;
 }

In the above example a logging attribute, “mylibrary.security”, is associated with the current thread’s logging context for the lifetime of the securityAttribute object. As a result, if attributes have been enabled in the log format, the error log message generated by this example might look like:

ERROR example.cpp:105 EXAMPLE.CATEGORY mylibrary.security="IBM US Equity" Error computing splines (-1)

Notice the attribute rendered does not appear in the logging message itself (“Error computing splines (-1)”), and is rendered as a name-value pair, meaning it can be easily parsed by log management systems like Humio or Splunk.

Important

Attributes will not appear in your log unless your ball::Observer format specification is configured to render attributes (see below).

Configuring an Observer to Output Attributes

Log attributes are not rendered by default as part of the log message (for backward compatibility). Clients can enable log attributes to be rendered for observers that support log record formatting:

  • ball::FileObserver

  • ball::AsyncFileObserver

  • ball::StreamObserver

  • ball::FileObserver2

Log message formatting is implemented by the ball_recordstringformatter component, which supports the following (new) format specifiers to render log attributes:

Format Specifier

Description

%A

Log all the attributes of the record

%a

Log only those attributes not already logged by the “%a[name]” specifier

%a[name]

Log a attribute’s value, where ‘name’ is the attribute’s name

The following code snippet illustrates the creation and configuration commonly used by observers:

int initFileObserver() {
   // 'ball::FileObserver' uses an internal record string formatter and
   // is configured by supplying a format string via 'setLogFormat().

   bslma::Allocator *alloc = bslma::Default::globalAllocator(0);

   bsl::shared_ptr<ball::FileObserver> observer =
       bsl::allocate_shared<ball::FileObserver>(alloc);


   // Set the log format for file and console logs to "\n%d %p:%t %s %f:%l %c %a %m\n"
   observer->setLogFormat(ball::RecordStringFormatter::k_BASIC_ATTRIBUTE_FORMAT,
                          ball::RecordStringFormatter::k_BASIC_ATTRIBUTE_FORMAT);

   if (0 != observer->enableFileLogging("myapplication.log.%T")) {
       bsl::cout << "Failed to enable logging" << bsl::endl;
       return -1;
   }
   ball::LoggerManager::singleton().registerObserver(observer, "default");
   return 0;
}

New Suggested Log Record Format

The logger now provides a new constant, ball::RecordStringFormatter::k_BASIC_ATTRIBUTE_FORMAT, which is the recommended log format specification for most users (see the example above). The default log format specification remains the same to avoid changing behavior for existing applications. Note that the default format specification might be changed in a subsequent release of BDE.

Details on Using Attributes

The ball library provides the following classes that implement ready-to-use application solutions for log attributes:

  • ball::Attribute This class represents an attribute that consists of a (literal) name (held but not owned), and an associated value (owned) that can be an int, bsls::Type::Int64, or a bsl::string.

  • ball::ScopedAttribute Scoped guard that creates an attribute container with a single attribute supplied at construction and adds this container to the current thread’s context. The container is removed from the thread context when the guard leaves the scope.

  • ball::RecordStringFormatter Implements a log record formatting functor. Formats log records into human-readable log messages according to the specified format specs.

Note that ball::ScopedAttribute is recommended for most applications (see Performance below). However, some low-level performance-critical systems (e.g., BAS) may implement custom attribute-collection mechanisms. This adds considerable complexity, but can deliver a small benefit in performance by taking advantage of compile time knowledge of the attributes being collected. See ball::AttributeCollectorRegistry for more details on attribute collection mechanism.

Advanced usage examples can be found in the BALL package documentation. We recommend reaching out to the BDE team for guidance before using these features .

Important

Use of ball::UserFields is now deprecated in favor of the new log attributes API.

Attribute Naming Recommendations

Use the following naming conventions for attribute names:

  • An attribute name should start with an alphabetic character; no other special characters or digits should be allowed as the first character of an attribute name.

  • An attribute name should not contain whitespaces.

  • An attribute name should contain only alphanumeric characters, underscores(‘_’), and dots(‘.’). Do not use any other special characters.

It is highly recommended to use “namespaces” when naming attributes to avoid attribute name collisions. For example, consider these attribute names:

Attribute Name

Notes

“context id”

BAD (contains whitespace)

“contextid”

BAD (no namespace)

“bde.contextid”

GOOD

“bde.logger.context_id”

GOOD

Handling of attributes with identical names is dictated by the underlying container(s) that store the attributes and the ball library cannot guarantee any deterministic behavior in this case. It is the responsibility of the users to guarantee uniqueness of attribute names.

Important

Log record attributes are rendered as space-separated ‘name=”value”’ pairs (for example: mylibrary.requestType="POST"). Note that attribute names are not quoted, whereas attribute values, if they are strings, are always quoted.

Humio and Splunk

Humio and Splunk are two popular log management systems used at Bloomberg. The format of the log attributes rendered by the ball logging system is designed to be parsed automatically by these systems.

Users of ball logging are also encouraged to format the text of their messages to be easily digested by these systems. For example, providing information as key-value pairs, where appropriate. Additional information can be found at Splunk Logging Best Practices and Humio Built-In Parsers.

Performance

The benchmark below gives some insight into the the cost of attribute-based logging and other logging features. The absolute times should be taken with a grain of salt – they are specific to the platform, archicture, build mode, machine, and time of day at which the benchmark was run. However, they should give some sense of the relative cost of various logging actions.

“Marginal Cost” Explained

The benchmark results present the “Marginal Cost” of various operations. The intention is to show the added cost for performing a single additional operation to an existing piece of code. E.g., the marginal cost of “One Log Statement Logging to Memory” is computed by comparing a test run A’, where a log record is written to an in-memory buffer on each test iteration, to a test-run A, which is (as close as possible) identical, but with the log category disabled so the logging statement does not write to the log. The Marginal Cost (MC) is computed using (A’-A)/N (N is the number of test iterations, in this case 5,000,000).

Results

Operation

Time microseconds

Notes

Baseline (nearly empty function)

0.003

Hash a ~25 char string

0.031

Provided to give a sense of scale

One Disabled Logging Statement

0.000

Cost is below the ability to measure over background noise

One Log Statement Logging to Memory

1.340

One log statement that will write to an in-memory buffer

One Log Statement Logging to a File

2.155

One log statement that will write to a file

Creating (3) ScopedAttributes

0.077

1 scoped attribute would be ~.03 microseconds

Publishing Attributes (w/ no attributes)

0.021

Adding %a to the log format specification but with no attributes to log

Publishing Attributes (w/attributes)

0.437

Adding %a to the log format specification and 3 attributes to log

High-Level Conclusions

  • Log statements that are not enabled are very low cost

  • Creating a log attribute has a small but measureable cost (similar to hashing a string)

  • The expense of publishing an attribute is mostly in writing the values, and is proportional with the amount of additional text being written

Our Recommendations

  • Use ball::ScopedAttributes where needed, but use them judiciously. Performance-critical infrastructure libraries might consider custom attribute containers (see Details on Using Attributes above).

  • Most users should enable the (non-default) format specification to enable attributes to be published to their log.

Benchmark Details

The source code and build instructions for the benchmark are here: https://bbgithub.dev.bloomberg.com/bde-extras/ball-benchmark

The data for the test run is here: Ball Attributes Benchmark Google Sheet

Context for the test:

  • OS: Red Hat Enterprise Linux Server 7.6 (Maipo)

  • Build: gcc-7.3.1, -02, -m64, –std=c++17

  • Processors: 47 CPU, Intel(R) Xeon(R) CPU E5-2687W v4 @ 3.00GHz (12 core)

  • Local Disk

  • Machine Load at Start: 99.6% idle

  • Discard initial test run data

Other Features

  • ball::StreamObserver now supports log record formatting by suppling a ball::RecordStringFormatter .

  • The BDE team is working on a JSON log record string formatter that will render published log records as JSON. This is expected to be released at the end of Q1.