Repository: pinojs/pino
Pull request #1359 (2022-03-04 19:04:24)

Fix hasOwnProperty usage
Under certain circumstances, the user's mergingObject may be passed through as is to `write`. If the mergingObject was created with no prototype (`Object.create(null)`), then calling hasOwnProperty will fail.

Sample problematic code:

```js
const PinoMS = require('pino-multi-stream');
const pino = require('pino');
const logger = pino({}, pino.multistream([
  { stream: PinoMS.prettyStream({ prettyPrint: { colorize: true, translateTime: 'SYS:standard' } }) }
]));

const example = Object.create(null);
Object.assign(example, { hello: 'world' });
logger.info(example, 'hello world');
```

(This worked prior to Pino 7.8.0.)

For consistency, I also updated another usage of hasOwnProperty to match the new style.


Patch:
diff --git a/docs/api.md b/docs/api.md
index 1557094..e10d253 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -119,8 +119,8 @@ Option to limit stringification of properties/elements when logging a specific o
 Default: `undefined`
 
 If provided, the `mixin` function is called each time one of the active
-logging methods is called. The first and only parameter is the value `mergeObject` or an empty object. The function must synchronously return an
-object. The properties of the returned object will be added to the
+logging methods is called. The first parameter is the value `mergeObject` or an empty object. The second parameter is the leg level number.
+The function must synchronously return an object. The properties of the returned object will be added to the
 logged JSON.
 
 ```js
@@ -153,12 +153,28 @@ const logger = pino({
 logger.info({
     description: 'Ok'
 }, 'Message 1')
-// {"level":30,"time":1591195061437,"pid":16012,"hostname":"x","appName":"My app","description":"Ok" "msg":"Message 1"}
+// {"level":30,"time":1591195061437,"pid":16012,"hostname":"x","appName":"My app","description":"Ok","msg":"Message 1"}
 logger.info('Message 2')
 // {"level":30,"time":1591195061437,"pid":16012,"hostname":"x","appName":"My app","description":"Ok","msg":"Message 2"}
 // Note: the second log contains "description":"Ok" text, even if it was not provided.
 ```
 
+The `mixin` method can be used to add the level label to each log message such as in the following example:
+```js
+const logger = pino({
+  mixin(_context, level) {
+    return { 'level-label': logger.levels.labels[level] }
+  }
+})
+
+logger.info({
+    description: 'Ok'
+}, 'Message 1')
+// {"level":30,"time":1591195061437,"pid":16012,"hostname":"x","appName":"My app","description":"Ok","level-label":"info","msg":"Message 1"}
+logger.error('Message 2')
+// {"level":30,"time":1591195061437,"pid":16012,"hostname":"x","appName":"My app","description":"Ok","level-label":"error","msg":"Message 2"}
+```
+
 If the `mixin` feature is being used merely to add static metadata to each log message,
 then a [child logger ⇗](/docs/child-loggers.md) should be used instead.
 
@@ -293,6 +309,8 @@ Changes the shape of the log level. The default shape is `{ level: number }`.
 The function takes two arguments, the label of the level (e.g. `'info'`)
 and the numeric value (e.g. `30`).
 
+ps: The log level cannot be customized when using multiple transports
+
 ```js
 const formatters = {
   level (label, number) {
diff --git a/lib/proto.js b/lib/proto.js
index f51e5d7..abbeef8 100644
--- a/lib/proto.js
+++ b/lib/proto.js
@@ -192,7 +192,7 @@ function write (_obj, msg, num) {
   }
 
   if (mixin) {
-    obj = mixinMergeStrategy(obj, mixin(obj))
+    obj = mixinMergeStrategy(obj, mixin(obj, num))
   }
 
   const s = this[asJsonSym](obj, msg, num, t)
diff --git a/lib/tools.js b/lib/tools.js
index 97c5f21..70b8bcb 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -108,7 +108,6 @@ function asJson (obj, msg, num, time) {
   data = data + chindings
 
   let value
-  const notHasOwnProperty = obj.hasOwnProperty === undefined
   if (formatters.log) {
     obj = formatters.log(obj)
   }
@@ -116,7 +115,7 @@ function asJson (obj, msg, num, time) {
   let propStr = ''
   for (const key in obj) {
     value = obj[key]
-    if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
+    if (Object.prototype.hasOwnProperty.call(obj, key) && value !== undefined) {
       value = serializers[key] ? serializers[key](value) : value
 
       const stringifier = stringifiers[key] || wildcardStringifier
@@ -291,7 +290,7 @@ function prettifierMetaWrapper (pretty, dest, opts) {
       const formattedObj = formatters.log ? formatters.log(lastObj) : lastObj
 
       const messageKey = lastLogger[messageKeySym]
-      if (lastMsg && formattedObj && !formattedObj.hasOwnProperty(messageKey)) {
+      if (lastMsg && formattedObj && !Object.prototype.hasOwnProperty.call(formattedObj, messageKey)) {
         formattedObj[messageKey] = lastMsg
       }
 
@@ -409,6 +408,9 @@ function createArgsNormalizer (defaultOptions) {
       if (opts.transport instanceof SonicBoom || opts.transport.writable || opts.transport._writableState) {
         throw Error('option.transport do not allow stream, please pass to option directly. e.g. pino(transport)')
       }
+      if (opts.transport.targets && opts.transport.targets.length && opts.formatters && typeof opts.formatters.level === 'function') {
+        throw Error('option.transport.targets do not allow custom level formatters')
+      }
       stream = transport({ caller, ...opts.transport })
     }
     opts = Object.assign({}, defaultOptions, opts)
diff --git a/package.json b/package.json
index dd0e0a5..9e05014 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "pino",
-  "version": "7.8.0",
+  "version": "7.9.2",
   "description": "super fast, all natural json logger",
   "main": "pino.js",
   "type": "commonjs",
@@ -85,7 +85,7 @@
     "jest": "^27.3.1",
     "log": "^6.0.0",
     "loglevel": "^1.6.7",
-    "pino-pretty": "^v7.5.1",
+    "pino-pretty": "^v7.5.4",
     "pre-commit": "^1.2.2",
     "proxyquire": "^2.1.3",
     "pump": "^3.0.0",
@@ -93,7 +93,7 @@
     "split2": "^4.0.0",
     "steed": "^1.1.3",
     "strip-ansi": "^6.0.0",
-    "tap": "^15.0.1",
+    "tap": "^16.0.0",
     "tape": "^5.0.0",
     "through2": "^4.0.0",
     "ts-node": "^10.3.0",
@@ -111,7 +111,7 @@
     "real-require": "^0.1.0",
     "safe-stable-stringify": "^2.1.0",
     "sonic-boom": "^2.2.1",
-    "thread-stream": "^0.13.0"
+    "thread-stream": "^0.15.0"
   },
   "tsd": {
     "directory": "test/types"
diff --git a/pino.d.ts b/pino.d.ts
index b1be386..2f2431b 100644
--- a/pino.d.ts
+++ b/pino.d.ts
@@ -31,7 +31,7 @@ import type { WorkerOptions } from "worker_threads";
 type ThreadStream = any
 
 type TimeFn = () => string;
-type MixinFn = (mergeObject: object) => object;
+type MixinFn = (mergeObject: object, level: number) => object;
 type MixinMergeStrategyFn = (mergeObject: object, mixinObject: object) => object;
 
 type CustomLevelLogger<Options> = Options extends { customLevels: Record<string, number> } ? Record<keyof Options["customLevels"], LogFn> : Record<never, LogFn>


Test patch:
diff --git a/test/fixtures/eval/index.js b/test/fixtures/eval/index.js
index 89da034..1d45ad0 100644
--- a/test/fixtures/eval/index.js
+++ b/test/fixtures/eval/index.js
@@ -5,7 +5,7 @@ const pino = require('../../../')
 
 const logger = pino(
   pino.transport({
-    target: 'pino-pretty'
+    target: 'pino/file'
   })
 )
 
diff --git a/test/fixtures/eval/node_modules/file14.js b/test/fixtures/eval/node_modules/file14.js
index f2e994d..443ca7f 100644
--- a/test/fixtures/eval/node_modules/file14.js
+++ b/test/fixtures/eval/node_modules/file14.js
@@ -3,7 +3,7 @@ const pino = require("../../../../");
 module.exports = function() {
     const logger = pino(
         pino.transport({
-            target: 'pino-pretty'
+            target: 'pino/file'
         })
     )
 
diff --git a/test/fixtures/pretty/null-prototype.js b/test/fixtures/pretty/null-prototype.js
new file mode 100644
index 0000000..a74ca2c
--- /dev/null
+++ b/test/fixtures/pretty/null-prototype.js
@@ -0,0 +1,8 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+const pino = require(require.resolve('./../../../'))
+const log = pino({ prettyPrint: true })
+const obj = Object.create(null)
+Object.assign(obj, { foo: 'bar' })
+log.info(obj, 'hello')
diff --git a/test/formatters.test.js b/test/formatters.test.js
index 354a880..75d05cd 100644
--- a/test/formatters.test.js
+++ b/test/formatters.test.js
@@ -335,3 +335,30 @@ test('formatter with transport', async ({ match, equal }) => {
     nested: { object: true }
   })
 })
+
+test('throws when custom level formatter is used with transport.targets', async ({ throws }) => {
+  const destination = join(
+    os.tmpdir(),
+    '_' + Math.random().toString(36).substr(2, 9)
+  )
+
+  throws(() => {
+    pino({
+      formatters: {
+        level (label) {
+          return label
+        }
+      },
+      transport: {
+        targets: [
+          {
+            target: 'pino/file',
+            options: { destination }
+          }
+        ]
+      }
+    }
+    )
+  },
+  Error('option.transport.targets do not allow custom level formatters'))
+})
diff --git a/test/mixin.test.js b/test/mixin.test.js
index cac37e9..86b1622 100644
--- a/test/mixin.test.js
+++ b/test/mixin.test.js
@@ -140,3 +140,23 @@ test('mixin works without context', async ({ ok, same }) => {
   instance.level = name
   instance[name]('test')
 })
+
+test('mixin can use level number', async ({ ok, same }) => {
+  const stream = sink()
+  const instance = pino({
+    mixin (context, num) {
+      ok(num !== null, 'level should be defined')
+      ok(num !== undefined, 'level should be defined')
+      same(num, level)
+      return Object.assign({
+        error: context.message,
+        stack: context.stack
+      })
+    }
+  }, stream)
+  instance.level = name
+  instance[name]({
+    message: '123',
+    stack: 'stack'
+  }, 'test')
+})
diff --git a/test/multistream.test.js b/test/multistream.test.js
index 7073148..ff406e4 100644
--- a/test/multistream.test.js
+++ b/test/multistream.test.js
@@ -221,12 +221,17 @@ test('supports pretty print', function (t) {
     cb()
   })
 
-  const pretty = proxyquire('pino-pretty', {
+  const nested = proxyquire('pino-pretty/lib/utils', {
     'sonic-boom': function () {
       t.pass('sonic created')
+      stream.flushSync = () => {}
+      stream.flush = () => {}
       return stream
     }
   })
+  const pretty = proxyquire('pino-pretty', {
+    './lib/utils': nested
+  })
 
   const log = pino({
     level: 'debug',
diff --git a/test/pretty.test.js b/test/pretty.test.js
index 3fe30af..43e25a2 100644
--- a/test/pretty.test.js
+++ b/test/pretty.test.js
@@ -341,6 +341,18 @@ test('works as expected with an object with the msg prop', async ({ not }) => {
   not(strip(actual).match(/\(123456 on abcdefghijklmnopqr\): hello/), null)
 })
 
+test('handles objects with null prototypes', async ({ not }) => {
+  let actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'pretty', 'null-prototype.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  not(strip(actual).match(/\(123456 on abcdefghijklmnopqr\): hello\s+foo: "bar"/), null)
+})
+
 test('should not lose stream metadata for streams with `needsMetadataGsym` flag', async ({ not }) => {
   const dest = new Writable({
     objectMode: true,
diff --git a/test/transport/big.test.js b/test/transport/big.test.js
index 2c5490f..762c594 100644
--- a/test/transport/big.test.js
+++ b/test/transport/big.test.js
@@ -12,6 +12,7 @@ const stream = require('stream')
 
 const pipeline = promisify(stream.pipeline)
 const { Writable } = stream
+const sleep = promisify(setTimeout)
 
 test('eight million lines', async ({ equal, comment }) => {
   const destination = join(
@@ -21,6 +22,7 @@ test('eight million lines', async ({ equal, comment }) => {
   const child = execa(process.argv[0], [join(__dirname, '..', 'fixtures', 'transport-many-lines.js'), destination])
 
   await once(child, 'exit')
+  await sleep(1000) // wait for the file to be written
   const toWrite = 8 * 1000000
   let count = 0
   await pipeline(createReadStream(destination), split(), new Writable({
diff --git a/test/transport/caller.test.js b/test/transport/caller.test.js
index c264088..5c55a8a 100644
--- a/test/transport/caller.test.js
+++ b/test/transport/caller.test.js
@@ -1,53 +1,23 @@
 'use strict'
 
-const writer = require('flush-write-stream')
 const { join } = require('path')
 const { test } = require('tap')
 const execa = require('execa')
 
-const { once } = require('../helper')
-
 test('when using a custom transport outside node_modules, the first file outside node_modules should be used', async function (t) {
   const evalApp = join(__dirname, '../', '/fixtures/eval/index.js')
-  const child = execa(process.argv[0], [evalApp])
-
-  let actual = ''
-  child.stdout.pipe(writer((s, enc, cb) => {
-    actual += s
-    cb()
-  }))
-
-  await once(child, 'close')
-
-  t.match(actual, /done!/)
+  const { stdout } = await execa(process.argv[0], [evalApp])
+  t.match(stdout, /done!/)
 })
 
 test('when using a custom transport where some files in stacktrace are in the node_modules, the first file outside node_modules should be used', async function (t) {
   const evalApp = join(__dirname, '../', '/fixtures/eval/node_modules/2-files.js')
-  const child = execa(process.argv[0], [evalApp])
-
-  let actual = ''
-  child.stdout.pipe(writer((s, enc, cb) => {
-    actual += s
-    cb()
-  }))
-
-  await once(child, 'close')
-
-  t.match(actual, /done!/)
+  const { stdout } = await execa(process.argv[0], [evalApp])
+  t.match(stdout, /done!/)
 })
 
 test('when using a custom transport where all files in stacktrace are in the node_modules, the first file inside node_modules should be used', async function (t) {
   const evalApp = join(__dirname, '../', '/fixtures/eval/node_modules/14-files.js')
-  const child = execa(process.argv[0], [evalApp])
-
-  let actual = ''
-  child.stdout.pipe(writer((s, enc, cb) => {
-    actual += s
-    cb()
-  }))
-
-  await once(child, 'close')
-
-  t.match(actual, /done!/)
+  const { stdout } = await execa(process.argv[0], [evalApp])
+  t.match(stdout, /done!/)
 })
diff --git a/test/types/pino.test-d.ts b/test/types/pino.test-d.ts
index a808903..87e319b 100644
--- a/test/types/pino.test-d.ts
+++ b/test/types/pino.test-d.ts
@@ -47,6 +47,14 @@ pino({
     mixin: () => ({ customName: "unknown", customId: 111 }),
 });
 
+pino({
+    mixin: (context: object) => ({ customName: "unknown", customId: 111 }),
+});
+
+pino({
+    mixin: (context: object, level: number) => ({ customName: "unknown", customId: 111 }),
+});
+
 pino({
     redact: { paths: [], censor: "SECRET" },
 });