Repository: pinojs/pino (js)

Issue:
addLevel is not working
__pino 3.1.1__

This fails with: _TypeError: log.foo is not a function_

``` js
const pino = require('pino')
const log = pino()
log.addLevel('foo', 35)
log.foo('bar')
```


The tests does not show this because:
1. Levels added to one instance via the constructor will be added to new instances
2. Adding a level on the constructor works and there exists a test that verifies this. The test creates a new level with the options: `{level:'foo', levelVal: 35}`
3. The test that verifies `addLevel('foo', 35)` is working because it's executed __after__ the test in _(2)_, and because of _(1)_ it uses that function.

If the test in _(3)_ is modified to `addLevel('foo2', 35)`,  the test fails.

Here is some code to show the problem:

``` js
const log = pino({level:'foo', levelVal:35})
const log2 = pino()
log2.foo('should fail, but will work')
```


Three problems exists in the current solution
- `levels` object is shared
- `lscache` object is shared
- `addLevel` does not add a new property

I have a fix for this, which copies `levels` and `lscache` to the instances when new custom levels are added to them. If no custom levels are added the standard values on `Pino.prototype` is used.

Let me know if you want me to submit a PR.

Pull request description:
addLevel bugfixes
This PR fixes #167

I've split it into three commits.

- a18f09244a28af865bdda1c96f501812b5504f3e Modifies the existing test to show that the current code fails
- dbdd81956087a54a2efbc3f203f16ea7bff1ea10 Adds a new test, that fails, to show that levels created via the constructor exists on other instances as well
- 886be9cce333ec8f230673bc456317cac379d05b Fixes the problems by not sharing levels and lscache between instances.


## Solution
Default `levels` and `_lscache` properties have been added to `Pino.prototype`. These are used when no custom levels have been added. 

##### addLevel()
The first time `addLevel()` is called on a `Pino` instance, new copies of `levels` and `_lscache` are created on the instance and these are then modified to include the new level.


##### Children of parents with custom levels
If a logger instance has custom levels, these are copied over to children as well, when `child()` is called. 

#### NOTE: Parent and children share `levels` and `_lscache`
The objects in `levels` and `_lscache` are shared between the parent and children. This means that if `addLevel` is called on one instance, all others `levels` and `_lscache` properties will contain the new level as well.

I choose to do it like this, in order to not make copies for every child. I think this is a fair tradeoff. 
Custom levels should be added to the first logger instance, before any child logs have been created, and no new levels should be added after that. `API.md` should probably include a comment about this.

Patch:
diff --git a/pino.js b/pino.js
index 2b8482f..69e446b 100644
--- a/pino.js
+++ b/pino.js
@@ -34,24 +34,40 @@ var levels = {
   debug: 20,
   trace: 10
 }
+Object.freeze(levels)
 
 var nums = Object.keys(levels).reduce(function (o, k) {
   o[levels[k]] = k
   return o
 }, {})
+Object.freeze(nums)
 
-function defineLevelsProperty (onObject) {
+var defaultLevelsValues = {
+  values: levels,
+  labels: nums
+}
+Object.freeze(defaultLevelsValues)
+
+function defineLevelsProperty (onObject, existing, noCopy) {
+  var value = noCopy ? existing : {
+    values: copy({}, existing.values),
+    labels: copy({}, existing.labels)
+  }
   Object.defineProperty(onObject, 'levels', {
-    value: {
-      values: copy({}, levels),
-      labels: copy({}, nums)
-    },
+    value: value,
     enumerable: true
   })
   Object.defineProperty(onObject.levels.values, 'silent', {value: 100})
   Object.defineProperty(onObject.levels.labels, '100', {value: 'silent'})
 }
 
+function defineLsCacheProperty (onObject, value, noCopy) {
+  Object.defineProperty(onObject, '_lscache', {
+    value: noCopy ? value : Object.assign({}, value),
+    enumerable: false
+  })
+}
+
 // IIFE so the keys are cached at module load
 var isStandardLevel = (function () {
   var keys = Object.keys(levels)
@@ -67,12 +83,6 @@ var isStandardLevelVal = (function () {
   }
 }())
 
-// level string catch
-var lscache = Object.keys(nums).reduce(function (o, k) {
-  o[k] = flatstr('"level":' + Number(k))
-  return o
-}, {})
-
 function streamIsBlockable (s) {
   if (s.hasOwnProperty('_handle') && s._handle.hasOwnProperty('fd') && s._handle.fd) return true
   if (s.hasOwnProperty('fd') && s.fd) return true
@@ -136,7 +146,7 @@ function pino (opts, stream) {
   return logger
 }
 
-defineLevelsProperty(pino)
+defineLevelsProperty(pino, defaultLevelsValues)
 
 function Pino (opts, stream) {
   this.stream = stream
@@ -149,6 +159,10 @@ function Pino (opts, stream) {
   this.chindings = opts.chindings
   this.cache = opts.cache
   this.formatOpts = opts.formatOpts
+  if (opts.customizedLevels) {
+    defineLsCacheProperty(this, opts.customizedLevels._lscache, true)
+    defineLevelsProperty(this, opts.customizedLevels.levels, true)
+  }
 
   if (opts.level && opts.levelVal) {
     var levelIsStandard = isStandardLevel(opts.level)
@@ -170,7 +184,7 @@ function Pino (opts, stream) {
 }
 
 Pino.prototype = new EventEmitter()
-defineLevelsProperty(Pino.prototype)
+defineLevelsProperty(Pino.prototype, defaultLevelsValues)
 
 Pino.prototype.fatal = genLog(levels.fatal)
 Pino.prototype.error = genLog(levels.error)
@@ -179,6 +193,13 @@ Pino.prototype.info = genLog(levels.info)
 Pino.prototype.debug = genLog(levels.debug)
 Pino.prototype.trace = genLog(levels.trace)
 
+var defaultLsCache = Object.keys(nums).reduce(function (o, k) { // level string cache
+  o[k] = flatstr('"level":' + Number(k))
+  return o
+}, {})
+Object.freeze(defaultLsCache)
+defineLsCacheProperty(Pino.prototype, defaultLsCache)
+
 Object.defineProperty(Pino.prototype, 'levelVal', {
   get: function getLevelVal () {
     return this._levelVal
@@ -230,7 +251,7 @@ Pino.prototype.asJson = function asJson (obj, msg, num) {
   if (!msg && obj instanceof Error) {
     msg = obj.message
   }
-  var data = this._baseLog + lscache[num] + this.time()
+  var data = this._baseLog + this._lscache[num] + this.time()
   // to catch both null and undefined
   /* eslint-disable eqeqeq */
   if (msg != undefined) {
@@ -296,7 +317,12 @@ Pino.prototype.child = function child (bindings) {
     cache: this.cache,
     formatOpts: this.formatOpts
   }
-
+  if (this.hasOwnProperty('levels')) {
+    opts.customizedLevels = {
+      levels: this.levels,
+      _lscache: this._lscache
+    }
+  }
   return new Pino(opts, this.stream)
 }
 
@@ -326,9 +352,16 @@ Pino.prototype.flush = function () {
 Pino.prototype.addLevel = function addLevel (name, lvl) {
   if (this.levels.values.hasOwnProperty(name)) return false
   if (this.levels.labels.hasOwnProperty(lvl)) return false
+  if (!this.hasOwnProperty('levels')) {
+    // define new properties on this instance by copying prototygpe values
+    defineLevelsProperty(this, this.levels)
+    defineLsCacheProperty(this, this._lscache)
+  }
+
   this.levels.values[name] = lvl
   this.levels.labels[lvl] = name
-  lscache[lvl] = flatstr('"level":' + Number(lvl))
+  this._lscache[lvl] = flatstr('"level":' + Number(lvl))
+  this[name] = genLog(lvl)
   return true
 }
 


Test patch:
diff --git a/test/addlevel.test.js b/test/addlevel.test.js
index 85f93f6..27d6925 100644
--- a/test/addlevel.test.js
+++ b/test/addlevel.test.js
@@ -23,9 +23,29 @@ test('can add a custom level to a prior instance', function (t) {
     t.is(chunk.msg, 'bar')
   }))
 
-  log.addLevel('foo', 35)
-  t.is(typeof log.foo, 'function')
-  log.foo('bar')
+  log.addLevel('foo2', 35)
+  t.is(typeof log.foo2, 'function')
+  log.foo2('bar')
+})
+
+test('custom level via constructor does not affect other instances', function (t) {
+  t.plan(2)
+
+  var log = pino({level: 'foo3', levelVal: 36})
+  var other = pino()
+  t.is(typeof log.foo3, 'function')
+  t.is(typeof other.foo3, 'undefined')
+})
+
+test('custom level on one instance does not affect other instances', function (t) {
+  t.plan(2)
+
+  var log = pino()
+  log.addLevel('foo4', 37)
+  var other = pino()
+  log.addLevel('foo5', 38)
+  t.is(typeof other.foo4, 'undefined')
+  t.is(typeof other.foo5, 'undefined')
 })
 
 test('custom levels encompass higher levels', function (t) {
@@ -65,6 +85,19 @@ test('children can be set to custom level', function (t) {
   child.foo('bar')
 })
 
+test('custom levels exists on children', function (t) {
+  t.plan(2)
+
+  var parent = pino({}, sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+    t.is(chunk.child, 'yes')
+    cb()
+  }))
+  parent.addLevel('foo', 35)
+  var child = parent.child({child: 'yes'})
+  child.foo('bar')
+})
+
 test('rejects already known labels', function (t) {
   t.plan(1)
   var log = pino({level: 'info', levelVal: 900})