Repository: pinojs/pino
Pull request #2051 (2024-09-26 22:34:57)

Add asObjectBindingsOnly, allowing write to receive only the bindings as object
This allows to pass the format string and args as
is the underlying console when to keep their
special handling, for when using `write` to only
modify the default way the printing to the console
looks rather than writing to an alternate
destination entirely.

The name of the option and its behavior is obviously open for discussion

Part of #1556


Patch:
diff --git a/.github/dependabot.yml b/.github/dependabot.yml
index dfa7fa6..35d66ca 100644
--- a/.github/dependabot.yml
+++ b/.github/dependabot.yml
@@ -9,5 +9,5 @@ updates:
   - package-ecosystem: "npm"
     directory: "/"
     schedule:
-      interval: "weekly"
+      interval: "monthly"
     open-pull-requests-limit: 10
diff --git a/browser.js b/browser.js
index 7d0aa2b..bfdb8ea 100644
--- a/browser.js
+++ b/browser.js
@@ -109,6 +109,7 @@ function pino (opts) {
     transmit,
     serialize,
     asObject: opts.browser.asObject,
+    asObjectBindingsOnly: opts.browser.asObjectBindingsOnly,
     formatters: opts.browser.formatters,
     levels,
     timestamp: getTimeFunction(opts),
@@ -118,6 +119,13 @@ function pino (opts) {
   logger.levels = getLevels(opts)
   logger.level = level
 
+  logger.isLevelEnabled = function (level) {
+    if (!this.levels.values[level]) {
+      return false
+    }
+
+    return this.levels.values[level] >= this.levels.values[this.level]
+  }
   logger.setMaxListeners = logger.getMaxListeners =
   logger.emit = logger.addListener = logger.on =
   logger.prependListener = logger.once =
@@ -317,7 +325,7 @@ function createWrap (self, opts, rootLogger, level) {
         argsIsSerialized = true
       }
       if (opts.asObject || opts.formatters) {
-        write.call(proto, asObject(this, level, args, ts, opts))
+        write.call(proto, ...asObject(this, level, args, ts, opts))
       } else write.apply(proto, args)
 
       if (opts.transmit) {
@@ -347,6 +355,10 @@ function asObject (logger, level, args, ts, opts) {
   const argsCloned = args.slice()
   let msg = argsCloned[0]
   const logObject = {}
+
+  let lvl = (logger._childLevel | 0) + 1
+  if (lvl < 1) lvl = 1
+
   if (ts) {
     logObject.time = ts
   }
@@ -358,19 +370,28 @@ function asObject (logger, level, args, ts, opts) {
     logObject.level = logger.levels.values[level]
   }
 
-  let lvl = (logger._childLevel | 0) + 1
-  if (lvl < 1) lvl = 1
-  // deliberate, catching objects, arrays
-  if (msg !== null && typeof msg === 'object') {
-    while (lvl-- && typeof argsCloned[0] === 'object') {
-      Object.assign(logObject, argsCloned.shift())
+  if (opts.asObjectBindingsOnly) {
+    if (msg !== null && typeof msg === 'object') {
+      while (lvl-- && typeof argsCloned[0] === 'object') {
+        Object.assign(logObject, argsCloned.shift())
+      }
     }
-    msg = argsCloned.length ? format(argsCloned.shift(), argsCloned) : undefined
-  } else if (typeof msg === 'string') msg = format(argsCloned.shift(), argsCloned)
-  if (msg !== undefined) logObject[opts.messageKey] = msg
 
-  const formattedLogObject = logObjectFormatter(logObject)
-  return formattedLogObject
+    const formattedLogObject = logObjectFormatter(logObject)
+    return [formattedLogObject, ...argsCloned]
+  } else {
+    // deliberate, catching objects, arrays
+    if (msg !== null && typeof msg === 'object') {
+      while (lvl-- && typeof argsCloned[0] === 'object') {
+        Object.assign(logObject, argsCloned.shift())
+      }
+      msg = argsCloned.length ? format(argsCloned.shift(), argsCloned) : undefined
+    } else if (typeof msg === 'string') msg = format(argsCloned.shift(), argsCloned)
+    if (msg !== undefined) logObject[opts.messageKey] = msg
+
+    const formattedLogObject = logObjectFormatter(logObject)
+    return [formattedLogObject]
+  }
 }
 
 function applySerializers (args, serialize, serializers, stdErrSerialize) {
diff --git a/docs/api.md b/docs/api.md
index c68ba5c..6789e3f 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -484,7 +484,7 @@ child.info('User authenticated!')
 <a id=opt-base></a>
 #### `base` (Object)
 
-Default: `{pid: process.pid, hostname: os.hostname}`
+Default: `{pid: process.pid, hostname: os.hostname()}`
 
 Key-value object added as child logger to each log line.
 
@@ -1307,6 +1307,9 @@ module.exports = function build () {
 }
 ```
 
+Note that _any `'error'`_ event emitted by the transport must be considered a fatal error and the process must be terminated.
+Error events are not recoverable.
+
 For more on transports, how they work, and how to create them see the [`Transports documentation`](/docs/transports.md).
 
 * See [`Transports`](/docs/transports.md)
diff --git a/docs/browser.md b/docs/browser.md
index a23ce83..9578e0c 100644
--- a/docs/browser.md
+++ b/docs/browser.md
@@ -27,6 +27,21 @@ pino.info('hi') // creates and logs {msg: 'hi', level: 30, time: <ts>}
 
 When `write` is set, `asObject` will always be `true`.
 
+### `asObjectBindingsOnly` (Boolean)
+
+```js
+const pino = require('pino')({browser: {asObjectBindingsOnly: true}})
+```
+
+The `asObjectBindingsOnly` is similar to `asObject` but will keep the message
+and arguments unformatted, this allows to defer formatting the message to the
+actual call to `console` methods, where browsers then have richer formatting in
+their devtools then when pino will format the message to a string first.
+
+```js
+pino.info('hello %s', 'world') // creates and logs {level: 30, time: <ts>}, 'hello %s', 'world'
+```
+
 ### `formatters` (Object)
 
 An object containing functions for formatting the shape of the log lines. When provided, it enables the logger to produce a pino-like log object with customized formatting. Currently, it supports formatting for the `level` object only.
diff --git a/docs/web.md b/docs/web.md
index 49a31d0..4b7bcd4 100644
--- a/docs/web.md
+++ b/docs/web.md
@@ -12,6 +12,7 @@ web framework ecosystem.
   - [Pino with Node core `http`](#pino-with-node-core-http)
   - [Pino with Nest](#pino-with-nest)
   - [Pino with H3](#pino-with-h3)
+  - [Pino with Hono](#pino-with-hono)
 
 <a id="fastify"></a>
 ## Pino with Fastify
@@ -267,3 +268,49 @@ router.get(
 Execute `npx --yes listhen -w --open ./server.mjs`.
 
 See the [pino-http README](https://npm.im/pino-http) for more info.
+
+
+<a id="h3"></a>
+## Pino with Hono
+
+```sh
+npm install pino pino-http hono
+```
+
+```ts
+import { HttpBindings, serve } from '@hono/node-server';
+import { Hono } from 'hono';
+import { requestId } from 'hono/request-id';
+import { pino } from 'pino';
+import { pinoHttp } from 'pino-http';
+
+declare module 'hono' {
+  interface ContextVariableMap {
+    logger: pino.Logger;
+  }
+}
+
+const app = new Hono<{ Bindings: HttpBindings }>();
+app.use(requestId());
+app.use(async (c, next) => {
+  // pass hono's request-id to pino-http
+  c.env.incoming.id = c.var.requestId;
+
+  // map express style middleware to hono
+  await new Promise<void>((resolve) => pinoHttp()(c.env.incoming, c.env.outgoing, () => resolve()));
+
+  c.set('logger', c.env.incoming.log);
+
+  await next();
+});
+
+app.get('/', (c) => {
+  c.var.logger.info('something');
+
+  return c.text('Hello Node.js!');
+});
+
+serve(app);
+```
+
+See the [pino-http README](https://npm.im/pino-http) for more info.
diff --git a/package.json b/package.json
index b844168..5649fb5 100644
--- a/package.json
+++ b/package.json
@@ -63,7 +63,7 @@
     "@types/flush-write-stream": "^1.0.0",
     "@types/node": "^22.0.0",
     "@types/tap": "^15.0.6",
-    "@yao-pkg/pkg": "6.1.1",
+    "@yao-pkg/pkg": "6.3.0",
     "airtap": "5.0.0",
     "benchmark": "^2.1.4",
     "bole": "^5.0.5",
@@ -98,7 +98,7 @@
     "through2": "^4.0.0",
     "ts-node": "^10.9.1",
     "tsd": "^0.31.0",
-    "typescript": "~5.7.2",
+    "typescript": "~5.8.2",
     "winston": "^3.7.2"
   },
   "dependencies": {
@@ -107,7 +107,7 @@
     "on-exit-leak-free": "^2.1.0",
     "pino-abstract-transport": "^2.0.0",
     "pino-std-serializers": "^7.0.0",
-    "process-warning": "^4.0.0",
+    "process-warning": "^5.0.0",
     "quick-format-unescaped": "^4.0.3",
     "real-require": "^0.2.0",
     "safe-stable-stringify": "^2.3.1",


Test patch:
diff --git a/test/browser-is-level-enabled.test.js b/test/browser-is-level-enabled.test.js
new file mode 100644
index 0000000..16d8c88
--- /dev/null
+++ b/test/browser-is-level-enabled.test.js
@@ -0,0 +1,104 @@
+'use strict'
+
+const { test } = require('tap')
+const pino = require('../browser')
+
+const customLevels = {
+  trace: 10,
+  debug: 20,
+  info: 30,
+  warn: 40,
+  error: 50,
+  fatal: 60
+}
+
+test('Default levels suite', ({ test, end }) => {
+  test('can check if current level enabled', async ({ equal }) => {
+    const log = pino({ level: 'debug' })
+    equal(true, log.isLevelEnabled('debug'))
+  })
+
+  test('can check if current level enabled when as object', async ({ equal }) => {
+    const log = pino({ asObject: true, level: 'debug' })
+    equal(true, log.isLevelEnabled('debug'))
+  })
+
+  test('can check if level enabled after level set', async ({ equal }) => {
+    const log = pino()
+    equal(false, log.isLevelEnabled('debug'))
+    log.level = 'debug'
+    equal(true, log.isLevelEnabled('debug'))
+  })
+
+  test('can check if higher level enabled', async ({ equal }) => {
+    const log = pino({ level: 'debug' })
+    equal(true, log.isLevelEnabled('error'))
+  })
+
+  test('can check if lower level is disabled', async ({ equal }) => {
+    const log = pino({ level: 'error' })
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  test('ASC: can check if child has current level enabled', async ({ equal }) => {
+    const log = pino().child({}, { level: 'debug' })
+    equal(true, log.isLevelEnabled('debug'))
+    equal(true, log.isLevelEnabled('error'))
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  test('can check if custom level is enabled', async ({ equal }) => {
+    const log = pino({
+      customLevels: { foo: 35 },
+      level: 'debug'
+    })
+    equal(true, log.isLevelEnabled('foo'))
+    equal(true, log.isLevelEnabled('error'))
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  end()
+})
+
+test('Custom levels suite', ({ test, end }) => {
+  test('can check if current level enabled', async ({ equal }) => {
+    const log = pino({ level: 'debug', customLevels })
+    equal(true, log.isLevelEnabled('debug'))
+  })
+
+  test('can check if level enabled after level set', async ({ equal }) => {
+    const log = pino({ customLevels })
+    equal(false, log.isLevelEnabled('debug'))
+    log.level = 'debug'
+    equal(true, log.isLevelEnabled('debug'))
+  })
+
+  test('can check if higher level enabled', async ({ equal }) => {
+    const log = pino({ level: 'debug', customLevels })
+    equal(true, log.isLevelEnabled('error'))
+  })
+
+  test('can check if lower level is disabled', async ({ equal }) => {
+    const log = pino({ level: 'error', customLevels })
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  test('can check if child has current level enabled', async ({ equal }) => {
+    const log = pino().child({ customLevels }, { level: 'debug' })
+    equal(true, log.isLevelEnabled('debug'))
+    equal(true, log.isLevelEnabled('error'))
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  test('can check if custom level is enabled', async ({ equal }) => {
+    const log = pino({
+      customLevels: { foo: 35, ...customLevels },
+      level: 'debug'
+    })
+    equal(true, log.isLevelEnabled('foo'))
+    equal(true, log.isLevelEnabled('error'))
+    equal(false, log.isLevelEnabled('trace'))
+  })
+
+  end()
+})
diff --git a/test/browser.test.js b/test/browser.test.js
index 8684006..0712e48 100644
--- a/test/browser.test.js
+++ b/test/browser.test.js
@@ -165,6 +165,7 @@ test('opts.browser.asObject logs pino-like object to console', ({ end, ok, is })
   instance.info('test')
   end()
 })
+
 test('opts.browser.asObject uses opts.messageKey in logs', ({ end, ok, is }) => {
   const messageKey = 'message'
   const instance = require('../browser')({
@@ -183,6 +184,25 @@ test('opts.browser.asObject uses opts.messageKey in logs', ({ end, ok, is }) =>
   end()
 })
 
+test('opts.browser.asObjectBindingsOnly passes the bindings but keep the message unformatted', ({ end, ok, is, deepEqual }) => {
+  const messageKey = 'message'
+  const instance = require('../browser')({
+    messageKey,
+    browser: {
+      asObjectBindingsOnly: true,
+      write: function (o, msg, ...args) {
+        is(o.level, 30)
+        ok(o.time)
+        is(msg, 'test %s')
+        deepEqual(args, ['foo'])
+      }
+    }
+  })
+
+  instance.info('test %s', 'foo')
+  end()
+})
+
 test('opts.browser.formatters (level) logs pino-like object to console', ({ end, ok, is }) => {
   const info = console.info
   console.info = function (o) {
diff --git a/test/fixtures/crashing-transport.js b/test/fixtures/crashing-transport.js
new file mode 100644
index 0000000..1f3d46e
--- /dev/null
+++ b/test/fixtures/crashing-transport.js
@@ -0,0 +1,13 @@
+const { Writable } = require('node:stream')
+
+module.exports = () =>
+  new Writable({
+    autoDestroy: true,
+    write (chunk, enc, cb) {
+      setImmediate(() => {
+        /* eslint-disable no-empty */
+        for (let i = 0; i < 1e3; i++) {}
+        process.exit(0)
+      })
+    }
+  })
diff --git a/test/pkg/pkg.test.js b/test/pkg/pkg.test.js
index a74b033..3cb28ad 100644
--- a/test/pkg/pkg.test.js
+++ b/test/pkg/pkg.test.js
@@ -8,6 +8,8 @@ const { join } = require('node:path')
 const { platform } = require('node:process')
 const execFile = promisify(require('node:child_process').execFile)
 
+const skip = process.env.PNPM_CI || process.env.CITGM || process.arch === 'ppc64'
+
 /**
  * The following regex is for tesintg the deprecation warning that is thrown by the `punycode` module.
  * Exact text that it's matching is:
@@ -18,7 +20,7 @@ const execFile = promisify(require('node:child_process').execFile)
  */
 const deprecationWarningRegex = /^\(\w+:\d+\)\s\[[\w|\d]+\]\sDeprecationWarning: The `punycode` module is deprecated\.\s+Please use a userland alternative instead\.\s+\(Use `node --trace-deprecation \.\.\.` to show where the warning was created\)\s+$/
 
-test('worker test when packaged into executable using pkg', { skip: !!process.env.PNPM_CI }, async (t) => {
+test('worker test when packaged into executable using pkg', { skip }, async (t) => {
   const packageName = 'index'
 
   // package the app into several node versions, check config for more info
diff --git a/test/transport/core.test.js b/test/transport/core.test.js
index 44449db..3bd55fe 100644
--- a/test/transport/core.test.js
+++ b/test/transport/core.test.js
@@ -3,6 +3,7 @@
 const os = require('node:os')
 const { join } = require('node:path')
 const { once } = require('node:events')
+const { setImmediate: immediate } = require('node:timers/promises')
 const { readFile, writeFile } = require('node:fs').promises
 const { watchFileCreated, watchForWrite, file } = require('../helper')
 const { test } = require('tap')
@@ -12,10 +13,8 @@ const strip = require('strip-ansi')
 const execa = require('execa')
 const writer = require('flush-write-stream')
 const rimraf = require('rimraf')
-const { promisify } = require('node:util')
 const { tmpdir } = os
 
-const immediate = promisify(setImmediate)
 const pid = process.pid
 const hostname = os.hostname()
 
diff --git a/test/transport/crash.test.js b/test/transport/crash.test.js
new file mode 100644
index 0000000..b5e31fe
--- /dev/null
+++ b/test/transport/crash.test.js
@@ -0,0 +1,34 @@
+'use strict'
+
+const { join } = require('node:path')
+const { once } = require('node:events')
+const { setImmediate: immediate } = require('node:timers/promises')
+const { test } = require('tap')
+const pino = require('../../')
+
+test('pino.transport emits error if the worker exits with 0 unexpectably', async ({ same, teardown, equal }) => {
+  // This test will take 10s, because flushSync waits for 10s
+  const transport = pino.transport({
+    target: join(__dirname, '..', 'fixtures', 'crashing-transport.js'),
+    sync: true
+  })
+  teardown(transport.end.bind(transport))
+
+  await once(transport, 'ready')
+
+  let maybeError
+  transport.on('error', (err) => {
+    maybeError = err
+  })
+
+  const logger = pino(transport)
+  for (let i = 0; i < 100000; i++) {
+    logger.info('hello')
+  }
+
+  await once(transport.worker, 'exit')
+
+  await immediate()
+
+  same(maybeError.message, 'the worker has exited')
+})