Repository: pinojs/pino
Pull request #124 (2016-11-08 23:25:33)

Add support for custom log levels
This PR defines a new static method that allows a user to create their own log level. Example:

```js
var pino = require('pino')
pino.addLevel('myLevel', 35)
var log = pino({level: 'myLevel'})
log.myLevel('a message')
log.warn('another message') // gets logged as well
```

This PR also ties level changes to the `pino.levels` property. Otherwise, adding a new level would result in pino instances not knowing about the new level.

## Benchmarks

**addlevel**
```
benchPino*10000: 231.730ms
benchPinoExreme*10000: 105.404ms
benchPino*10000: 225.207ms
benchPinoExreme*10000: 99.640ms
```

**master**
```
benchPino*10000: 231.722ms
benchPinoExreme*10000: 108.249ms
benchPino*10000: 221.465ms
benchPinoExreme*10000: 103.063ms
```


Patch:
diff --git a/README.md b/README.md
index 9ee3932..8d5dc77 100644
--- a/README.md
+++ b/README.md
@@ -202,6 +202,7 @@ INFO [2016-03-09T15:27:09.339Z] (14139 on MacBook-Pro-3.home): hello world
   * <a href="#debug"><code>logger.<b>debug()</b></code></a>
   * <a href="#trace"><code>logger.<b>trace()</b></code></a>
   * <a href="#flush"><code>logger.<b>flush()</b></code></a>
+  * <a href="#addLevel"><code>logger.<b>addLevel(name, lvl)</b></code></a>
   * <a href="#levelVal"><code>logger.<b>levelVal</b></code></a>
   * <a href="#level-change"><code>logger.on(<b>'level-change'</b>, fn)</code></a>
   * <a href="#levelValues"><code>logger.levels.<b>values</b></code> & <code>pino.levels.<b>values</b></code></a>
@@ -225,7 +226,8 @@ Returns a new logger. Allowed options are:
 * `timestamp`: Enables or disables the inclusion of a timestamp in the log message. `slowtime` has no effect if this option is set to `false`. Defaults to `true`.
 * `slowtime`: Outputs ISO time stamps (`'2016-03-09T15:18:53.889Z'`) instead of Epoch time stamps (`1457536759176`). **WARNING**: This option carries a 25% performance drop, we recommend using default Epoch timestamps and transforming logs after if required. The `pino -t` command will do this for you (see [CLI](#cli)). default `false`.
 * `extreme`: Enables extreme mode, yields an additional 60% performance (from 250ms down to 100ms per 10000 ops). There are trade-off's should be understood before usage. See [Extreme mode explained](#extreme). default `false`
-* `level`: one of `'fatal'`, `'error'`, `'warn'`, `'info`', `'debug'`, `'trace'`; also `'silent'` is supported to disable logging.
+* `level`: one of `'fatal'`, `'error'`, `'warn'`, `'info`', `'debug'`, `'trace'`; also `'silent'` is supported to disable logging. Any other value defines a custom level and requires supplying a level value via `levelVal`.
+* `levelVal`: when defining a custom log level via `level`, set to an integer value to define the new level. Defaults to `undefined`.
 * `enabled`: enables logging, defaults to `true`.
 
 `stream` is a Writable stream, defaults to `process.stdout`.
@@ -415,6 +417,34 @@ If more args follows `msg`, these will be used to format `msg` using
 Flushes the content of the buffer in [extreme mode](#extreme). It has no effect if
 extreme mode is not enabled.
 
+<a name="addLevel"></a>
+### logger.addLevel(name, lvl)
+
+Defines a new level on the logger instance.
+Returns `true` on success and `false` if there was a conflict (level name or number already exists).
+
+Example:
+
+```js
+var pino = require('pino')
+var log = pino()
+log.addLevel('myLevel', 35)
+log.level = 'myLevel'
+log.myLevel('a message')
+```
+
+Notice that `addLevel` does *not* change the current level of the logger.
+
+If you need a custom level at construction, you can supply the `level` and `levelVal` options:
+
+```js
+var pino = require('pino')
+var log = pino({level: 'myLevel', levelVal: 35})
+log.myLevel('a message')
+```
+
+Notice that the level is set to the custom level on construction, i.e. `log.level` does not need to be set.
+
 <a name="levelVal"></a>
 ### logger.levelVal
 
diff --git a/pino.js b/pino.js
index 221d4e4..cb85255 100644
--- a/pino.js
+++ b/pino.js
@@ -22,6 +22,7 @@ var defaultOptions = {
   slowtime: false,
   extreme: false,
   level: 'info',
+  levelVal: undefined,
   enabled: true
 }
 
@@ -34,29 +35,44 @@ var levels = {
   trace: 10
 }
 
-// private property
-Object.defineProperty(levels, 'silent', {
-  value: 100,
-  enumerable: false
-})
-
 var nums = Object.keys(levels).reduce(function (o, k) {
   o[levels[k]] = k
   return o
 }, {})
 
+function defineLevelsProperty (onObject) {
+  Object.defineProperty(onObject, 'levels', {
+    value: {
+      values: copy({}, levels),
+      labels: copy({}, nums)
+    },
+    enumerable: true
+  })
+  Object.defineProperty(onObject.levels.values, 'silent', {value: 100})
+  Object.defineProperty(onObject.levels.labels, '100', {value: 'silent'})
+}
+
+// IIFE so the keys are cached at module load
+var isStandardLevel = (function () {
+  var keys = Object.keys(levels)
+  return function (level) {
+    return keys.indexOf(level) > -1
+  }
+}())
+
+var isStandardLevelVal = (function () {
+  var keys = Object.keys(nums)
+  return function (val) {
+    return keys.indexOf(val + '') > -1
+  }
+}())
+
 // level string catch
 var lscache = Object.keys(nums).reduce(function (o, k) {
   o[k] = flatstr('"level":' + Number(k))
   return o
 }, {})
 
-// private property
-Object.defineProperty(nums, '100', {
-  value: 'silent',
-  enumerable: false
-})
-
 function streamIsBlockable (s) {
   if (s.hasOwnProperty('_handle') && s._handle.hasOwnProperty('fd') && s._handle.fd) return true
   if (s.hasOwnProperty('fd') && s.fd) return true
@@ -120,13 +136,7 @@ function pino (opts, stream) {
   return logger
 }
 
-Object.defineProperty(pino, 'levels', {
-  value: {
-    values: copy({}, levels),
-    labels: copy({}, nums)
-  },
-  enumerable: true
-})
+defineLevelsProperty(pino)
 
 function Pino (opts, stream) {
   this.stream = stream
@@ -139,6 +149,13 @@ function Pino (opts, stream) {
   this.chindings = opts.chindings
   this.cache = opts.cache
   this.formatOpts = opts.formatOpts
+
+  if (opts.level && opts.levelVal) {
+    var levelIsStandard = isStandardLevel(opts.level)
+    var valIsStandard = isStandardLevelVal(opts.levelVal)
+    if (valIsStandard) throw new Error('level value is already used: ' + opts.levelVal)
+    if (levelIsStandard === false && valIsStandard === false) this.addLevel(opts.level, opts.levelVal)
+  }
   this._setLevel(opts.level)
 
   this._baseLog = flatstr(baseLog +
@@ -154,6 +171,7 @@ function Pino (opts, stream) {
 }
 
 Pino.prototype = new EventEmitter()
+defineLevelsProperty(Pino.prototype)
 
 Pino.prototype.fatal = genLog(levels.fatal)
 Pino.prototype.error = genLog(levels.error)
@@ -162,8 +180,6 @@ Pino.prototype.info = genLog(levels.info)
 Pino.prototype.debug = genLog(levels.debug)
 Pino.prototype.trace = genLog(levels.trace)
 
-Object.defineProperty(Pino.prototype, 'levels', {value: pino.levels})
-
 Object.defineProperty(Pino.prototype, 'levelVal', {
   get: function getLevelVal () {
     return this._levelVal
@@ -172,32 +188,32 @@ Object.defineProperty(Pino.prototype, 'levelVal', {
     if (typeof num === 'string') { return this._setLevel(num) }
 
     if (this.emit) {
-      this.emit('level-change', nums[num], num, nums[this._levelVal], this._levelVal)
+      this.emit('level-change', this.levels.labels[num], num, this.levels.labels[this._levelVal], this._levelVal)
     }
 
     this._levelVal = num
 
-    for (var key in levels) {
-      if (num > levels[key]) {
+    for (var key in this.levels.values) {
+      if (num > this.levels.values[key]) {
         this[key] = noop
         continue
       }
-      this[key] = Pino.prototype[key]
+      this[key] = isStandardLevel(key) ? Pino.prototype[key] : genLog(num)
     }
   }
 })
 
 Pino.prototype._setLevel = function _setLevel (level) {
-  if (typeof level === 'number') { level = nums[level] }
+  if (typeof level === 'number') { level = this.levels.labels[level] }
 
-  if (!levels[level]) {
+  if (!this.levels.values[level]) {
     throw new Error('unknown level ' + level)
   }
-  this.levelVal = levels[level]
+  this.levelVal = this.levels.values[level]
 }
 
 Pino.prototype._getLevel = function _getLevel (level) {
-  return nums[this.levelVal]
+  return this.levels.labels[this.levelVal]
 }
 
 Object.defineProperty(Pino.prototype, 'level', {
@@ -297,6 +313,7 @@ Pino.prototype.child = function child (bindings) {
 
   var opts = {
     level: bindings.level || this.level,
+    levelVal: isStandardLevelVal(this.levelVal) ? undefined : this.levelVal,
     serializers: bindings.hasOwnProperty('serializers') ? extend(this.serializers, bindings.serializers) : this.serializers,
     stringify: this.stringify,
     end: this.end,
@@ -334,6 +351,15 @@ Pino.prototype.flush = function () {
   this.cache.buf = ''
 }
 
+Pino.prototype.addLevel = function addLevel (name, lvl) {
+  if (this.levels.values.hasOwnProperty(name)) return false
+  if (this.levels.labels.hasOwnProperty(lvl)) return false
+  this.levels.values[name] = lvl
+  this.levels.labels[lvl] = name
+  lscache[lvl] = flatstr('"level":' + Number(lvl))
+  return true
+}
+
 function mapHttpRequest (req) {
   return {
     req: asReqValue(req)


Test patch:
diff --git a/test/addlevel.test.js b/test/addlevel.test.js
new file mode 100644
index 0000000..85f93f6
--- /dev/null
+++ b/test/addlevel.test.js
@@ -0,0 +1,81 @@
+'use strict'
+
+var test = require('tap').test
+var pino = require('../')
+var sink = require('./helper').sink
+
+test('can add a custom level via constructor', function (t) {
+  t.plan(2)
+
+  var log = pino({level: 'foo', levelVal: 35}, sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+    cb()
+  }))
+
+  t.is(typeof log.foo, 'function')
+  log.foo('bar')
+})
+
+test('can add a custom level to a prior instance', function (t) {
+  t.plan(2)
+
+  var log = pino(sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+  }))
+
+  log.addLevel('foo', 35)
+  t.is(typeof log.foo, 'function')
+  log.foo('bar')
+})
+
+test('custom levels encompass higher levels', function (t) {
+  t.plan(1)
+
+  var log = pino({level: 'foo', levelVal: 35}, sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+    cb()
+  }))
+
+  log.warn('bar')
+})
+
+test('after the fact add level does not include lower levels', function (t) {
+  t.plan(1)
+
+  var log = pino(sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+    cb()
+  }))
+
+  log.addLevel('foo', 35)
+  log.level = 'foo'
+  log.info('nope')
+  log.foo('bar')
+})
+
+test('children can be set to custom level', function (t) {
+  t.plan(2)
+
+  var parent = pino({level: 'foo', levelVal: 35}, sink(function (chunk, enc, cb) {
+    t.is(chunk.msg, 'bar')
+    t.is(chunk.child, 'yes')
+    cb()
+  }))
+  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})
+  t.is(log.levelVal, 30)
+})
+
+test('reject already known values', function (t) {
+  t.plan(1)
+  try {
+    pino({level: 'foo', levelVal: 30})
+  } catch (e) {
+    t.is(e.message.indexOf('level value') > -1, true)
+  }
+})