Skip to content

Commit

Permalink
Merge a4c92ab into 8077987
Browse files Browse the repository at this point in the history
  • Loading branch information
David Mark Clements committed Jul 14, 2018
2 parents 8077987 + a4c92ab commit 49e4acf
Show file tree
Hide file tree
Showing 17 changed files with 1,567 additions and 1,249 deletions.
435 changes: 49 additions & 386 deletions README.md

Large diffs are not rendered by default.

1,057 changes: 540 additions & 517 deletions docs/api.md

Large diffs are not rendered by default.

58 changes: 58 additions & 0 deletions docs/benchmarks.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,58 @@
# Benchmarks

`pino.info('hello world')`:

```
BASIC benchmark averages
Bunyan average: 549.042ms
Winston average: 467.873ms
Bole average: 201.529ms
Debug average: 253.724ms
LogLevel average: 282.653ms
Pino average: 188.956ms
PinoExtreme average: 108.809ms
```

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

```
OBJECT benchmark averages
BunyanObj average: 564.363ms
WinstonObj average: 464.824ms
BoleObj average: 230.220ms
LogLevelObject average: 474.857ms
PinoObj average: 201.442ms
PinoUnsafeObj average: 202.687ms
PinoExtremeObj average: 108.689ms
PinoUnsafeExtremeObj average: 106.718ms
```

`pino.info(aBigDeeplyNestedObject)`:

```
DEEPOBJECT benchmark averages
BunyanDeepObj average: 5293.279ms
WinstonDeepObj average: 9020.292ms
BoleDeepObj average: 9169.043ms
LogLevelDeepObj average: 15260.917ms
PinoDeepObj average: 8467.807ms
PinoUnsafeDeepObj average: 6159.227ms
PinoExtremeDeepObj average: 8354.557ms
PinoUnsafeExtremeDeepObj average: 6214.073ms
```

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

```
BunyanInterpolateExtra average: 778.408ms
WinstonInterpolateExtra average: 627.956ms
BoleInterpolateExtra average: 429.757ms
PinoInterpolateExtra average: 316.043ms
PinoUnsafeInterpolateExtra average: 316.809ms
PinoExtremeInterpolateExtra average: 218.468ms
PinoUnsafeExtremeInterpolateExtra average: 215.040ms
```

For a fair comparison, [LogLevel](http://npm.im/loglevel) was extended
to include a timestamp and [bole](http://npm.im/bole) had
`fastTime` mode switched on.
199 changes: 199 additions & 0 deletions docs/browser.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,199 @@
# Browser API

Pino is compatible with [`browserify`](http://npm.im/browserify) for browser side usage:

This can be useful with isomorphic/universal JavaScript code.

By default, in the browser,
`pino` uses corresponding [Log4j](https://en.wikipedia.org/wiki/Log4j) `console` methods (`console.error`, `console.warn`, `console.info`, `console.debug`, `console.trace`) and uses `console.error` for any `fatal` level logs.

## Options

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

### `asObject` (Boolean)

```js
const 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:

```js
pino.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.

```js
const 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`.


```js
const pino = require('pino')({
browser: {
write: {
info: function (o) {
//process info log object
},
error: 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,

```js
const pino = require('pino')({
browser: {
serialize: true
}
})
```

Or we can selectively enable them via an array:

```js
const pino = require('pino')({
serializers: {
custom: myCustomSerializer,
another: anotherSerializer
},
browser: {
serialize: ['custom']
}
})
// following will apply myCustomSerializer to the custom property,
// but will not apply anotherSerizlier to another key
pino.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:

```js
const pino = require('pino')({
serializers: {
custom: myCustomSerializer,
another: anotherSerializer
},
browser: {
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:

```js
{
ts = Number,
messages = Array,
bindings = Array,
level: { 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 hierarchy, with the lowest index
being the top of the hierarchy.

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:

```js
const pino = require('pino')({
browser: {
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
}
}
}
}
})
```
95 changes: 95 additions & 0 deletions docs/child-loggers.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,95 @@
# Child loggers

Let's assume we want to have `"module":"foo"` added to every log within a
module `foo.js`.

To accomplish this, simply use a child logger:

```js
'use strict'
// imports a pino logger instance of `require('pino')()`
const parentLogger = require('./lib/logger')
const log = parentLogger.child({module: 'foo'})

function doSomething () {
log.info('doSomething invoked')
}

module.exports = {
doSomething
}
```

## Cost of child logging

Child logger creation is fast:

```
benchBunyanCreation*10000: 564.514ms
benchBoleCreation*10000: 283.276ms
benchPinoCreation*10000: 258.745ms
benchPinoExtremeCreation*10000: 150.506ms
```

Logging through a child logger has little performance penalty:

```
benchBunyanChild*10000: 556.275ms
benchBoleChild*10000: 288.124ms
benchPinoChild*10000: 231.695ms
benchPinoExtremeChild*10000: 122.117ms
```

Logging via the child logger of a child logger also has negligible overhead:

```
benchBunyanChildChild*10000: 559.082ms
benchPinoChildChild*10000: 229.264ms
benchPinoExtremeChildChild*10000: 127.753ms
```

## Duplicate keys caveat

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 the same keys between
parent and child loggers are used, Pino resolves the conflict in the sanest way.

For example, consider the following:

```js
const pino = require('pino')
pino(pino.destination('./my-log'))
.child({a: 'property'})
.child({a: 'prop'})
.info('howdy')
```

```sh
$ cat my-log
{"pid":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.

At some point the logs will most likely be processed (for instance with a [transport](transports.md)),
and this generally involves parsing. `JSON.parse` will return an object where the conflicting
namespace holds the final value assigned to it:

```sh
$ cat my-log | node -e "process.stdin.once('data', (line) => console.log(JSON.stringify(JSON.parse(line))))"
{"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":"2016-04-01T18:08:34.473Z","a":"prop","v":1}
```

Ultimately the conflict is resolved by taking the last value, which aligns with Bunyans child logging
behavior.

There may be cases where this edge case becomes problematic if a JSON parser with alternative behavior
is used to process the logs. It's recommended to be conscious of namespace conflicts with child loggers,
in light of an expected log processing approach.

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.
7 changes: 3 additions & 4 deletions docs/ecosystem.md
Original file line number Diff line number Diff line change
@@ -1,14 +1,13 @@
# Pino Ecosystem

Are you looking for a transport to accomplish some sort of log processing?
Or maybe a transport to make logs easier to read? This list will help you
with that endeavor. If you cannot find what you are looking for here, write
it and submit a PR adding it to the list 😃.
This is a list of ecosystem modules that integrate with `pino`.

Modules listed under [Core](#core) are maintained by the Pino team. Modules
listed under [Community](#community) are maintained by independent community
members.

Please send a PR to add new modules!

<a id="core"></a>
## Core

Expand Down

0 comments on commit 49e4acf

Please sign in to comment.