Log++ -- A Logging Framework for Modern Development

Log++ is a logging framework designed to support modern development needs.

• Log++ is fast! 4-7 times faster than bunyan and 2 times faster than pino. Log++ can process a log statement in under 1µs of blocking time, with the high cost formatting operations done as a background tasking using a N-API module.
• Log++ helps banish log spew with novel multi-level logging support. All (verbose) log messages are initially stored in an in-memory buffer for high performance and if they are needed for core dumps. However, these can be filitered out when writting so they don't pollute the saved logs with overly detailed information.
• Log++ logs are machine parsable. The logging output provides structured and machine parsable formats (even with printf style logging). These formats can be explicitly provided/managed via external JSON specifications. Common prefix data and macros for embedding useful system information are also available.
• Log++ provides modular flexible logging with unified control of logging levels, categories, and output across modules. Log++ supports both child loggers and logic for controlling the output from subloggers created by other modules that your application uses.

Basic Usage

Log++ is designed to be simple to use and provides a nearly drop in replacement for existing logging frameworks.

//Import the logpp module and create a logger (named "myapp") 
const log = require("logpp")("myapp");

//Add a format for better structured log output and provide it on the logger (prefixed with a "$")
log.addFormat("Hello", "Hello %s!!!");

//Emit the message specified by the format -- Hello "World"!!!
log.info(log.$Hello, "World");

//Or emit message given by a printf style format -- Hello "printf"!!!
log.info("Hello %s!!!", "printf");

Performance

Log++ is designed to minimize logging overhead on your application so you can use it to provide rich/useful information about your application without impacting your users. As a very rough benchmark we have a comparison with three other popular loggers -- Bunyan, Debug, and Pino (Extreme). The first 3 benchmarks are taken from Pino and the last one is from us. Each message is written 100k times and these timings are from an Intel Core i7-5600 running Node-V8 10.0 on Windows 10.

• Basic: info('hello world -- logger')
• String: info('hello %s', 'world')
• Multi: info('hello %s %j %d', 'world', { obj: true }, 4)
• Complex: info('hello at %j from %s with %j %n -- %s', new Date(), app, ['iter', { f: i, g: i.toString() }], i - 5, (i % 2 === 0 ? 'ok' : 'skip'))

The results in the table below show a representative timing taken for each logger framework on each benchmark and the speedup of Log++ over the next best performing framework.

| Logger | Basic | String | Multi | Complex | | ------ | ------ | ------ | ------ | ------ | | Bunyan | 690 ms | 779 ms | 1106 ms | 1578 ms | | Debug | 266 ms | 385 ms | 515 ms | 842 ms | | Pino | 141 ms | 211 ms | 378 ms | 887 ms | | Log++ | 71 ms | 109 ms | 253 ms | 438 ms | | Speedup | 1.98x | 1.93x | 1.49x | 1.92x |

As seen in our results Log++ is consistently the lowest overhead logger, in most cases spending nearly 2x less time blocking the main event thread, than any of the others.

Logging Levels and Categories

Log++ supports 8 logging levels. At each level only messages at the given level and higher will be processed, any messages at lower levels will be nop'd or filtered (see multi-level logging below). For each level the logger exports a function with the corresponding name. Thus to log a message at the INFO level you would call log.info(...) and to log at the DEBUG level you can call log.debug(...). The available levels and order is:

• OFF        // all messages are disabled
• FATAL     // fatal messages only
• ERROR   // error and higher
• WARN    // warn and higher
• INFO      // info and higher -- default for emit (see multi-level logging)
• DETAIL   // detail and higher -- default for in-memory (see multi-level logging)
• DEBUG   // debug and higher
• TRACE    // trace and higher
• ALL         // all messages are enabled

In addition to adjusting the level at which log messages are processed Log++ also supports message categories to organize log messages and to selectively enable/disable them at a fine grain level. Categories can be defined using any name desired and enabled/disabled on a per logger basis.

Setting up and using a logging category can be done as follows:

//Define and enable the "performance" category
log.enableCategory("Performance", true);

//Emit the message specified by the format under the given category-- "Hello World!!!"
log.info(log.$$Performance, log.$Hello);

//Disable the "performance" category
logpp.enableCategory("Performance", false);

//NOP since Performance category is disabled now
log.info(log.$$Performance, logpp.$Hello);

Thus categories provide a simple way to selectively turn off/on related streams of logging data and (like logging levels) can be dynamically adjusted during execution.

Log++ also provides simple conditional logging with If versions of all the unconditional logging functions. These functions take a boolean as the first argument and only perform the logging work if the value is true.

log.info(log.$Hello); //"Hello World!!!"

let x = 1;
log.infoIf(x === 1, log.$Hello); //"Hello World!!!"
log.infoIf(x === 0, log.$Hello); //NOP

Multi-Level Logging

In the default mode Log++ operates with a novel multi-level logging system that consists of two layers and three phases.

1. An in memory buffer where all enabled messages are synchronously copied into during the logger call (info/debug/etc.). In this step the formatter info + information on the arguments is copied but no formatting or emitting is done.
2. Asynchronously messages + data from the in memory buffer that are over time or memory limits (see Multi-Level Log Layer Management below) are checked and either discarded or copied to a format & emit buffer. The decision to copy/discard is governed by the level the message was logged at and the emit level the loggers are running at.
3. In a native module, running on a background thread, the messages to be emitted are formatted into specified wire format (currently JSON and Binary -- see Formatters below). When this is complete the results can be written directly to stdout or a user provided writable stream (see Emit Channels below).

With this design the only blocking cost on the main thread for a log operation is an enabled check, an immediate check/copy of the message data, and a bulk filter copy. This time is much smaller than the format and emit time which then happens on an asynchronous background thread -- resulting in a 5x or more reduction in performance overhead when compared to console.log style logging.

In addition to this default asynchronous mode Log++ also supports completely synchronous processing (at lower performance) as an option and as the default when the debugger is attached vs. high performance async when running in production (see Sync vs. Async below).

Beyond the performance implications of splitting the logging into 2 layers there are two other substantial benefits:

1. Since the initial logging of a message is cheap (~1µs) it is feasible to log at a much higher rate than previously possible, say DETAIL or DEBUG instead of INFO or just WARN. Then, when an error occurs this invaluable information is present in the in-memory buffer and can be included with the rest of the error dump.
2. While this high fidelity logging data is desireable when analyzing an error or performance issue for normal execution it is simply clutter that unnecessarily takes up and space and complicates other informational log analysis tasks. The ability to discard messages as they move to the emit buffer allows us to eliminate this clutter and only save messages that are generally useful and worth longer term storage (say INFO or just WARN).

Full Log Write Hooks

To maximize the value of the in-memory log ability we support the hooking of common failure events and will perform an explicit flush of the full in-memory log. The auto-hooked events are:

• Unhandled exception
• Exit with a non-zero exit code

In other cases you may want to programatically (and synchronously) produce a full dump of the in-memory log. This can be done with the emitLogSync(FULL, DETAIL) API which synchronously returns the formatted log data as a string (where the log can be fully flushed and can include details from all the log messages without any filtering).

Multi-Level Log Layer Management

Log++ provides a range of settings to control how data is stored and flows between the levels in the log and is ultimately emitted.

Sync vs. Async: Log++ supports asynchronous logging, for best performance and other benefits of multi-level logging, as well as fully synchronous logging for simpler debugging and testing scenarios. The mode can be set with the flushMode option -- either 'ASYNC' | 'SYNC' | 'NOP'.

The default mode is 'ASYNC' which enables formatting in the background of messages that have been added to the emit worklist. This option provides the best performance. The 'SYNC' mode does synchronous processing of the messages in the emit worklist, resulting in higher overhead than the 'ASYNC' mode but, if used in combination with a