pinojs/pino

Name: pino

Owner: pino

Description: ? super fast, all natural json logger ?

Created: 2016-02-16 14:14:29.0

Updated: 2018-01-19 23:31:17.0

Pushed: 2018-01-03 12:22:14.0

Homepage: http://getpino.io

Size: 1178

Language: JavaScript

GitHub Committers

UserMost Recent Commit# Commits

Other Committers

UserEmailMost Recent Commit# Commits

README

banner

pino  Build Status Coverage Status TypeScript definitions on DefinitelyTyped

Extremely fast node.js logger, inspired by Bunyan. It also includes a shell utility to pretty-print its log files.

cli

Install
install pino --save

If you need support for Node.js v0.12 or v0.10, please install the latest 2.x release using the legacy tag:

install pino@legacy --save

Documentation for the legacy version 2.x is available on the v2.x.x branch.

Usage
 strict'

pino = require('pino')()

.info('hello world')
.error('this is at error level')
.info('the answer is %d', 42)
.info({ obj: 42 }, 'hello world')
.info({ obj: 42, b: 2 }, 'hello world')
.info({ obj: { aa: 'bbb' } }, 'another')
mmediate(function () {
no.info('after setImmediate')

.error(new Error('an error'))

child = pino.child({ a: 'property' })
d.info('hello child!')

childsChild = child.child({ another: 'property' })
dsChild.info('hello baby..')

This produces:

d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1459529098958,"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":50,"msg":"this is at error level","time":1459529098959,"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"the answer is 42","time":1459529098960,"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1459529098960,"obj":42,"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1459529098960,"obj":42,"b":2,"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"another","time":1459529098960,"obj":{"aa":"bbb"},"v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":50,"msg":"an error","time":1459529098961,"type":"Error","stack":"Error: an error\n    at Object.<anonymous> (/Users/davidclements/z/nearForm/pino/example.js:14:12)\n    at Module._compile (module.js:435:26)\n    at Object.Module._extensions..js (module.js:442:10)\n    at Module.load (module.js:356:32)\n    at Function.Module._load (module.js:311:12)\n    at Function.Module.runMain (module.js:467:10)\n    at startup (node.js:136:18)\n    at node.js:963:3","v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello child!","time":1459529098962,"a":"property","v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello baby..","time":1459529098962,"another":"property","a":"property","v":1}
d":94473,"hostname":"MacBook-Pro-3.home","level":30,"msg":"after setImmediate","time":1459529098963,"v":1}

Benchmarks

As far as we know, it is one of the fastest loggers in town:

pino.info('hello world'):

hBunyan*10000: 1355.229ms
hWinston*10000: 2226.117ms
hBole*10000: 291.727ms
hDebug*10000: 445.291ms
hLogLevel*10000: 322.181ms
hPino*10000: 269.109ms
hPinoExtreme*10000: 102.239ms

pino.info({'hello': 'world'}):

hBunyanObj*10000: 1464.568ms
hWinstonObj*10000: 2177.602ms
hBoleObj*10000: 322.105ms
hLogLevelObject*10000: 1443.148ms
hPinoObj*10000: 309.564ms
hPinoUnsafeObj*10000: 301.308ms
hPinoExtremeObj*10000: 130.343ms
hPinoUnsafeExtremeObj*10000: 131.322ms

pino.info(aBigDeeplyNestedObject):

hBunyanDeepObj*10000: 8749.174ms
hWinstonDeepObj*10000: 17761.409ms
hBoleDeepObj*10000: 5252.563ms
hLogLevelDeepObj*10000: 43518.525ms
hPinoDeepObj*10000: 5124.361ms
hPinoUnsafeDeepObj*10000: 3539.253ms
hPinoExtremeDeepObj*10000: 5138.457ms
hPinoUnsafeExtremeDeepObj*10000: 3480.270ms

pino.info('hello %s %j %d', 'world', {obj: true}, 4, {another: 'obj'}):

hDebugInterpolateExtra*10000: 640.001ms
hBunyanInterpolateExtra*10000: 2888.825ms
hWinstonInterpolateExtra*10000: 2616.285ms
hBoleInterpolateExtra*10000: 1313.470ms
hLogLevelInterpolateExtra*10000: 1487.610ms
hPinoInterpolateExtra*10000: 486.367ms
hPinoUnsafeInterpolateExtra*10000: 457.778ms
hPinoExtremeInterpolateExtra*10000: 314.635ms
hPinoUnsafeExtremeInterpolateExtra*10000: 294.915ms

In many cases, pino is over 6x faster than alternatives.

For a fair comparison, LogLevel was extended to include a timestamp and bole had fastTime mode switched on.

Transports

A transport in most logging libraries is something that runs in-process to perform some operation with the finalized log line. For example, a transport might send the log line to a standard syslog server after processing the log line and reformatting it. For details on implementing, and some already written, transports, see our Transports? document.

Pino does not natively support in-process transports.

Pino does not support in-process transports because Node processes are single threaded processes (ignoring some technical details). Given this restriction, one of the methods Pino employs to achieve its speed is to purposefully offload the handling of logs, and their ultimate destination, to external processes so that the threading capabilities of the OS can be used (or other CPUs).

One consequence of this methodology is that “error” logs do not get written to stderr. However, since Pino logs are in a parseable format, it is possible to use tools like pino-tee or jq to work with the logs. For example, to view only logs marked as “error” logs:

de an-app.js | jq 'select(.level == 50)'

In short, the way Pino generates logs:

  1. Reduces the impact of logging on your application to an extremely minimal amount.
  2. Gives greater flexibility in how logs are processed and stored.

Given all of the above, Pino clearly promotes out-of-process log processing. However, it is possible to wrap Pino and perform processing in-process. For an example of this, see pino-multi-stream.

Pino in the browser

Pino is compatible with browserify for browser side usage:

This can be useful with isomorphic/universal JavaScript code.

By default, in the browser, pino uses corresponding Log4j console methods (console.error, console.warn, console.info, console.debug, console.trace) and uses console.error for any fatal level logs.

Browser Options

Pino can be passed a browser object in the options object, which can have the following properties:

asObject (Boolean)
pino = require('pino')({browser: {asObject: true}})

The asObject option will create a pino-like log object instead of passing all arguments to a console method, for instance:

.info('hi') // creates and logs {msg: 'hi', level: 30, time: <ts>}

When write is set, asObject will always be true.

write (Function | Object)

Instead of passing log messages to console.log they can be passed to a supplied function.

If write is set to a single function, all logging objects are passed to this function.

pino = require('pino')({browser: {write: (o) => {
 do something with o

If write is an object, it can have methods that correspond to the levels. When a message is logged at a given level, the corresponding method is called. If a method isn't present, the logging falls back to using the console.

pino = require('pino')({browser: {write: {
fo: function (o) {
//process info log object

ror: function (o) {
//process error log object


serialize: (Boolean | Array)

The serializers provided to pino are ignored by default in the browser, including the standard serializers provided with Pino. Since the default destination for log messages is the console, values such as Error objects are enhanced for inspection, which they otherwise wouldn't be if the Error serializer was enabled.

We can turn all serializers on,

pino = require('pino')({
owser: {
serialize: true


Or we can selectively enable them via an array:

pino = require('pino')({
rializers: {
custom: myCustomSerializer,
another: anotherSerializer

owser: {
serialize: ['custom']


ollowing will apply myCustomSerializer to the custom property,
ut will not apply anotherSerizlier to another key
.info({custom: 'a', another: 'b'})  

When serialize is true the standard error serializer is also enabled (see https://github.com/pinojs/pino/blob/master/docs/API.md#stdSerializers). This is a global serializer which will apply to any Error objects passed to the logger methods.

If serialize is an array the standard error serializer is also automatically enabled, it can be explicitly disabled by including a string in the serialize array: !stdSerializers.err, like so:

pino = require('pino')({
rializers: {
custom: myCustomSerializer,
another: anotherSerializer

owser: {
serialize: ['!stdSerializers.err', 'custom'] //will not serialize Errors, will serialize `custom` keys


The serialize array also applies to any child logger serializers (see https://github.com/pinojs/pino/blob/master/docs/API.md#discussion-2 for how to set child-bound serializers).

Unlike server pino the serializers apply to every object passed to the logger method, if the asObject option is true, this results in the serializers applying to the first object (as in server pino).

For more info on serializers see https://github.com/pinojs/pino/blob/master/docs/API.md#parameters.

transmit (Object)

An object with send and level properties.

The transmit.level property specifies the minimum level (inclusive) of when the send function should be called, if not supplied the send function be called based on the main logging level (set via options.level, defaulting to info).

The transmit object must have a send function which will be called after writing the log message. The send function is passed the level of the log message and a logEvent object.

The logEvent object is a data structure representing a log message, it represents the arguments passed to a logger statement, the level at which they were logged and the heirarchy of child bindings.

The logEvent format is structured like so:


 = Number,
ssages = Array, 
ndings = Array, 
vel: { label = String, value = Number}

The ts property is a unix epoch timestamp in milliseconds, the time is taken from the moment the logger method is called.

The messages array is all arguments passed to logger method, (for instance logger.info('a', 'b', 'c') would result in messages array ['a', 'b', 'c']).

The bindings array represents each child logger (if any), and the relevant bindings. For instance given logger.child({a: 1}).child({b: 2}).info({c: 3}), the bindings array would hold [{a: 1}, {b: 2}] and the messages array would be [{c: 3}]. The bindings are ordered according to their position in the child logger heirarchy, with the lowest index being the top of the heirarchy.

By default serializers are not applied to log output in the browser, but they will always be applied to messages and bindings in the logEvent object. This allows us to ensure a consistent format for all values between server and client.

The level holds the label (for instance info), and the corresponding numerical value (for instance 30). This could be important in cases where client side level values and labels differ from server side.

The point of the send function is to remotely record log messages:

pino = require('pino')({
owser: {
transmit: {
  level: 'warn',
  send: function (level, logEvent) {
    if (level === 'warn') {
      // maybe send the logEvent to a separate endpoint
      // or maybe analyse the messages further before sending
    }
    // we could also use the `logEvent.level.value` property to determine
    // numerical value
    if (logEvent.level.value >= 50) { // covers error and fatal

      // send the logEvent somewhere 
    }
  }
}


Caveats

There's some fine points to be aware of, which are a result of worthwhile trade-offs:

11 Arguments

The logger functions (e.g. pino.info) can take a maximum of 11 arguments.

If you need more than that to write a log entry, you're probably doing it wrong.

Duplicate Keys

It's possible for naming conflicts to arise between child loggers and children of child loggers.

This isn't as bad as it sounds, even if you do use the same keys between parent and child loggers Pino resolves the conflict in the sanest way.

For example, consider the following:

pino = require('pino')
fs = require('fs')
(fs.createWriteStream('./my-log'))
hild({a: 'property'})
hild({a: 'prop'})
nfo('howdy')
h
t my-log
d":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459534114473,"a":"property","a":"prop","v":1}

Notice how there's two key's named a in the JSON output. The sub-childs properties appear after the parent child properties. This means if we run our logs through pino -t (or convert them to objects in any other way) we'll end up with one a property whose value corresponds to the lowest child in the hierarchy:

t my-log | pino -t
d":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":"2016-04-01T18:08:34.473Z","a":"prop","v":1}

This equates to the same log output that Bunyan supplies.

One of Pino's performance tricks is to avoid building objects and stringifying them, so we're building strings instead. This is why duplicate keys between parents and children will end up in log output.

The Team
Matteo Collina

https://github.com/pinojs

https://www.npmjs.com/~matteo.collina

https://twitter.com/matteocollina

David Mark Clements

https://github.com/davidmarkclements

https://www.npmjs.com/~davidmarkclements

https://twitter.com/davidmarkclem

James Sumners

https://github.com/jsumners

https://www.npmjs.com/~jsumners

https://twitter.com/jsumners79

Thomas Watson Steen

https://github.com/watson

https://www.npmjs.com/~watson

https://twitter.com/wa7son

Chat on Gitter

https://gitter.im/pinojs/pino

Chat on IRC

You'll find an active group of Pino users in the #pinojs channel on Freenode, including some of the contributors to this project.

Contributing

Pino is an OPEN Open Source Project. This means that:

Individuals making significant and valuable contributions are given commit-access to the project to contribute as they see fit. This project is more like an open wiki than a standard guarded open source project.

See the CONTRIBUTING.md file for more details.

Acknowledgements

This project was kindly sponsored by nearForm.

Logo and identity designed by Cosmic Fox Design: https://www.behance.net/cosmicfox.

License

Licensed under MIT.


This work is supported by the National Institutes of Health's National Center for Advancing Translational Sciences, Grant Number U24TR002306. This work is solely the responsibility of the creators and does not necessarily represent the official views of the National Institutes of Health.