more careful timestamp extraction (#675)

lib/proto.js

@@ -12,6 +12,7 @@ const {
   messageKeySym,
   writeSym,
   timeSym,
+  timeSliceIndexSym,
   streamSym,
   serializersSym,
   useOnlyCustomLevelsSym,
@@ -130,7 +131,7 @@ function write (_obj, msg, num) {
     // it is not needed anymore
     stream.lastMsg = msg
     stream.lastObj = obj
-    stream.lastTime = t.slice(8)
+    stream.lastTime = t.slice(this[timeSliceIndexSym])
     stream.lastLogger = this // for child loggers
   }
   if (stream instanceof SonicBoom) stream.write(s)

lib/symbols.js

@@ -16,6 +16,7 @@ const writeSym = Symbol('pino.write')
 const redactFmtSym = Symbol('pino.redactFmt')
 
 const timeSym = Symbol('pino.time')
+const timeSliceIndexSym = Symbol('pino.timeSliceIndex')
 const streamSym = Symbol('pino.stream')
 const stringifySym = Symbol('pino.stringify')
 const stringifiersSym = Symbol('pino.stringifiers')
@@ -44,6 +45,7 @@ module.exports = {
   serializersSym,
   redactFmtSym,
   timeSym,
+  timeSliceIndexSym,
   streamSym,
   stringifySym,
   stringifiersSym,

pino.js

@@ -19,6 +19,7 @@ const {
   redactFmtSym,
   serializersSym,
   timeSym,
+  timeSliceIndexSym,
   streamSym,
   stringifySym,
   stringifiersSym,
@@ -88,6 +89,7 @@ function pino (...args) {
     ? coreChindings(base) : coreChindings(Object.assign({}, base, { name }))
   const time = (timestamp instanceof Function)
     ? timestamp : (timestamp ? epochTime : nullTime)
+  const timeSliceIndex = time().indexOf(':') + 1
 
   if (useOnlyCustomLevels && !customLevels) throw Error('customLevels is required if useOnlyCustomLevels is set true')
 
@@ -101,6 +103,7 @@ function pino (...args) {
     [useOnlyCustomLevelsSym]: useOnlyCustomLevels,
     [streamSym]: stream,
     [timeSym]: time,
+    [timeSliceIndexSym]: timeSliceIndex,
     [stringifySym]: stringify,
     [stringifiersSym]: stringifiers,
     [endSym]: end,

test/fixtures/pretty/custom-time-label.js

@@ -0,0 +1,9 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../../'))
+var log = pino({
+  timestamp: () => `,"custom-time-label":"test"`,
+  prettyPrint: true
+})
+log.info('h')

test/pretty.test.js

@@ -181,6 +181,18 @@ test('with custom timestamp', async ({ is }) => {
   is(actual.slice(0, 8), '["test"]')
 })
 
+test('with custom timestamp label', async ({ is }) => {
+  var actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'pretty', 'custom-time-label.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  is(actual.slice(0, 8), '["test"]')
+})
+
 test('errors', async ({ isNot }) => {
   var actual = ''
   const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'pretty', 'error.js')])

test/timestamp.test.js

@@ -23,6 +23,18 @@ test('pino accepts external time functions', async ({ is }) => {
   is(result.time, 'none')
 })
 
+test('pino accepts external time functions with custom label', async ({ is }) => {
+  const opts = {
+    timestamp: () => ',"custom-time-label":"none"'
+  }
+  const stream = sink()
+  const instance = pino(opts, stream)
+  instance.info('foobar')
+  const result = await once(stream, 'data')
+  is(result.hasOwnProperty('custom-time-label'), true)
+  is(result['custom-time-label'], 'none')
+})
+
 test('inserts timestamp by default', async ({ ok, is }) => {
   const stream = sink()
   const instance = pino(stream)