Repository: pinojs/pino
Pull request #741 (2019-11-14 14:22:03)

feat(mixin): add mixin config option
@mcollina here's the "context" PR as we talked about at NodeConf. I ended up calling the feature "mixin" instead, as I think that suits the use-case better. But feel free to suggest other names 😃 

jsumners: Wouldn't this function need to be synchronous? That should be called out in the docs.

I'm not enamored with the name "mixin" but I don't have a better suggestion either.

Patch:
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
new file mode 100644
index 0000000..ce34d1b
--- /dev/null
+++ b/.github/workflows/ci.yml
@@ -0,0 +1,38 @@
+name: CI
+on: [push, pull_request]
+jobs:
+  build:
+    name: ${{ matrix.node-version }} ${{ matrix.os }}
+    runs-on: ${{ matrix.os }}
+    strategy:
+      fail-fast: false
+      matrix:
+        os: [macOS-latest, windows-latest, ubuntu-latest]
+        node-version: [6, 8, 10, 11, 12, 13]
+    steps:
+      - uses: actions/checkout@v1
+      - name: Use Node.js ${{ matrix.node-version }}
+        uses: actions/setup-node@v1
+        with:
+          node-version: ${{ matrix.node-version }}
+      - name: Install
+        run: npm i
+      - name: Tests
+        run: npm run test
+  coverage:
+    name: coverage
+    runs-on: ubuntu-latest
+    steps:
+      - uses: actions/checkout@v1
+      - name: Use Node.js 12
+        uses: actions/setup-node@v1
+        with:
+          node-version: 12
+      - name: Install
+        run: npm i
+      - name: run with coverage
+        run: npm run cov-ci
+      - name: Coveralls
+        uses: coverallsapp/github-action@master
+        with:
+          github-token: ${{ secrets.GITHUB_TOKEN }}
diff --git a/.travis.yml b/.travis.yml
index 0c45ee9..3aa2522 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -5,6 +5,8 @@ node_js:
   - 8
   - 10
   - 11
+  - 12
+  - 13
 script:
   - npm run ci
 env:
diff --git a/docs/api.md b/docs/api.md
index 7e7afae..6e15ba3 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -96,6 +96,28 @@ logger.foo('hi')
 logger.info('hello') // Will throw an error saying info in not found in logger object
 ```
 
+#### `mixin` (Function):
+
+Default: `undefined`
+
+If provided, the `mixin` function is called each time one of the active
+logging methods is called. The function must synchronously return an
+object. The properties of the returned object will be added to the
+logged JSON.
+
+```js
+let n = 0
+const logger = pino({
+  mixin () {
+    return { line: ++n }
+  }
+})
+logger.info('hello')
+// {"level":30,"time":1573664685466,"pid":78742,"hostname":"x","line":1,"msg":"hello","v":1}
+logger.info('world')
+// {"level":30,"time":1573664685469,"pid":78742,"hostname":"x","line":2,"msg":"world","v":1}
+```
+
 #### `redact` (Array | Object):
 
 Default: `undefined`
diff --git a/lib/levels.js b/lib/levels.js
index a9e0e55..c4ebbdc 100644
--- a/lib/levels.js
+++ b/lib/levels.js
@@ -24,7 +24,11 @@ const levelMethods = {
     const stream = this[streamSym]
     logFatal.call(this, ...args)
     if (typeof stream.flushSync === 'function') {
-      stream.flushSync()
+      try {
+        stream.flushSync()
+      } catch (e) {
+        // https://github.com/pinojs/pino/pull/740#discussion_r346788313
+      }
     }
   },
   error: genLog(levels.error),
diff --git a/lib/proto.js b/lib/proto.js
index 09cc0d9..a063b21 100644
--- a/lib/proto.js
+++ b/lib/proto.js
@@ -11,6 +11,7 @@ const {
   setLevelSym,
   getLevelSym,
   chindingsSym,
+  mixinSym,
   asJsonSym,
   messageKeySym,
   writeSym,
@@ -115,14 +116,15 @@ function bindings () {
 function write (_obj, msg, num) {
   const t = this[timeSym]()
   const messageKey = this[messageKeySym]
+  const mixin = this[mixinSym]
   const objError = _obj instanceof Error
   var obj
 
   if (_obj === undefined || _obj === null) {
-    obj = {}
+    obj = mixin ? mixin() : {}
     obj[messageKey] = msg
   } else {
-    obj = Object.assign({}, _obj)
+    obj = Object.assign(mixin ? mixin() : {}, _obj)
     if (msg) {
       obj[messageKey] = msg
     } else if (objError) {
diff --git a/lib/symbols.js b/lib/symbols.js
index 38c3609..22446a8 100644
--- a/lib/symbols.js
+++ b/lib/symbols.js
@@ -6,6 +6,7 @@ const levelValSym = Symbol('pino.levelVal')
 const useLevelLabelsSym = Symbol('pino.useLevelLabels')
 const changeLevelNameSym = Symbol('pino.changeLevelName')
 const useOnlyCustomLevelsSym = Symbol('pino.useOnlyCustomLevels')
+const mixinSym = Symbol('pino.mixin')
 
 const lsCacheSym = Symbol('pino.lsCache')
 const chindingsSym = Symbol('pino.chindings')
@@ -37,6 +38,7 @@ module.exports = {
   getLevelSym,
   levelValSym,
   useLevelLabelsSym,
+  mixinSym,
   lsCacheSym,
   chindingsSym,
   parsedChindingsSym,
diff --git a/package.json b/package.json
index 4cfce0d..37c0535 100644
--- a/package.json
+++ b/package.json
@@ -20,6 +20,7 @@
     "browser-test": "airtap --local 8080 test/browser*test.js",
     "test": "standard | snazzy && cross-env NODE_OPTIONS=\"--no-warnings -r qodaa\" tap --no-esm -j 4 --no-cov test/*test.js",
     "ci": "standard | snazzy && cross-env TAP_TIMEOUT=480000 NODE_OPTIONS=\"--no-warnings -r qodaa\" tap --no-esm -j 4 --100 test/*test.js",
+    "cov-ci": "cross-env TAP_TIMEOUT=480000 NODE_OPTIONS=\"--no-warnings -r qodaa\" tap --no-esm -j 4 --100 --coverage-report=lcov test/*test.js",
     "cov-ui": "cross-env NODE_OPTIONS=\"--no-warnings -r qodaa\" tap --no-esm -j 4 --coverage-report=html test/*test.js",
     "bench": "node benchmarks/utils/runbench all",
     "bench-basic": "node benchmarks/utils/runbench basic",
@@ -75,6 +76,7 @@
     "proxyquire": "^2.1.3",
     "pump": "^3.0.0",
     "qodaa": "^1.0.1",
+    "semver": "^6.3.0",
     "snazzy": "^8.0.0",
     "split2": "^3.1.1",
     "standard": "^14.2.0",
diff --git a/pino.js b/pino.js
index 14ad86c..9a6aeb3 100644
--- a/pino.js
+++ b/pino.js
@@ -29,6 +29,7 @@ const {
   messageKeySym,
   useLevelLabelsSym,
   changeLevelNameSym,
+  mixinSym,
   useOnlyCustomLevelsSym
 } = symbols
 const { epochTime, nullTime } = time
@@ -71,6 +72,7 @@ function pino (...args) {
     customLevels,
     useLevelLabels,
     changeLevelName,
+    mixin,
     useOnlyCustomLevels
   } = opts
 
@@ -92,6 +94,7 @@ function pino (...args) {
   const timeSliceIndex = time().indexOf(':') + 1
 
   if (useOnlyCustomLevels && !customLevels) throw Error('customLevels is required if useOnlyCustomLevels is set true')
+  if (mixin && typeof mixin !== 'function') throw Error(`Unknown mixin type "${typeof mixin}" - expected "function"`)
 
   assertDefaultLevelFound(level, customLevels, useOnlyCustomLevels)
   const levels = mappings(customLevels, useOnlyCustomLevels)
@@ -110,6 +113,7 @@ function pino (...args) {
     [formatOptsSym]: formatOpts,
     [messageKeySym]: messageKey,
     [serializersSym]: serializers,
+    [mixinSym]: mixin,
     [chindingsSym]: chindings
   }
   Object.setPrototypeOf(instance, proto)


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index a83c6e5..2a1475a 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -479,7 +479,7 @@ test('pino.destination', async ({ same }) => {
   )
   const instance = pino(pino.destination(tmp))
   instance.info('hello')
-  await sleep(250)
+  await sleep(300)
   const result = JSON.parse(readFileSync(tmp).toString())
   delete result.time
   same(result, {
@@ -498,7 +498,7 @@ test('auto pino.destination with a string', async ({ same }) => {
   )
   const instance = pino(tmp)
   instance.info('hello')
-  await sleep(250)
+  await sleep(300)
   const result = JSON.parse(readFileSync(tmp).toString())
   delete result.time
   same(result, {
@@ -517,7 +517,7 @@ test('auto pino.destination with a string as second argument', async ({ same })
   )
   const instance = pino(null, tmp)
   instance.info('hello')
-  await sleep(250)
+  await sleep(300)
   const result = JSON.parse(readFileSync(tmp).toString())
   delete result.time
   same(result, {
@@ -538,7 +538,7 @@ test('does not override opts with a string as second argument', async ({ same })
     timestamp: () => ',"time":"none"'
   }, tmp)
   instance.info('hello')
-  await sleep(250)
+  await sleep(300)
   const result = JSON.parse(readFileSync(tmp).toString())
   same(result, {
     pid: pid,
diff --git a/test/http.test.js b/test/http.test.js
index eddcc79..1c2023e 100644
--- a/test/http.test.js
+++ b/test/http.test.js
@@ -2,6 +2,7 @@
 
 const http = require('http')
 const os = require('os')
+const semver = require('semver')
 const { test } = require('tap')
 const { sink, once } = require('./helper')
 const pino = require('../')
@@ -93,7 +94,7 @@ test('http request support via serializer without request connection', async ({
   }, sink((chunk, enc) => {
     ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
     delete chunk.time
-    same(chunk, {
+    const expected = {
       pid: pid,
       hostname: hostname,
       level: 30,
@@ -104,7 +105,12 @@ test('http request support via serializer without request connection', async ({
         url: originalReq.url,
         headers: originalReq.headers
       }
-    })
+    }
+    if (semver.gte(process.version, '13.0.0')) {
+      expected.req.remoteAddress = originalReq.connection.remoteAddress
+      expected.req.remotePort = originalReq.connection.remotePort
+    }
+    same(chunk, expected)
   }))
 
   const server = http.createServer(function (req, res) {
diff --git a/test/levels.test.js b/test/levels.test.js
index 4643ad8..b7ac1cc 100644
--- a/test/levels.test.js
+++ b/test/levels.test.js
@@ -417,3 +417,16 @@ test('fatal method sync-flushes the destination if sync flushing is available',
     instance.fatal('this is fatal')
   })
 })
+
+test('fatal method should call async when sync-flushing fails', ({ equal, fail, doesNotThrow, plan }) => {
+  plan(2)
+  const messages = [
+    'this is fatal 1'
+  ]
+  const stream = sink((result) => equal(result.msg, messages.shift()))
+  stream.flushSync = () => { throw new Error('Error') }
+  stream.flush = () => fail('flush should be called')
+
+  const instance = pino(stream)
+  doesNotThrow(() => instance.fatal(messages[0]))
+})
diff --git a/test/mixin.test.js b/test/mixin.test.js
new file mode 100644
index 0000000..49bcfa9
--- /dev/null
+++ b/test/mixin.test.js
@@ -0,0 +1,106 @@
+'use strict'
+
+const os = require('os')
+const { test } = require('tap')
+const { sink, once } = require('./helper')
+const pino = require('../')
+
+const { pid } = process
+const hostname = os.hostname()
+const level = 50
+const name = 'error'
+
+test('mixin object is included', async ({ ok, same }) => {
+  let n = 0
+  const stream = sink()
+  const instance = pino({
+    mixin () {
+      return { hello: ++n }
+    }
+  }, stream)
+  instance.level = name
+  instance[name]('test')
+  const result = await once(stream, 'data')
+  ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
+  delete result.time
+  same(result, {
+    pid,
+    hostname,
+    level,
+    msg: 'test',
+    hello: 1,
+    v: 1
+  })
+})
+
+test('mixin object is new every time', async ({ plan, ok, same }) => {
+  plan(6)
+
+  let n = 0
+  const stream = sink()
+  const instance = pino({
+    mixin () {
+      return { hello: n }
+    }
+  }, stream)
+  instance.level = name
+
+  while (++n < 4) {
+    const msg = `test #${n}`
+    stream.pause()
+    instance[name](msg)
+    stream.resume()
+    const result = await once(stream, 'data')
+    ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
+    delete result.time
+    same(result, {
+      pid,
+      hostname,
+      level,
+      msg,
+      hello: n,
+      v: 1
+    })
+  }
+})
+
+test('mixin object is not called if below log level', async ({ ok }) => {
+  const stream = sink()
+  const instance = pino({
+    mixin () {
+      ok(false, 'should not call mixin function')
+    }
+  }, stream)
+  instance.level = 'error'
+  instance.info('test')
+})
+
+test('mixin object + logged object', async ({ ok, same }) => {
+  let n = 0
+  const stream = sink()
+  const instance = pino({
+    mixin () {
+      return { hello: ++n }
+    }
+  }, stream)
+  instance.level = name
+  instance[name]({ foo: 42 })
+  const result = await once(stream, 'data')
+  ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
+  delete result.time
+  same(result, {
+    pid,
+    hostname,
+    level,
+    foo: 42,
+    hello: 1,
+    v: 1
+  })
+})
+
+test('mixin not a function', async ({ throws }) => {
+  const stream = sink()
+  throws(function () {
+    pino({ mixin: 'not a function' }, stream)
+  })
+})