Add tracing channels (#2281)

README.md

@@ -15,6 +15,7 @@
 * [Redaction ⇗](/docs/redaction.md)
 * [Child Loggers ⇗](/docs/child-loggers.md)
 * [Transports ⇗](/docs/transports.md)
+* [Diagnostics ⇗](/docs/diagnostics.md)
 * [Web Frameworks ⇗](/docs/web.md)
 * [Pretty Printing ⇗](/docs/pretty.md)
 * [Asynchronous Logging ⇗](/docs/asynchronous.md)

docs/diagnostics.md

@@ -0,0 +1,16 @@
+# Diagnostics
+
+Pino provides [tracing channel](tc) events that allow insight into the
+internal workings of the library. The currently supported events are:
+
++ `tracing:pino_asJson:start`: emitted when the final serialization process
+  of logs is started. The emitted event payload has the following fields:
+  - `instance`: the Pino instance associated with the function
+  - `arguments`: the arguments passed to the function
++ `tracing:pino_asJson:end`: emitted at the end of the final serialization
+  process. The emitted event payload has the following fields:
+  - `instance`: the Pino instance associated with the function
+  - `arguments`: the arguments passed to the function
+  - `result`: the finalized, newline delimited, log line as a string
+
+[tc]: https://nodejs.org/docs/latest/api/diagnostics_channel.html#tracingchannel-channels

lib/proto.js

@@ -66,6 +66,7 @@ const prototype = {
   get levelVal () { return this[levelValSym] },
   set levelVal (n) { throw Error('levelVal is read-only') },
   get msgPrefix () { return this[msgPrefixSym] },
+  get [Symbol.toStringTag] () { return 'Pino' },
   [lsCacheSym]: initialLsCache,
   [writeSym]: write,
   [asJsonSym]: asJson,

lib/tools.js

@@ -2,6 +2,7 @@
 
 /* eslint no-prototype-builtins: 0 */
 
+const diagChan = require('node:diagnostics_channel')
 const format = require('quick-format-unescaped')
 const { mapHttpRequest, mapHttpResponse } = require('pino-std-serializers')
 const SonicBoom = require('sonic-boom')
@@ -27,6 +28,8 @@ const {
 const { isMainThread } = require('worker_threads')
 const transport = require('./transport')
 
+const asJsonChan = diagChan.tracingChannel('pino_asJson')
+
 function noop () {
 }
 
@@ -103,7 +106,38 @@ function asString (str) {
   return point < 32 ? JSON.stringify(str) : '"' + result + '"'
 }
 
+/**
+ * `asJson` wraps `_asJson` in order to facilitate generating diagnostics.
+ *
+ * @param {object} obj The merging object passed to the log method.
+ * @param {string} msg The log message passed to the log method.
+ * @param {number} num The log level number.
+ * @param {number} time The log time in milliseconds.
+ *
+ * @returns {string}
+ */
 function asJson (obj, msg, num, time) {
+  if (asJsonChan.hasSubscribers === false) {
+    return _asJson.call(this, obj, msg, num, time)
+  }
+
+  const store = { instance: this, arguments }
+  return asJsonChan.traceSync(_asJson, store, this, obj, msg, num, time)
+}
+
+/**
+ * `_asJson` parses all collected data and generates the finalized newline
+ * delimited JSON string.
+ *
+ * @param {object} obj The merging object passed to the log method.
+ * @param {string} msg The log message passed to the log method.
+ * @param {number} num The log level number.
+ * @param {number} time The log time in milliseconds.
+ *
+ * @returns {string} The finalized log string terminated with a newline.
+ * @private
+ */
+function _asJson (obj, msg, num, time) {
   const stringify = this[stringifySym]
   const stringifySafe = this[stringifySafeSym]
   const stringifiers = this[stringifiersSym]

package.json

@@ -61,6 +61,7 @@
   "homepage": "https://getpino.io",
   "devDependencies": {
     "@arethetypeswrong/cli": "^0.18.1",
+    "@matteo.collina/tspl": "^0.2.0",
     "@types/flush-write-stream": "^1.0.0",
     "@types/node": "^24.0.8",
     "@types/tap": "^15.0.6",

test/diagnostics.test.js

@@ -0,0 +1,104 @@
+'use strict'
+
+const test = require('node:test')
+const os = require('node:os')
+const diagChan = require('node:diagnostics_channel')
+const { AsyncLocalStorage } = require('node:async_hooks')
+const { Writable } = require('node:stream')
+const tspl = require('@matteo.collina/tspl')
+const pino = require('../pino')
+
+const hostname = os.hostname()
+const { pid } = process
+const AS_JSON_START = 'tracing:pino_asJson:start'
+const AS_JSON_END = 'tracing:pino_asJson:end'
+
+test.beforeEach(ctx => {
+  ctx.pino = {
+    ts: 1757512800000, // 2025-09-10T10:00:00.000-05:00
+    now: Date.now
+  }
+
+  Date.now = () => ctx.pino.ts
+
+  ctx.pino.dest = new Writable({
+    objectMode: true,
+    write (data, enc, cb) {
+      cb()
+    }
+  })
+})
+
+test.afterEach(ctx => {
+  Date.now = ctx.pino.now
+})
+
+test('asJson emits events', async (t) => {
+  const plan = tspl(t, { plan: 8 })
+  const { dest } = t.pino
+  const logger = pino({}, dest)
+  const expectedArguments = [
+    {},
+    'testing',
+    30,
+    `,"time":${t.pino.ts}`
+  ]
+
+  let startEvent
+  diagChan.subscribe(AS_JSON_START, startHandler)
+  diagChan.subscribe(AS_JSON_END, endHandler)
+
+  logger.info('testing')
+  await plan
+
+  diagChan.unsubscribe(AS_JSON_START, startHandler)
+  diagChan.unsubscribe(AS_JSON_END, endHandler)
+
+  function startHandler (event) {
+    startEvent = event
+    plan.equal(Object.prototype.toString.call(event.instance), '[object Pino]')
+    plan.equal(event.instance === logger, true)
+    plan.deepStrictEqual(Array.from(event.arguments ?? []), expectedArguments)
+  }
+
+  function endHandler (event) {
+    plan.equal(Object.prototype.toString.call(event.instance), '[object Pino]')
+    plan.equal(event.instance === logger, true)
+    plan.deepStrictEqual(Array.from(event.arguments ?? []), expectedArguments)
+    plan.equal(
+      event.result,
+      `{"level":30,"time":${t.pino.ts},"pid":${pid},"hostname":"${hostname}","msg":"testing"}\n`
+    )
+
+    plan.equal(event.arguments === startEvent.arguments, true, 'same event object is supplied to both events')
+  }
+})
+
+test('asJson context is not lost', async (t) => {
+  const plan = tspl(t, { plan: 2 })
+  const { dest } = t.pino
+  const logger = pino({}, dest)
+  const asyncLocalStorage = new AsyncLocalStorage()
+  const localStore = { foo: 'bar' }
+
+  diagChan.subscribe(AS_JSON_START, startHandler)
+  diagChan.subscribe(AS_JSON_END, endHandler)
+
+  asyncLocalStorage.run(localStore, () => {
+    logger.info('testing')
+  })
+  await plan
+
+  diagChan.unsubscribe(AS_JSON_START, startHandler)
+  diagChan.unsubscribe(AS_JSON_END, endHandler)
+
+  function startHandler () {
+    const store = asyncLocalStorage.getStore()
+    plan.equal(store === localStore, true)
+  }
+
+  function endHandler () {
+    const store = asyncLocalStorage.getStore()
+    plan.equal(store === localStore, true)
+  }
+})

test/pkg/pkg.config.json

@@ -7,11 +7,10 @@
             "../../node_modules/pino-abstract-transport/index.js"
         ],
         "targets": [
-            "node14",
-            "node16",
             "node18",
-            "node20"
+            "node20",
+            "node22"
         ],
         "outputPath": "test/pkg"
     }
-}
+}