1 | # Child loggers
|
2 |
|
3 | Let's assume we want to have `"module":"foo"` added to every log within a
|
4 | module `foo.js`.
|
5 |
|
6 | To accomplish this, simply use a child logger:
|
7 |
|
8 | ```js
|
9 | 'use strict'
|
10 | // imports a pino logger instance of `require('pino')()`
|
11 | const parentLogger = require('./lib/logger')
|
12 | const log = parentLogger.child({module: 'foo'})
|
13 |
|
14 | function doSomething () {
|
15 | log.info('doSomething invoked')
|
16 | }
|
17 |
|
18 | module.exports = {
|
19 | doSomething
|
20 | }
|
21 | ```
|
22 |
|
23 | ## Cost of child logging
|
24 |
|
25 | Child logger creation is fast:
|
26 |
|
27 | ```
|
28 | benchBunyanCreation*10000: 564.514ms
|
29 | benchBoleCreation*10000: 283.276ms
|
30 | benchPinoCreation*10000: 258.745ms
|
31 | benchPinoExtremeCreation*10000: 150.506ms
|
32 | ```
|
33 |
|
34 | Logging through a child logger has little performance penalty:
|
35 |
|
36 | ```
|
37 | benchBunyanChild*10000: 556.275ms
|
38 | benchBoleChild*10000: 288.124ms
|
39 | benchPinoChild*10000: 231.695ms
|
40 | benchPinoExtremeChild*10000: 122.117ms
|
41 | ```
|
42 |
|
43 | Logging via the child logger of a child logger also has negligible overhead:
|
44 |
|
45 | ```
|
46 | benchBunyanChildChild*10000: 559.082ms
|
47 | benchPinoChildChild*10000: 229.264ms
|
48 | benchPinoExtremeChildChild*10000: 127.753ms
|
49 | ```
|
50 |
|
51 | ## Duplicate keys caveat
|
52 |
|
53 | It's possible for naming conflicts to arise between child loggers and
|
54 | children of child loggers.
|
55 |
|
56 | This isn't as bad as it sounds, even if the same keys between
|
57 | parent and child loggers are used, Pino resolves the conflict in the sanest way.
|
58 |
|
59 | For example, consider the following:
|
60 |
|
61 | ```js
|
62 | const pino = require('pino')
|
63 | pino(pino.destination('./my-log'))
|
64 | .child({a: 'property'})
|
65 | .child({a: 'prop'})
|
66 | .info('howdy')
|
67 | ```
|
68 |
|
69 | ```sh
|
70 | $ cat my-log
|
71 | {"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":1459534114473,"a":"property","a":"prop"}
|
72 | ```
|
73 |
|
74 | Notice how there's two key's named `a` in the JSON output. The sub-childs properties
|
75 | appear after the parent child properties.
|
76 |
|
77 | At some point the logs will most likely be processed (for instance with a [transport](transports.md)),
|
78 | and this generally involves parsing. `JSON.parse` will return an object where the conflicting
|
79 | namespace holds the final value assigned to it:
|
80 |
|
81 | ```sh
|
82 | $ cat my-log | node -e "process.stdin.once('data', (line) => console.log(JSON.stringify(JSON.parse(line))))"
|
83 | {"pid":95469,"hostname":"MacBook-Pro-3.home","level":30,"msg":"howdy","time":"2016-04-01T18:08:34.473Z","a":"prop"}
|
84 | ```
|
85 |
|
86 | Ultimately the conflict is resolved by taking the last value, which aligns with Bunyans child logging
|
87 | behavior.
|
88 |
|
89 | There may be cases where this edge case becomes problematic if a JSON parser with alternative behavior
|
90 | is used to process the logs. It's recommended to be conscious of namespace conflicts with child loggers,
|
91 | in light of an expected log processing approach.
|
92 |
|
93 | One of Pino's performance tricks is to avoid building objects and stringifying
|
94 | them, so we're building strings instead. This is why duplicate keys between
|
95 | parents and children will end up in log output.
|