Binlog User Guide

A quick tour to a high-throughput low-latency logging library.

Hello World

#include <binlog/binlog.hpp>

int main()
{
  BINLOG_INFO("Hello {}!", "World");

  std::ofstream logfile("hello.blog", std::ofstream::out|std::ofstream::binary);
  binlog::consume(logfile);
}

Compile and run this program: it will produce a binary logfile, hello.blog. The logfile can be converted to text using bread:

$ bread hello.blog
INFO [10/05 20:05:30.176362854] Hello World!

Compared to other log libraries, Binlog is very fast for two reasons: First, Binlog is using asynchronous logging. The log events are first copied to a fast-access, lock-free intermediate storage, before consume writes them to the logfile. Second, Binlog produces a structured, binary log. This means, in the application, arguments and timestamps are not converted to text, and are not substituted into a format string. These happen in a later stage offline, while reading the logs (i.e: when running bread). As a bonus, structured logfiles are smaller, more flexible (e.g: text representation is customizable), and easier to data mine.

Logging

Binlog provides a macro interface for logging. The most basic log macros are: BINLOG_TRACE, BINLOG_DEBUG, BINLOG_INFO, BINLOG_WARNING, BINLOG_ERROR and BINLOG_CRITICAL, one for each severity. Usage:

BINLOG_INFO("Result: {}", 42);
// Outputs: INFO Result: 42

Each basic log macro takes a format string, and zero or more arguments. The format string can contain {} placeholders for the arguments. The number of placeholders in the format string and the number of arguments must match, and it is enforced by a compile time check. Events are timestamped using std::chrono::system_clock. The set of loggable argument types includes primitives, containers, pointers, pairs and tuples, enums and adapted user defined types - as shown below.

Logging Containers

Standard containers of loggable value_type are loggable by default:

std::vector<int>       vec{1,2,3};
std::array<int, 3>     arr{4,5,6};
std::forward_list<int> lst{7,8,9};
BINLOG_INFO("Sequence containers: {} {} {}", vec, arr, lst);
// Outputs: Sequence containers: [1, 2, 3] [4, 5, 6] [7, 8, 9]

std::set<int> set{4,8,15,16,23,42};
std::map<char, std::string> map{{'a', "alpha"}, {'b', "beta"}};
BINLOG_INFO("Associative containers: {} {}", set, map);
// Outputs: Associative containers: [4, 8, 15, 16, 23, 42] [(a, alpha), (b, beta)]

Aside the standard containers, any container-like type is loggable that satisfies the following constraints:

C style arrays of loggable elements can be wrapped in a view if the array size is known, to be logged as a container:

int array[] = {1, 2, 3};
BINLOG_INFO("Array: {}", binlog::array_view(array, 3));
// Outputs: Array: [1, 2, 3]

Logging Strings

Containers of characters (e.g: std::string or std::vector<char>) are logged just like any other container, but have a special text representation:

std::string str = "String";
BINLOG_INFO("Hello {}!", str);
// Outputs: Hello String!

const char* arguments, because of established convention, are assumed to point to null terminated strings, therefore logged and displayed accordingly.

Unfortunately, sometimes even char* is used to refer to a null terminated string (e.g: strerror). Binlog has no way to know whether the passed argument is a string (therefore calling strlen on it is safe) or just a pointer to a single character. To remain on the safe side, by default, Binlog assumes the latter. A few ways to workaround this:

Logging Pointers and Optionals

Raw and standard smart pointers pointing to a loggable element_type are loggable by default:

int* ptr = nullptr;
std::unique_ptr<int> uptr(std::make_unique<int>(1));
std::shared_ptr<int> sptr(std::make_shared<int>(2));
BINLOG_INFO("Pointers: {} {} {}", ptr, uptr, sptr);
// Outputs: Pointers: {null} 1 2

If the pointer is valid, it gets dereferenced and the pointed object will be logged. If the pointer is empty (i.e: it points to no valid object), no value is logged, and in the text log it will be shown as {null}. Logging of weak_ptr is not supported, those must be .lock()-ed first.

If C++17 is available, the standard optional with a loggable value_type can be made loggable:

#include <binlog/adapt_stdoptional.hpp> // must be included to log std::optional, requires C++17

std::optional<int> opt(123);
std::optional<int> emptyOpt;
BINLOG_INFO("Optionals: {} {}", opt, emptyOpt);
// Outputs: Optionals: 123 {null}

Aside the standard pointers, any pointer or optional-like type is loggable that satisfies the following constraints:

Logging Pairs and Tuples

Standard pair and tuple with loggable elements are loggable by default:

std::pair<int, char> p{1, 'a'};
std::tuple<std::string, bool, int> t{"foo", true, 2};
BINLOG_INFO("Pair: {}, Tuple: {}", p, t);
// Outputs: Pair: (1, a), Tuple: (foo, true, 2)

Aside the standard pair and tuple, any tuple-like type is loggable that satisfies the following constraints:

Logging Enums

Enums are loggable by default, serialized and shown as their underlying type:

enum Enum { Alpha = 123, Beta = 124 };
BINLOG_INFO("Enum: {}", Alpha);
// Outputs: Enum: 123

To make the log easier to read, enums can be adapted: adapted enums are still serialized as their underlying type, but in the log, the enumerator name is shown:

enum AdaptedEnum { Gamma, Delta };
BINLOG_ADAPT_ENUM(AdaptedEnum, Gamma, Delta)

BINLOG_INFO("Adapted enum: {}", Delta);
// Outputs: Adapted enum: Delta

The BINLOG_ADAPT_ENUM must be called in global scope, outside of any namespace. If an enumerator is omitted, the underlying value will be shown instead of the omitted enumerator name. Both scoped and unscoped enums can be adapted. For scoped enums, the enumerators must be prefixed with the enum name, as usual:

enum class ScopedEnum { Epsilon, Phi };
BINLOG_ADAPT_ENUM(ScopedEnum, Epsilon, Phi)

BINLOG_INFO("Scoped enum: {}", ScopedEnum::Epsilon);
// Outputs: Scoped enum: Epsilon

The maximum number of enumerators is limited to 100.

Logging User Defined Structures

User defined types outside the categories above can be still logged, if adapted:

struct Foo
{
  int a = 0;
  std::string b;

  bool c() const { return true; }
};

BINLOG_ADAPT_STRUCT(Foo, a, b, c)

BINLOG_INFO("My foo: {}", Foo{1, "two"});
// Outputs: My foo: Foo{ a: 1, b: two, c: true }

BINLOG_ADAPT_STRUCT takes a typename, and a list of data members or getters.

Data members are:

Getters are:

The member list does not have to be exhaustive, e.g: mutex members can be omitted, those will not be logged. The member list can be empty. The maximum number of members is limited to 100. BINLOG_ADAPT_STRUCT must be called in global scope, outside of any namespace. The type must not be recursive, e.g: Foo can't have a to be logged Foo* typed member. For more information and to make templates or recursive types loggable, see the Mserialize documentation on Adapting custom types and Adapting user defined recursive types for visitation.

Tools

bread

The binary logfile produced by Binlog is not human-readable, it has to be converted to text first. The bread program reads the given binary logfile, converts it to text and writes the text to the standard output.

$ bread logfile.blog > logfile.txt

The format of the text representation can be customized using command line switches:

$ bread -f "%S [%d] %n %m (%G:%L)" -d "%m/%d %H:%M:%S.%N" logfile.blog

The events of the logfile can be sorted by their timestamp using -s. The complete input is consumed first, then sorted and printed in one go.

$ bread -s logfile.blog

If no input file is specified, or it is -, bread reads from the standard input, acting like a filter that converts a binary log stream to text. This allows reading compressed logfiles:

$ zcat logfile.blog.gz | bread

With piping, a live logfile that is being written by the application can be read, even if log rotation is configured:

$ tail -c0 -F logfile.blog | bread

To customize the output and for further options, see the builtin help:

$ bread -h

brecovery

If the application crashes, because of the asynchronous logging employed by Binlog, it is possible that the most interesting log events, those directly preceding the crash, are still in the intermediate queues, waiting to be consumed and flushed to the logfile. The brecovery program takes a coredump (memory dump, crash dump, the memory image of the application at the time of the crash), searches for metadata and log queues, and writes recovered content to the specified file:

$ brecovery application.core recovered.blog

The recovered logfile is a binary logfile, that can be read using bread:

$ bread recovered.blog

A More Elaborate Greeting of the World

The first section, Hello World shows a very simple example, where the data flow might not be clear, due to the hidden state, which makes the example short. Consider the following, more explicit example:

#include <binlog/Session.hpp>
#include <binlog/SessionWriter.hpp>
#include <binlog/advanced_log_macros.hpp>

#include <fstream>
#include <iostream>

int main()
{
  binlog::Session session;
  binlog::SessionWriter writer(session);

  BINLOG_INFO_W(writer, "Hello {}!", "World");

  std::ofstream logfile("hello.blog", std::ofstream::out|std::ofstream::binary);
  session.consume(logfile);

  if (! logfile)
  {
    std::cerr << "Failed to write hello.blog\n";
    return 1;
  }

  std::cout << "Binary log written to hello.blog\n";
  return 0;
}

Session is a log stream. SessionWriter can add log events to such a stream. Multiple writers can write a single session concurrently, as between the session and each writer there's a queue of bytes. In the first example, the default instances of these types were used implicitly, provided by default_session() and default_thread_local_writer().

BINLOG_INFO_W is the same as BINLOG_INFO, except that it takes an additional writer as the first argument, which it will use to add the event instead of the default writer. The log event, created by this macro, is first serialized into the queue of the writer, upon invocation. If this is the first call to this macro, the metadata associated with this event is also added to the session of the writer. This macro is available for each severity, i.e: BINLOG_TRACE_W, BINLOG_DEBUG_W, BINLOG_INFO_W, BINLOG_WARNING_W, BINLOG_ERROR_W and BINLOG_CRITICAL_W. Serialization is done using the Mserialize library.

When session.consume is called, first the available metadata is consumed and written to the provided stream. Then each writer queue is polled for data. Available data is written to the provided stream in batches. At the end of the program, the health of the output stream is checked, to make sure errors are not swallowed (e.g: disk full).

Named Writers

To make the source of the events easier to identify, writers can be named. Writer names appear in the converted text output. This feature can be used to distinguish the output of different threads.

writer.setName("w1");
BINLOG_INFO_W(writer, "Hello named writer");
// Outputs: w1 Hello named writer

Severity Control

It might be desirable to change the verbosity of the logging runtime. Setting the minimum severity of the session disables production of events with lesser severities:

#include <binlog/Severity.hpp>

session.setMinSeverity(binlog::Severity::warning);
// trace, debug, info severities are disabled

If an event of disabled severity is given to a writer, it will be discarded without effect, and the log arguments will not be evaluated.

// after setting min severity to warning above:
BINLOG_INFO("Call f: {}", f()); // f will not be called

Categories

To separate the log events coming from different components of the application, a category can be attached to them:

#include <binlog/advanced_log_macros.hpp>

BINLOG_INFO_C(my_category, "This is a categorized event");
// Outputs: my_category  This is a categorized event

BINLOG_INFO_C is the same as BINLOG_INFO, except that it takes an additional category name as the first argument, which will be the category of the event. The category name can be any valid identifier, that must be available compile time. The name of the default category is main. This macro is available for each severity, i.e: BINLOG_TRACE_C, BINLOG_DEBUG_C, BINLOG_INFO_C, BINLOG_WARNING_C, BINLOG_ERROR_C and BINLOG_CRITICAL_C.

The BINLOG_<SEVERITY>_W and BINLOG_<SEVERITY>_C macros can be combined:

BINLOG_INFO_WC(writer, my_category, "My writer, my category");
// Outputs: my_category W1 My writer, my category

As above, there's one for each severity, i.e: BINLOG_TRACE_WC, BINLOG_DEBUG_WC, BINLOG_INFO_WC, BINLOG_WARNING_WC, BINLOG_ERROR_WC and BINLOG_CRITICAL_WC.

Consume Logs

Regardless the exact log macro being used (BINLOG_<SEVERITY>*), when an event is created, it is first put into the queue of the writer. When session.consume(ostream) is called, these queues are polled and the acquired data is written to the given ostream. If the writer is unable to write the queue, because it is full, it creates a new one, and closes the old. Therefore, a balance of new event frequency, queue size and consume frequency must be established. For applications built around a main loop, it might be suitable to consume the logs at the end of each loop iteration, sizing the queue according to the estimated amount of data one iteration produces:

binlog::Session session;
const std::size_t queueCapacityBytes = 1 << 20;
binlog::SessionWriter writer(session, queueCapacityBytes);

std::string input;
while (std::getline(std::cin, input))
{
  processInput(input, writer); // logs using `writer`
  session.consume(logfile);
}

For different kind of applications, calling consume periodically in a dedicated thread or task can be an option.

Log Rotation

Log rotation can be achieved by simply changing the output stream passed to Session::consume. Session does not know or care about the underlying device of the stream. However, metadata is not added automatically to the new file (as Session does not know that a rotation happened). To make the new file self contained (i.e: readable without the metadata in the old file), old metadata has to be added via Session::reconsumeMetadata:

if (std::rename("rotate.blog", "rotate.1.blog") != 0)
{
  std::cerr << "Failed to rename rotate.blog to rotate.1.blog\n";
  return 2;
}

logfile.close();
logfile.open("rotate.blog", std::ofstream::out|std::ofstream::binary);

// Metadata is now moved to rotate.1.blog, rotate.blog is empty.
// To make rotate.blog stand alone, re-add metadata:
binlog::default_session().reconsumeMetadata(logfile);

Text Output

The key feature of Binlog is producing structured, binary logfiles. However, in some cases, writing text output directly might be still desirable. This is easy to do using TextOutputStream:

#include <binlog/TextOutputStream.hpp> // requires binlog library to be linked
#include <binlog/binlog.hpp>

#include <iostream>

int main()
{
  BINLOG_INFO("Hello Text Output!");

  binlog::TextOutputStream output(std::cout);
  binlog::consume(output);

  return 0;
}

TextOutputStream requires the Binlog library to be linked to the application.

Multiple Output

Session::consume takes a single target only, but it is easy to multiplex the log stream to produce multiple output streams. With EventFilter, it is possible to route different kinds of events to different outputs, efficiently. In this example, the complete binary log is written to a logfile, but high severity events are also written to the standard error as text:

#include <binlog/EventFilter.hpp>
#include <binlog/TextOutputStream.hpp> // requires binlog library to be linked

// Write complete binlog output to `binary`,
// and also write error and above events to `text` - as text.
class MultiOutputStream
{
public:
  MultiOutputStream(std::ostream& binary, std::ostream& text)
    :_binary(binary),
     _text(text),
     _filter([](const binlog::EventSource& source) {
        return source.severity >= binlog::Severity::error;
     })
  {}

  MultiOutputStream& write(const char* buffer, std::streamsize size)
  {
    _binary.write(buffer, size);

    try
    {
      _filter.writeAllowed(buffer, std::size_t(size), _text);
    }
    catch (const std::runtime_error& ex)
    {
      std::cerr << "Failed to convert buffer to text: " << ex.what() << "\n";
    }

    return *this;
  }

private:
  std::ostream& _binary;
  binlog::TextOutputStream _text;
  binlog::EventFilter _filter;
};

Usage is like before:

std::ofstream logfile(path, std::ofstream::out|std::ofstream::binary);
MultiOutputStream output(logfile, std::cerr);
binlog::consume(output);