Repository: pinojs/pino
Pull request #239 (2017-04-29 01:20:51)

Implement pluggable time functions
This PR implements the time function plugin system discussed in #202 . It also removes the `slowtime` option.  Thus, this should necessitate a major version bump.


Patch:
diff --git a/docs/API.md b/docs/API.md
index 2a6a0aa..1dbdf8e 100644
--- a/docs/API.md
+++ b/docs/API.md
@@ -23,6 +23,10 @@
     + [.req](#reqSerializer)
     + [.res](#resSerializer)
     + [.err](#errSerializer)
+  + [.stdTimeFunctions](#stdTimeFunctions)
+    + [.epochTime](#epochTimeFunction)
+    + [.slowTime](#slowTimeFunction)
+    + [.nullTime](#nullTimeFunction)
 
 # module.exports
 
@@ -38,13 +42,20 @@
     of objects. These functions should return an JSONifiable object and they
     should never throw. Each property name of this object will match to a
     property name is logged objects.
-  * `timestamp` (boolean): Enables or disables the inclusion of a timestamp in the
-    log message. `slowtime` has no effect if this option is set to `false`.
-    Defaults: `true`.
+  * `timestamp` (boolean|function): Enables or disables the inclusion of a timestamp in the
+    log message. If a function is supplied, it must synchronously return a JSON string
+    representation of the time, e.g. `,"time":1493426328206 (which is the default).
+    If set to `false`, no timestamp will be included in the output.
+    See [stdTimeFunctions](#stdTimeFunctions) for a set of available functions
+    for passing in as a value for this option. Caution: any sort of formatted
+    time will significantly slow down Pino's performance.
   * `slowtime` (boolean): 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.md)). Default: `false`.
+     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.md)). Default: `false`.
+     **Deprecation**: this option is scheduled to be removed in Pino 5.0.0. Use
+     `timestamp: pino.stdTimeFunctions.slowTime` instead.
   * `extreme` (boolean): 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.md). Default: `false`.
@@ -536,3 +547,32 @@ Serializes an `Error` object if passed in as an property.
   "stack": "Error: an error\n    at Object.<anonymous> (/Users/matteo/Repositories/pino/example.js:16:7)\n    at Module._compile (module.js:435:26)\n    at Object.Module._extensions..js (module.js:442:10)\n    at Module.load (module.js:356:32)\n    at Function.Module._load (module.js:313:12)\n    at Function.Module.runMain (module.js:467:10)\n    at startup (node.js:136:18)\n    at node.js:963:3"
 }
 ```
+<a id="stdTimeFunctions"></a>
+## .stdTimeFunctions
+
+Available as a static property, the `stdTimeFunctions` provide functions for
+generating the timestamp property in the log output. You can set the `timestamp`
+option during initialization to one of these functions to adjust the output
+format. Alternatively, you can specify your own time function.
+
+A time function must synchronously return a string that would be a valid
+component of a JSON string. For example, the default function returns
+a string like `,"time":1493426328206`.
+
+<a id="epochTimeFunction"></a>
+### .epochTime
+
+The default time function for Pino. Returns a string like `,"time":1493426328206`.
+
+<a id="slowTimeFunction"></a>
+### .slowTime
+
+Returns an ISO formatted string like `,"time":"2017-04-29T00:47:49.354Z". It is
+highly recommended that you avoid this function. It incurs a significant
+performance penalty.
+
+<a id="nullTimeFunction"></a>
+### .nulltime
+
+Returns an empty string. This function is used when the `timestamp` option
+is set to `false`.
diff --git a/lib/time.js b/lib/time.js
index cb35b11..66f0744 100644
--- a/lib/time.js
+++ b/lib/time.js
@@ -1,19 +1,19 @@
 'use strict'
 
-function getNoTime () {
+function nullTime () {
   return ''
 }
 
-function getTime () {
+function epochTime () {
   return ',"time":' + Date.now()
 }
 
-function getSlowTime () {
+function slowTime () {
   return ',"time":"' + (new Date()).toISOString() + '"'
 }
 
 module.exports = {
-  getNoTime: getNoTime,
-  getTime: getTime,
-  getSlowTime: getSlowTime
+  nullTime: nullTime,
+  epochTime: epochTime,
+  slowTime: slowTime
 }
diff --git a/lib/tools.js b/lib/tools.js
index 77f8d2d..f6e8a4d 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -44,12 +44,15 @@ function applyOptions (opts) {
   this._baseLog = flatstr(baseLog +
     (this.name === undefined ? '' : '"name":' + this.stringify(this.name) + ','))
 
-  if (opts.timestamp === false) {
-    this.time = time.getNoTime
-  } else if (opts.slowtime) {
-    this.time = time.getSlowTime
+  if (opts.slowtime) {
+    this.time = time.slowTime
+    process.emitWarning('use `timestamp: pino.stdTimeFunctions.slowTime`', '(pino) `slowtime` is deprecated')
+  } else if (opts.timestamp && Function.prototype.isPrototypeOf(opts.timestamp)) {
+    this.time = opts.timestamp
+  } else if (opts.timestamp) {
+    this.time = time.epochTime
   } else {
-    this.time = time.getTime
+    this.time = time.nullTime
   }
 }
 
diff --git a/pino.js b/pino.js
index e02eecd..aef3b1e 100644
--- a/pino.js
+++ b/pino.js
@@ -10,6 +10,7 @@ var events = require('./lib/events')
 var levels = require('./lib/levels')
 var tools = require('./lib/tools')
 var serializers = require('./lib/serializers')
+var time = require('./lib/time')
 
 var LOG_VERSION = 1
 
@@ -17,7 +18,7 @@ var defaultOptions = {
   safe: true,
   name: undefined,
   serializers: {},
-  timestamp: true,
+  timestamp: time.epochTime,
   slowtime: false,
   extreme: false,
   level: 'info',
@@ -315,6 +316,7 @@ module.exports.stdSerializers = {
   res: serializers.asResValue,
   err: serializers.asErrValue
 }
+module.exports.stdTimeFunctions = Object.assign({}, time)
 module.exports.pretty = pretty
 Object.defineProperty(
   module.exports,


Test patch:
diff --git a/test/http.test.js b/test/http.test.js
index b4d1cb9..d4463b4 100644
--- a/test/http.test.js
+++ b/test/http.test.js
@@ -5,6 +5,7 @@ var os = require('os')
 var pino = require('../')
 var sink = require('./helper').sink
 var http = require('http')
+var time = require('../lib/time')
 
 var pid = process.pid
 var hostname = os.hostname()
@@ -164,7 +165,7 @@ test('http response support via a serializer', function (t) {
 })
 
 test('slowtime', function (t) {
-  var instance = pino({slowtime: true},
+  var instance = pino({timestamp: time.slowTime},
     sink(function (chunk, enc, cb) {
       t.ok(Date.parse(chunk.time) <= new Date(), 'time is greater than Date.now()')
       t.end()
diff --git a/test/timestamp.test.js b/test/timestamp.test.js
index 761b42b..8e4d06d 100644
--- a/test/timestamp.test.js
+++ b/test/timestamp.test.js
@@ -4,6 +4,28 @@ var test = require('tap').test
 var pino = require('../')
 var sink = require('./helper').sink
 
+test('pino exposes standard time functions', function (t) {
+  t.plan(4)
+  t.ok(pino.stdTimeFunctions)
+  t.ok(pino.stdTimeFunctions.epochTime)
+  t.ok(pino.stdTimeFunctions.slowTime)
+  t.ok(pino.stdTimeFunctions.nullTime)
+})
+
+test('pino accepts external time functions', function (t) {
+  t.plan(2)
+  var opts = {
+    timestamp: function () {
+      return ',"time":"none"'
+    }
+  }
+  var instance = pino(opts, sink(function (chunk, enc, cb) {
+    t.equal(chunk.hasOwnProperty('time'), true)
+    t.equal(chunk.time, 'none')
+  }))
+  instance.info('foobar')
+})
+
 test('inserts timestamp by default', function (t) {
   var instance = pino(sink(function (chunk, enc, cb) {
     t.equal(chunk.hasOwnProperty('time'), true)