Repository: pinojs/pino
Pull request #315 (2017-10-24 15:03:53)

browser-transmit-timestamp
pretty big omission from the new transmit API, 
logEvents should have a timestamp so when it reaches the server we know
the time of the logEvent (the logEvent doesn't contain the final object, so no `time` prop)

Code has been refactored so we only wrap
the logger function once, and then perform operations (serialize, asObject mode, transmit) from there instead of having heirarchy of function wrappers. 

This also means we can take a timestamp right when the log message is called, and then use that in asObject for `time` prop and as the `ts` prop in the `logEvent` - so we have a consistent timestamp




Patch:
diff --git a/README.md b/README.md
index c85634d..8b0902c 100644
--- a/README.md
+++ b/README.md
@@ -322,12 +322,16 @@ 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']`).
 
diff --git a/browser.js b/browser.js
index dc93899..be29e4b 100644
--- a/browser.js
+++ b/browser.js
@@ -136,71 +136,59 @@ 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)
+  wrap(opts, logger, val, level)
 }
 
-function serializerWrap (logger, level) {
+function wrap (opts, logger, val, level) {
+  if (!opts.transmit && logger[level] === noop) return
+
   logger[level] = (function (write) {
     return function LOG () {
+      var ts = Date.now()
       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)
+      if (opts.serialize && !opts.asObject) {
+        applySerializers(args, this._serialize, this.serializers, this._stdErrSerialize)
+      }
+      if (opts.asObject) write.call(this, asObject(this, level, args, ts))
+      else write.apply(this, args)
+
+      if (opts.transmit) {
+        var transmitLevel = opts.transmit.level || opts.level
+        var transmitValue = pino.levels.values[transmitLevel]
+        var methodValue = pino.levels.values[level]
+        if (methodValue < transmitValue) return
+        transmit(this, {
+          ts: ts,
+          methodLevel: level,
+          methodValue: methodValue,
+          transmitLevel: transmitLevel,
+          transmitValue: pino.levels.values[opts.transmit.level || opts.level],
+          send: opts.transmit.send,
+          val: val
+        }, args)
+      }
     }
-  })(logger[level], level)
+  })(logger[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)
+function asObject (logger, level, args, ts) {
+  if (logger._serialize) applySerializers(args, logger._serialize, logger.serializers, logger._stdErrSerialize)
+  var msg = args[0]
+  var o = { time: ts, level: pino.levels.values[level] }
+  var lvl = (logger._childLevel | 0) + 1
+  if (lvl < 1) lvl = 1
+  // deliberate, catching objects, arrays
+  if (msg !== null && typeof msg === 'object') {
+    args = args.slice()
+    while (lvl-- && typeof args[0] === 'object') {
+      Object.assign(o, args.shift())
     }
-  })(logger[methodLevel])
+    msg = args.length ? format(args) : undefined
+  } else if (typeof msg === 'string') msg = format(args)
+  if (msg !== undefined) o.msg = msg
+  return o
 }
 
 function applySerializers (args, serialize, serializers, stdErrSerialize) {
@@ -230,6 +218,7 @@ function bind (parent, bindings, level) {
 
 function transmit (logger, opts, args) {
   var send = opts.send
+  var ts = opts.ts
   var methodLevel = opts.methodLevel
   var methodValue = opts.methodValue
   var val = opts.val
@@ -240,7 +229,7 @@ function transmit (logger, opts, args) {
     logger.serializers,
     logger._stdErrSerialize === undefined ? true : logger._stdErrSerialize
   )
-
+  logger._logEvent.ts = ts
   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
@@ -256,6 +245,7 @@ function transmit (logger, opts, args) {
 
 function createLogEventShape () {
   return {
+    ts: 0,
     messages: [],
     bindings: [],
     level: {label: '', value: 0}


Test patch:
diff --git a/test/browser.transmit.test.js b/test/browser.transmit.test.js
index 3acfbd1..cb22448 100644
--- a/test/browser.transmit.test.js
+++ b/test/browser.transmit.test.js
@@ -70,6 +70,26 @@ test('passes send function messages in logEvent object', function (t) {
   logger.fatal({test: 'test'}, 'another test')
 })
 
+test('supplies a timestamp (ts) in logEvent object which is exactly the same as the `time` property in asObject mode', function (t) {
+  t.plan(1)
+  var expected
+  var logger = pino({
+    browser: {
+      asObject: true, // implict because `write`, but just to be explicit
+      write: function (o) {
+        expected = o.time
+      },
+      transmit: {
+        send: function (level, logEvent) {
+          t.is(logEvent.ts, expected)
+        }
+      }
+    }
+  })
+
+  logger.fatal('test')
+})
+
 test('passes send function child bindings via logEvent object', function (t) {
   t.plan(4)
   var logger = pino({