diff --git a/README.md b/README.md index 82f2e783f..b8d1491ea 100644 --- a/README.md +++ b/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) diff --git a/docs/diagnostics.md b/docs/diagnostics.md new file mode 100644 index 000000000..c4c370d07 --- /dev/null +++ b/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 diff --git a/lib/proto.js b/lib/proto.js index 9f074a919..f878813ae 100644 --- a/lib/proto.js +++ b/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, diff --git a/lib/tools.js b/lib/tools.js index b8b79d5e1..5cd5825a4 100644 --- a/lib/tools.js +++ b/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] diff --git a/package.json b/package.json index 22302371b..090262888 100644 --- a/package.json +++ b/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", diff --git a/test/diagnostics.test.js b/test/diagnostics.test.js new file mode 100644 index 000000000..143892011 --- /dev/null +++ b/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) + } +}) diff --git a/test/pkg/pkg.config.json b/test/pkg/pkg.config.json index a7d2b990c..d73c66f57 100644 --- a/test/pkg/pkg.config.json +++ b/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" } -} \ No newline at end of file +}