rvagg/bole

A tiny JSON logger

bole

A tiny JSON logger, optimised for speed and simplicity

Log JSON from within Node.js applications. The log format is obviously inspired by the excellent Bunyan and is likely to be output-compatible in most cases. The difference is that bole aims for even more simplicity, supporting only the common-case basics.

bole is designed for global singleton use. Your application has many log sources, but they all aggregate to the same sources. You configure output in one place for an application, regardless of how many modules and dependencies are also using bole for logging.

Example

mymodule.js

const log = require('bole')('mymodule')

module.exports.derp = () => {
  log.debug('W00t!')
  log.info('Starting mymodule#derp()')
}

main.js

const bole = require('bole')
const mod  = require('./mymodule')

bole.output({
  level: 'info',
  stream: process.stdout
})

mod.derp()

$ node main
{"time":"2014-05-18T23:47:06.545Z","hostname":"tweedy","pid":27374,"level":"info","name":"mymodule","message":"Starting mymodule#derp()"}

Features

• Very fast, bole has been optimised for common cases and is designed to add minimal overhead to your applications, use the bole.setFastTime() feature (below) to make it even faster
• Arbitrary log names, create a logger by calling const log = bole('logname') and 'logname' will be attached to the output
• Loggers have 4 levels / methods: log.debug(), log.info(), log.warn(), log.error()
• Log methods accept console.log() style strfmt output ( usingutil.format()): log.warn('foo %s', 'bar')
• Log methods accept arbitrary objects that extend the log output data, each property on the object is attached to the debug output object
• Log methods accept Error objects and print appropriate Error properties, including a full stack trace (including any cause where supported)
• Log methods accept http.IncomingMessage for simple logging of an HTTP server's req object. URL, method, headers, remote host details will be included in the log output.
• Newline separated JSON output to arbitrary streams
• Any number of output streams, each with configurable minimum log-levels
• Fast short-circuit where no loggers are configured for the log-level, effectively making log statements a noop where they don't output
• Sub-logger to split a logger for grouping types of events, such as individual HTTP request
• Object-logging (i.e. not automatically stringified) if you pass an objectMode:true stream for output.

API

bole(name)

Create a new logger with the supplied name to be attached to each output. If you keep a logger-per module you don't need to pass loggers around, keep your concerns separated.

logger#debug(), logger#info(), logger#warn(), logger#error()

Loggers have 4 roughly identical log methods, one for each of the supports log-levels. Log levels are recorded on the output and can be used to determine the level of detail passed to the output.

Log methods support the following types of input:

• Error objects: log output will include the error name, message, complete stack and also a code where there is one. Additionally you can supply further arguments which are passed to util.format() and attached as a "message" property to the output: log.warn(err, 'error occurred while fetching session for user %s', user.name)

• http.IncomingMessage for simple access-log style logging. URL, method, headers, remote address and remote port are logged: log.info(req), further data can be provided for a "message" property if required.

• Arbitrary objects whose properties will be placed directly on the logged output object. Be careful passing objects with large numbers of properties, in most cases you are best to construct your own objects: log.debug({ dbHost: 'foo', dbPort: 8080 }, 'connecting to database'), further data can be provided for a "message" property if required.

• console.log style output so you can treat loggers just like console.log(): log.info('logging a string'), log.info('it has been said that %d is the meaning of %s', 42, 'life'), log.debug('foo', 'bar', 'baz').

If you require more sophisticated serialisation of your objects, then write a utility function to convert those objects to loggable objects.

logger()

The logger object returned by bole(name) is also a function that accepts a name argument. It returns a new logger whose name is the parent logger with the new name appended after a ':' character. This is useful for splitting a logger up for grouping events. Consider the HTTP server case where you may want to group all events from a particular request together:

const log = bole('server')

http.createServer((req, res) => {
  req.log = log(uuid.v4()) // make a new sub-logger
  req.log.info(req)

  //...

  // log an error against this sub-logger
  req.log.error(err)
})

In this case, your events would be listed as something like "name":"server:93f57a1a-ae59-46da-a625-8d084a77028a" and each event for a particular request would have the same "name" property, distinct from the rest.

Sub-loggers can even be split in to sub-sub loggers, the rabbit hole is ~bottomless.

bole.output()

Add outputs for application-wide logging, accepts either an object for defining a single output or an array of objects defining multiple outputs. Each output requires only a 'level' and a 'stream', where the level defines the minimum debug level to print to this stream and the stream is any WritableStream that accepts a .write() method.

If you pass in a stream with objectMode set to true then you will receive the raw log objects rather than their stringified versions.

bole.output([
  { level: 'debug', stream: fs.createWriteStream('app.log') },
  { level: 'info', stream: process.stdout }
])

bole.reset()

Clears all output streams from the application

bole.setFastTime()

If speed is something you care about and you can handle time in milliseconds since epoch (Date.now()) rather than the full ISO string (new Date().toISOString()) in your logs then use bole.setFastTime(true) to shave off some precious microseconds.

Note that this will reset to the default of false when you use bole.reset()

Additional features

If you need to serialise specific types of objects then write a utility function to convert to a loggable object.

If you need a special kind of output then write a stream to accept output data.

If you need to filter a present output data in a special way, write a package to do it and publish it in npm.

License

bole is Copyright (c) 2014 Rod Vagg @rvagg and licensed under the MIT License. All rights not explicitly granted in the MIT License are reserved. See the included LICENSE.md file for more details.

bole's Issues

output formatter

If you need to filter a present output data in a special way, write a package to do it and publish it in npm.

I'd like to change the output a bit. I'm running on amazon lambda and I don't need the PID but I do need some extra environment variables. I was looking through the source and it doesn't seem like there is a good way to hook into how the logging object is created. Any pointers?

Thanks!

Question: disable logging?

I got a sneaking suspicion that this is a too simple question, but I'll add it anyway as I've found no way to do this. I'd like to disable the bole logger, how can I achieve that?

I use bole to log inside a library module, but I want the consumer of the library to be able to toggle logging inside my module. For some reason I can't get bole to not log once I've required the module.

Use of os.hostname() causes runtime crash on Wndows 7

hello, when i use pnpm on win7, i got an error, then i find there error stack point to

bole/bole.js

Line 7 in 9929b9e

const hostname = require('os').hostname()

the cause reason is paralleldrive/cuid#263

hope it can be fixed 🙏

Logger creation

Instead of having a unique logger instance which can use any module in the npm registry, have you thought about letting the user to create instances? I feel very insecure having only one instance. I'd prefer to have a wrapper around the bole module, something like this:

//logger.js
module.exports = require('bole').createLogger();
module.exports.output([...]);

And then use that instance as usual:

var log = require('../../very/long/path/to/logger')('my-module');
log.info(...);

You could maintain the singleton instance, but third-party modules shouldn't use a logger module, bole shouldn't be a dependency of any other module.

You may think that this approach generates the very-hard-to-maintain relative paths, and it's true, but this can be resolved in other ways. Furthermore, if you're using a web framework with a very basic evented logging mechanism like hapi, you don't need to care about this. Hapi emits events which can be listened in a single place. With the below code you just need to require the module once in your app. This is just a sample, but other frameworks could work in a similar way:

//Anywhere
hapiServer.log(['my-module', 'error'], new Error ('foo')); //This can be wrapped in a function: log(new Error('foo'))
hapiRequest.log(...);

//Listening
var logger = require('../../very/long/path/to/logger'); //The path is hardcoded only once
server.on('log', function(event) {
  bole(event.tags[0])[event.tags[1]](event.data);
  //This will be resolved to: bole('my-module').error(err)
})

pretty printing output during development

Great fast library..are you using another tool to format the logs during development? If not, is there a hidden option for formatting the output like JSON.stringify(object, null, 2)?

How to disable logging from sub modules, but keep logging from the "top level" app

I have several modules that use bole for logging and one of them is very chatty (on info level),
so it would be nice to have ability to filter output stream based on log names, so I can have separate file with app's only logs.

Is it something that could be done in the existing version?

Thank you.

tests failing on node 5

Running the unmodified tests on node 5.0 fail; it might be a good idea to add greenkeeper / travis so this can be caught early next time. Ran into this while quickly testing if I could pull in quick-format to improve perf. Thanks!

> [email protected] test /Users/yw/src/bole
> node test.js

TAP version 13
# test simple logging
ok 1 should be equal
# test multiple logs
ok 2 should be equal
# test multiple outputs
ok 3 should be equal
ok 4 should be equal
ok 5 should be equal
ok 6 should be equal
# test string formatting
ok 7 should be equal
ok 8 should be equal
ok 9 should be equal
ok 10 should be equal
ok 11 should be equal
ok 12 should be equal
ok 13 should be equal
# test error formatting
ok 14 should be equal
# test error formatting with message
ok 15 should be equal
# test request object
not ok 16 should be equal
  ---
    operator: equal
    expected:
      '{"time":"2016-03-21T03:06:34.xxxZ,"hostname":"Yoshuas-MacBook-Pro.local","pid":95098,"level":"info","name":"reqfmt","req":{"method":"GET","url":"/foo?bar=baz","headers":{"host":":58575","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":"RPORT"}}\n'
    actual:
      '{"time":"2016-03-21T03:06:34.xxxZ,"hostname":"Yoshuas-MacBook-Pro.local","pid":95098,"level":"info","name":"reqfmt","req":{"method":"GET","url":"/::/foo?bar=baz","headers":{"host":":58575","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":"RPORT"}}\n'
  ...
# test request object with message
not ok 17 should be equal
  ---
    operator: equal
    expected:
      '{"time":"2016-03-21T03:06:34.xxxZ,"hostname":"Yoshuas-MacBook-Pro.local","pid":95098,"level":"info","name":"reqfmt","message":"this is a message","req":{"method":"GET","url":"/foo?bar=baz","headers":{"host":":58577","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":"RPORT"}}\n'
    actual:
      '{"time":"2016-03-21T03:06:34.xxxZ,"hostname":"Yoshuas-MacBook-Pro.local","pid":95098,"level":"info","name":"reqfmt","message":"this is a message","req":{"method":"GET","url":"/::/foo?bar=baz","headers":{"host":":58577","connection":"close"},"remoteAddress":"127.0.0.1","remotePort":"RPORT"}}\n'
  ...
# test sub logger
ok 18 should be equal
# test object logging
ok 19 correct number of log entries
ok 20 correct log entry #0
ok 21 correct log entry #1
ok 22 correct log entry #2
ok 23 correct log entry #3

1..23
# tests 23
# pass  21
# fail  2

Raw object logging

Can you add a raw flag that whe enabled the output is not stringified?

I want to write a plugin for bole called bole-console that formats the console output with colors and currently I'm parsing the JSON object that you're stringifying.

This is how I'm using the plugin:

var bole = require('bole');
var boleConsole = require('bole-console')
bole.output([
  { level: 'info', stream: boleConsole({ ... }) }
]);

I basically need a raw flag:

bole.output([
  { level: 'info', raw: true, stream: boleConsole({ ... }) }
]);

Logging additional values with an error object

Hi! 👋

I'd like to log additional context when logging an error object so that I have more information about why the error occurred. I have something like the following:

var log = require('bole')('mymodule')
var query = 'select * from users'
executeQuery(query, function(err, results) {
  if (err) {
    // Want to log query that caused error
    err.query = query;
    log.error(err);
  }
})

In this example, I want the value of query to show up in my logs alongside the error object.

I don't currently see a way of doing this. Should it be possible?

custom errors handling

Great logger module, but I have some issues with custom errors logging.
Look at the code:

var bole = require('bole'),
        log = require('bole')('mymodule')

bole.output({
        level: 'debug',
        stream: process.stdout
});


log.error(new MyError());

var inherits = require('util').inherits;
function MyError(message) {
        Error.captureStackTrace(this, this.constructor);
        this.name = 'MyError';
        this.code = 'MYERRORCODE';
        this.message = message || 'my error';
}
inherits(MyError, Error);

and after launch I got this in stdout:

{"time":"2016-06-19T13:06:07.626Z","hostname":"flegdev","pid":21948,"level":"error","name":"mymodule","name":"MyError","code":"MYERRORCODE","message":"my error"}

err property is missing and name is overwritten with error name.

[email protected]
[email protected]

What's the right way to log nested objects to stdout?

I was trying to log some objects using
logger.debug("data is", dataObj);

However some objects are not getting logged properly, instead of expanded object I am seeing just "Object":
headers: {\n host: [ [Object] ],\n 'user-agent': [ [Object] ],\n accept: [ [Object] ]\n }

Here is my bole config:
bole.output({ level: process.env.LOG_LEVEL || 'debug', stream: process.stdout });

What is the right way to log nested objects in stdout. I don't want to log stringified objects.

perf improvements

There's a new kid on the block and things aren't looking too great for bole perf-wise.

benchBunyanObj*10000: 1252.539ms
benchWinstonObj*10000: 1729.837ms
benchBoleObj*10000: 1491.677ms
benchPinoObj*10000: 365.207ms

Perhaps it'd be good to find out where bole's pain points lie and see if we can speed things up a bit. pino uses the following packages that were built specifically for it:

• quick-format - fast util.format replacement
• fast-safe-stringify - fast and safe JSON.stringify implementation

ability to only have explicit levels logged

it would be nice to be able to specify explicit levels for logging. So instead of info getting that and the levels above it would be cool to allow for only info, warn, debug to be printed out.

produces invalid JSON

Logger will produce invalid JSON if the object includes keys with undefined value.

Code:

var bole = require('bole');
var log = bole('TEST');

bole.output({
  level: 'info',
  stream: process.stdout
});

log.info({ foo: undefined }, 'Test Message');

Errror (output line will include "foo":undefined)

$ node index.js | jq .
parse error: Invalid numeric literal at line 1, column 137