Repository: pinojs/pino
Pull request #312 (2017-10-20 00:33:53)

browser transmit API
This adds a new API to pino browser, which facilitates log messages to be sent across the wire 

the user supplies a `send` function via a `transmit` object on the `browser` options object, 
the `send` function is passed `level` and `logEvent` params. The `logEvent` represents the log message, including child bindings and their hierarchy, each argument passed to the log method (after serializers have been applied, which is mandatory even if not enabled), and the level label and value. 

The `send` function is totally decoupled from the `write` function, and can use a different level which can be set on the `transmit` object. 

See the readme update for more details

The main point of this API is to open up a new type of client side plugin, e.g. 

```js
var pino = require('pino')
var logger = pino({
  browser: {
    transmit: require('pino-splunk-transmitter')
  }
})
```

Next steps after this is to build `pino-transmit` (sort of a browser-server analogy to `pino-socket`) . `pino-transmit` would be specifically for encoding and relaying messages across the wire using the [beacon API](https://developer.mozilla.org/en-US/docs/Web/API/Beacon_API) on the client side (falling back to XHR), and then receiving, decoding those messages on the server.

Hypothetical modules like `pino-splunk-transmitter` could then be built on top of `pino-transmit`, but `pino-transmit` would also usable as a standalone plugin with the `browser.transmit` api.

Coverage is 100% 


Patch:
diff --git a/README.md b/README.md
index e1e4013..c85634d 100644
--- a/README.md
+++ b/README.md
@@ -302,6 +302,73 @@ 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
+{ 
+  messages = Array, 
+  bindings = Array, 
+  level: { label = String, value = Number}
+}
+```
+
+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: 
+
+```js
+var 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 
+        }
+      }
+    }
+  }
+})
+```
+
 <a name="caveats"></a>
 ## Caveats
 
diff --git a/browser.js b/browser.js
index 241ff71..dc93899 100644
--- a/browser.js
+++ b/browser.js
@@ -14,6 +14,10 @@ var stdSerializers = {
 function pino (opts) {
   opts = opts || {}
   opts.browser = opts.browser || {}
+
+  var transmit = opts.browser.transmit
+  if (transmit && typeof transmit.send !== 'function') { throw Error('pino: transmit option must have a send function') }
+
   var proto = opts.browser.write || _console
   if (opts.browser.write) opts.browser.asObject = true
   var serializers = opts.serializers || {}
@@ -42,12 +46,20 @@ function pino (opts) {
   var logger = Object.create(proto)
   if (!logger.log) logger.log = noop
 
-  set(logger, val, 'error', 'log') // <-- must stay first
-  set(logger, val, 'fatal', 'error')
-  set(logger, val, 'warn', 'error')
-  set(logger, val, 'info', 'log')
-  set(logger, val, 'debug', 'log')
-  set(logger, val, 'trace', 'log')
+  var setOpts = {
+    transmit: transmit,
+    serialize: serialize,
+    asObject: opts.browser.asObject,
+    levels: levels,
+    level: level
+  }
+
+  set(setOpts, logger, val, 'error', 'log') // <-- must stay first
+  set(setOpts, logger, val, 'fatal', 'error')
+  set(setOpts, logger, val, 'warn', 'error')
+  set(setOpts, logger, val, 'info', 'log')
+  set(setOpts, logger, val, 'debug', 'log')
+  set(setOpts, logger, val, 'trace', 'log')
 
   logger.setMaxListeners = logger.getMaxListeners =
   logger.emit = logger.addListener = logger.on =
@@ -61,12 +73,15 @@ function pino (opts) {
   logger._stdErrSerialize = stdErrSerialize
   logger.child = child
 
+  if (transmit) logger._logEvent = createLogEventShape()
+
   function child (bindings) {
     if (!bindings) {
       throw new Error('missing bindings for child Pino')
     }
-    if (serialize && bindings.serializers) {
-      var childSerializers = Object.assign({}, serializers, bindings.serializers)
+    var bindingsSerializers = bindings.serializers
+    if (serialize && bindingsSerializers) {
+      var childSerializers = Object.assign({}, serializers, bindingsSerializers)
       var childSerialize = opts.browser.serialize === true
         ? Object.keys(childSerializers)
         : serialize
@@ -85,69 +100,12 @@ function pino (opts) {
         this.serializers = childSerializers
         this._serialize = childSerialize
       }
+      if (transmit) this._logEvent.bindings.push(bindings)
     }
     Child.prototype = this
     return new Child(this)
   }
   logger.levels = pino.levels
-  if (serialize && !opts.browser.asObject) serializerWrap(logger, levels)
-  return !opts.browser.asObject ? logger : asObject(logger, levels)
-}
-
-function serializerWrap (logger, levels) {
-  var k
-  for (var i = 0; i < levels.length; i++) {
-    k = levels[i]
-    logger[k] = (function (write) {
-      return function LOG () {
-        var args = new Array(arguments.length)
-        for (var i = 0; i < args.length; i++) args[i] = arguments[i]
-        applySerializers(args, this._serialize, this.serializers, this._stdErrSerialize)
-        write.apply(this, args)
-      }
-    })(logger[k])
-  }
-}
-
-function applySerializers (args, serialize, serializers, stdErrSerialize) {
-  for (var i in args) {
-    if (stdErrSerialize && args[i] instanceof Error) {
-      args[i] = pino.stdSerializers.err(args[i])
-    } else if (typeof args[i] === 'object' && !Array.isArray(args[i])) {
-      for (var k in args[i]) {
-        if (serialize.indexOf(k) > -1 && k in serializers) {
-          args[i][k] = serializers[k](args[i][k])
-        }
-      }
-    }
-  }
-}
-
-function asObject (logger, levels) {
-  var k
-  for (var i = 0; i < levels.length; i++) {
-    k = levels[i]
-    logger[k] = (function (write, k) {
-      return function LOG () {
-        var args = new Array(arguments.length)
-        for (var i = 0; i < args.length; i++) args[i] = arguments[i]
-        if (this._serialize) applySerializers(args, this._serialize, this.serializers, this._stdErrSerialize)
-        var msg = args[0]
-        var o = { time: Date.now(), level: pino.levels.values[k] }
-        var lvl = (this._childLevel | 0) + 1
-        if (lvl < 1) lvl = 1
-        // deliberate, catching objects, arrays
-        if (msg !== null && typeof msg === 'object') {
-          while (lvl-- && typeof args[0] === 'object') {
-            Object.assign(o, args.shift())
-          }
-          msg = args.length ? format(args) : undefined
-        } else if (typeof msg === 'string') msg = format(args)
-        if (msg !== undefined) o.msg = msg
-        write.call(this, o)
-      }
-    })(logger[k], k)
-  }
   return logger
 }
 
@@ -174,6 +132,91 @@ pino.levels = {
 
 pino.stdSerializers = stdSerializers
 
+function set (opts, logger, val, level, fallback) {
+  logger[level] = val > pino.levels.values[level] ? noop
+    : (logger[level] ? logger[level] : (_console[level] || _console[fallback] || noop))
+
+  if (opts.serialize && !opts.asObject) serializerWrap(logger, level)
+  if (opts.asObject) asObjectWrap(logger, level)
+  if (opts.transmit) transmitWrap(opts.transmit, logger, val, level, opts.level)
+}
+
+function serializerWrap (logger, level) {
+  logger[level] = (function (write) {
+    return function LOG () {
+      var args = new Array(arguments.length)
+      for (var i = 0; i < args.length; i++) args[i] = arguments[i]
+      applySerializers(args, this._serialize, this.serializers, this._stdErrSerialize)
+      write.apply(this, args)
+    }
+  })(logger[level])
+}
+
+function asObjectWrap (logger, level) {
+  logger[level] = (function (write, k) {
+    return function LOG () {
+      var args = new Array(arguments.length)
+      for (var i = 0; i < args.length; i++) args[i] = arguments[i]
+      if (this._serialize) applySerializers(args, this._serialize, this.serializers, this._stdErrSerialize)
+      var msg = args[0]
+      var o = { time: Date.now(), level: pino.levels.values[k] }
+      var lvl = (this._childLevel | 0) + 1
+      if (lvl < 1) lvl = 1
+      // deliberate, catching objects, arrays
+      if (msg !== null && typeof msg === 'object') {
+        while (lvl-- && typeof args[0] === 'object') {
+          Object.assign(o, args.shift())
+        }
+        msg = args.length ? format(args) : undefined
+      } else if (typeof msg === 'string') msg = format(args)
+      if (msg !== undefined) o.msg = msg
+      write.call(this, o)
+    }
+  })(logger[level], level)
+}
+
+function transmitWrap (opts, logger, val, methodLevel, logLevel) {
+  var transmitLevel = opts.level || logLevel
+  var transmitValue = pino.levels.values[transmitLevel]
+  var methodValue = pino.levels.values[methodLevel]
+  var send = opts.send
+
+  if (methodValue < transmitValue) {
+    return
+  }
+
+  logger[methodLevel] = (function (write) {
+    return function () {
+      var args = new Array(arguments.length)
+      for (var i = 0; i < args.length; i++) args[i] = arguments[i]
+      write.apply(this, args)
+      var transmitOpts = {
+        methodLevel: methodLevel,
+        methodValue: methodValue,
+        transmitLevel: transmitLevel,
+        transmitValue: transmitValue,
+        send: send,
+        val: val
+      }
+      transmit(this, transmitOpts, args)
+    }
+  })(logger[methodLevel])
+}
+
+function applySerializers (args, serialize, serializers, stdErrSerialize) {
+  for (var i in args) {
+    if (stdErrSerialize && args[i] instanceof Error) {
+      args[i] = pino.stdSerializers.err(args[i])
+    } else if (typeof args[i] === 'object' && !Array.isArray(args[i])) {
+      for (var k in args[i]) {
+        if (serialize && serialize.indexOf(k) > -1 && k in serializers) {
+          args[i][k] = serializers[k](args[i][k])
+        }
+      }
+    }
+  }
+}
+
 function bind (parent, bindings, level) {
   return function () {
     var args = new Array(1 + arguments.length)
@@ -185,9 +228,38 @@ function bind (parent, bindings, level) {
   }
 }
 
-function set (logger, val, level, fallback) {
-  logger[level] = val > pino.levels.values[level] ? noop
-    : (logger[level] ? logger[level] : (_console[level] || _console[fallback] || noop))
+function transmit (logger, opts, args) {
+  var send = opts.send
+  var methodLevel = opts.methodLevel
+  var methodValue = opts.methodValue
+  var val = opts.val
+
+  applySerializers(
+    args,
+    logger._serialize || Object.keys(logger.serializers),
+    logger.serializers,
+    logger._stdErrSerialize === undefined ? true : logger._stdErrSerialize
+  )
+
+  logger._logEvent.messages = args.filter(function (arg) {
+      // bindings can only be objects, so reference equality check via indexOf is fine
+    return logger._logEvent.bindings.indexOf(arg) === -1
+  })
+
+  logger._logEvent.level.label = methodLevel
+  logger._logEvent.level.value = methodValue
+
+  send(methodLevel, logger._logEvent, val)
+
+  logger._logEvent = createLogEventShape()
+}
+
+function createLogEventShape () {
+  return {
+    messages: [],
+    bindings: [],
+    level: {label: '', value: 0}
+  }
 }
 
 function asErrValue (err) {


Test patch:
diff --git a/test/browser.transmit.test.js b/test/browser.transmit.test.js
new file mode 100644
index 0000000..67e98a6
--- /dev/null
+++ b/test/browser.transmit.test.js
@@ -0,0 +1,239 @@
+'use strict'
+var test = require('tap').test
+var pino = require('../browser')
+
+function noop () {}
+
+test('throws if transmit object does not have send function', function (t) {
+  t.throws(function () {
+    pino({browser: {transmit: {}}})
+  })
+
+  t.throws(function () {
+    pino({browser: {transmit: {send: 'not a func'}}})
+  })
+
+  t.end()
+})
+
+test('calls send function after write', function (t) {
+  t.plan(1)
+  var c = 0
+  var logger = pino({
+    browser: {
+      write: function (o) {
+        c++
+      },
+      transmit: {
+        send: function () {
+          t.is(c, 1)
+        }
+      }
+    }
+  })
+
+  logger.fatal({test: 'test'})
+})
+
+test('passes send function the logged level', function (t) {
+  t.plan(1)
+  var logger = pino({
+    browser: {
+      write: function (o) {
+      },
+      transmit: {
+        send: function (level) {
+          t.is(level, 'fatal')
+        }
+      }
+    }
+  })
+
+  logger.fatal({test: 'test'})
+})
+
+test('passes send function messages in logEvent object', function (t) {
+  t.plan(2)
+  var logger = pino({
+    browser: {
+      write: noop,
+      transmit: {
+        send: function (level, logEvent) {
+          var messages = logEvent.messages
+          t.same(messages[0], {test: 'test'})
+          t.is(messages[1], 'another test')
+        }
+      }
+    }
+  })
+
+  logger.fatal({test: 'test'}, 'another test')
+})
+
+test('passes send function child bindings via logEvent object', function (t) {
+  t.plan(4)
+  var logger = pino({
+    browser: {
+      write: noop,
+      transmit: {
+        send: function (level, logEvent) {
+          var messages = logEvent.messages
+          var bindings = logEvent.bindings
+          t.same(bindings[0], {first: 'binding'})
+          t.same(bindings[1], {second: 'binding2'})
+          t.same(messages[0], {test: 'test'})
+          t.is(messages[1], 'another test')
+        }
+      }
+    }
+  })
+
+  logger
+    .child({first: 'binding'})
+    .child({second: 'binding2'})
+    .fatal({test: 'test'}, 'another test')
+})
+
+test('passes send function level:{label, value} via logEvent object', function (t) {
+  t.plan(2)
+  var logger = pino({
+    browser: {
+      write: noop,
+      transmit: {
+        send: function (level, logEvent) {
+          var label = logEvent.level.label
+          var value = logEvent.level.value
+
+          t.is(label, 'fatal')
+          t.is(value, 60)
+        }
+      }
+    }
+  })
+
+  logger.fatal({test: 'test'}, 'another test')
+})
+
+test('calls send function according to transmit.level', function (t) {
+  t.plan(2)
+  var c = 0
+  var logger = pino({
+    browser: {
+      write: noop,
+      transmit: {
+        level: 'error',
+        send: function (level) {
+          c++
+          if (c === 1) t.is(level, 'error')
+          if (c === 2) t.is(level, 'fatal')
+        }
+      }
+    }
+  })
+  logger.warn('ignored')
+  logger.error('test')
+  logger.fatal('test')
+})
+
+test('transmit.level defaults to logger level', function (t) {
+  t.plan(2)
+  var c = 0
+  var logger = pino({
+    level: 'error',
+    browser: {
+      write: noop,
+      transmit: {
+        send: function (level) {
+          c++
+          if (c === 1) t.is(level, 'error')
+          if (c === 2) t.is(level, 'fatal')
+        }
+      }
+    }
+  })
+  logger.warn('ignored')
+  logger.error('test')
+  logger.fatal('test')
+})
+
+test('transmit.level is effective even if lower than logger level', function (t) {
+  t.plan(3)
+  var c = 0
+  var logger = pino({
+    level: 'error',
+    browser: {
+      write: noop,
+      transmit: {
+        level: 'info',
+        send: function (level) {
+          c++
+          if (c === 1) t.is(level, 'warn')
+          if (c === 2) t.is(level, 'error')
+          if (c === 3) t.is(level, 'fatal')
+        }
+      }
+    }
+  })
+  logger.warn('ignored')
+  logger.error('test')
+  logger.fatal('test')
+})
+
+test('applies all serializers to messages and bindings (serialize:false - default)', function (t) {
+  t.plan(4)
+  var logger = pino({
+    serializers: {
+      first: function () { return 'first' },
+      second: function () { return 'second' },
+      test: function () { return 'serialize it' }
+    },
+    browser: {
+      write: noop,
+      transmit: {
+        send: function (level, logEvent) {
+          var messages = logEvent.messages
+          var bindings = logEvent.bindings
+          t.same(bindings[0], {first: 'first'})
+          t.same(bindings[1], {second: 'second'})
+          t.same(messages[0], {test: 'serialize it'})
+          t.is(messages[1].type, 'Error')
+        }
+      }
+    }
+  })
+
+  logger
+    .child({first: 'binding'})
+    .child({second: 'binding2'})
+    .fatal({test: 'test'}, Error())
+})
+
+test('applies all serializers to messages and bindings (serialize:true)', function (t) {
+  t.plan(4)
+  var logger = pino({
+    serializers: {
+      first: function () { return 'first' },
+      second: function () { return 'second' },
+      test: function () { return 'serialize it' }
+    },
+    browser: {
+      serialize: true,
+      write: noop,
+      transmit: {
+        send: function (level, logEvent) {
+          var messages = logEvent.messages
+          var bindings = logEvent.bindings
+          t.same(bindings[0], {first: 'first'})
+          t.same(bindings[1], {second: 'second'})
+          t.same(messages[0], {test: 'serialize it'})
+          t.is(messages[1].type, 'Error')
+        }
+      }
+    }
+  })
+
+  logger
+    .child({first: 'binding'})
+    .child({second: 'binding2'})
+    .fatal({test: 'test'}, Error())
+})