Repository: pinojs/pino
Pull request #1635 (2023-01-31 01:17:57)

Allow message prefix - #544
Allowing message prefix

fixing:
- #544

This PR contains:

- [x] Fix
- [x] Tests
- [x] Updated docs

rluvaton: Could someone please approve running the workflows so I can see the performance change :) 
rluvaton: Could someone please stop this job:
https://github.com/pinojs/pino/actions/runs/4049806965/jobs/6977390174
rluvaton: @Fdawgs Could you please me out and allow running the workflows 😬
Fdawgs: Have reran it @rluvaton
mcollina: The benchmarks looks ok to me. Could you add some tests for the fix you are making?
rluvaton: yeah sure, to make sure this fix is ok for you, I'll try to add it + docs later this day 
rluvaton: This PR is now ready for review @jsumners 
rluvaton: let's merge it?
mcollina: let's wait for @jsumners 
rluvaton: I think the failed test is flaky, had it before... in the CI but couldn't reproduce on ubuntu, would love a rerun
jsumners: I don't see any errors with the CI run. But the benchmarks may not be acceptable. @mcollina can you run them on your dedicated system?
rluvaton: They changed a lot between:
504d1f1bdc60ba492245d6553a160cd84ed4e9db

to

f8067843fdc2b11bfcd3ad6576ae8c88d94425a1

and I only changed this:
[`a94a9da` (#1635)](https://github.com/pinojs/pino/pull/1635/commits/a94a9da3166672d2857650c7d2dc0f1d4153f12f#diff-7f88797c7db38a6af7a3283e3af30f2cdd3c2489bd9c85a7a25b32ec2485f724R56-R62)
jsumners: > They changed a lot between: [504d1f1](https://github.com/pinojs/pino/commit/504d1f1bdc60ba492245d6553a160cd84ed4e9db)
> 
> to
> 
> [f806784](https://github.com/pinojs/pino/commit/f8067843fdc2b11bfcd3ad6576ae8c88d94425a1)
> 
> and I only changed this: [`a94a9da` (#1635)](https://github.com/pinojs/pino/pull/1635/commits/a94a9da3166672d2857650c7d2dc0f1d4153f12f#diff-7f88797c7db38a6af7a3283e3af30f2cdd3c2489bd9c85a7a25b32ec2485f724R56-R62)

Then the coercive check may not be acceptable. Revert the change and add a note like:

```js
// We do not use a coercive check for `msg` as it is
// measurably slower than the explicit checks.
```
rluvaton: Reverted but it doesn't make any sense, this check has never met as we don't run benchmarks with log-prefix
rluvaton: it's ready for merge :)
rluvaton: @jsumners can this be merged?

Patch:
diff --git a/docs/api.md b/docs/api.md
index cfd1ca7..cc8f0cb 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -384,6 +384,24 @@ See `errorKey` option to change `err` namespace.
 
 * See [pino.stdSerializers](#pino-stdserializers)
 
+#### `msgPrefix` (String)
+
+Default: `undefined`
+
+The `msgPrefix` property allows you to specify a prefix for every message of the logger and its children.
+
+```js
+const logger = pino({
+  msgPrefix: '[HTTP] '
+})
+logger.info('got new request!')
+// >  [HTTP] got new request!
+
+const child = logger.child({})
+child.info('User authenticated!')
+// >  [HTTP] User authenticated!
+```
+
 #### `base` (Object)
 
 Default: `{pid: process.pid, hostname: os.hostname}`
@@ -842,6 +860,26 @@ const child = logger.child({foo: 'bar'}, {level: 'debug'})
 child.debug('debug!') // will log as the `level` property set the level to debug
 ```
 
+##### `options.msgPrefix` (String)
+
+Default: `undefined`
+
+The `msgPrefix` property allows you to specify a prefix for every message of the child logger.
+By default, the parent prefix is inherited.
+If the parent already has a prefix, the prefix of the parent and then the child will be displayed.
+
+```js
+const logger = pino({
+  msgPrefix: '[HTTP] '
+})
+logger.info('got new request!')
+// >  [HTTP] got new request!
+
+const child = logger.child({avengers: 'assemble'}, {msgPrefix: '[Proxy] '})
+child.info('message proxied!')
+// >  [HTTP] [Proxy] message proxied!
+```
+
 ##### `options.redact` (Array | Object)
 
 Setting `options.redact` to an array or object will override the parent `redact` options. To remove `redact` options inherited from the parent logger set this value as an empty array (`[]`).
diff --git a/lib/proto.js b/lib/proto.js
index 4009452..026d644 100644
--- a/lib/proto.js
+++ b/lib/proto.js
@@ -25,7 +25,8 @@ const {
   redactFmtSym,
   stringifySym,
   formatOptsSym,
-  stringifiersSym
+  stringifiersSym,
+  msgPrefixSym
 } = require('./symbols')
 const {
   getLevel,
@@ -138,6 +139,10 @@ function child (bindings, options) {
     instance[formatOptsSym] = formatOpts
   }
 
+  if (typeof options.msgPrefix === 'string') {
+    instance[msgPrefixSym] = (this[msgPrefixSym] || '') + options.msgPrefix
+  }
+
   instance[chindingsSym] = asChindings(instance, bindings)
   const childLevel = options.level || this.level
   instance[setLevelSym](childLevel)
diff --git a/lib/symbols.js b/lib/symbols.js
index 2a0228e..08c0e88 100644
--- a/lib/symbols.js
+++ b/lib/symbols.js
@@ -27,6 +27,7 @@ const errorKeySym = Symbol('pino.errorKey')
 const nestedKeySym = Symbol('pino.nestedKey')
 const nestedKeyStrSym = Symbol('pino.nestedKeyStr')
 const mixinMergeStrategySym = Symbol('pino.mixinMergeStrategy')
+const msgPrefixSym = Symbol('pino.msgPrefix')
 
 const wildcardFirstSym = Symbol('pino.wildcardFirst')
 
@@ -66,5 +67,6 @@ module.exports = {
   formattersSym,
   hooksSym,
   nestedKeyStrSym,
-  mixinMergeStrategySym
+  mixinMergeStrategySym,
+  msgPrefixSym
 }
diff --git a/lib/tools.js b/lib/tools.js
index e16c0c7..92bd23b 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -21,12 +21,14 @@ const {
   formattersSym,
   messageKeySym,
   errorKeySym,
-  nestedKeyStrSym
+  nestedKeyStrSym,
+  msgPrefixSym
 } = require('./symbols')
 const { isMainThread } = require('worker_threads')
 const transport = require('./transport')
 
-function noop () {}
+function noop () {
+}
 
 function genLog (level, hook) {
   if (!hook) return LOG
@@ -52,9 +54,21 @@ function genLog (level, hook) {
         msg = n.shift()
         formatParams = n
       }
+      // We do not use a coercive check for `msg` as it is
+      // measurably slower than the explicit checks.
+      if (typeof this[msgPrefixSym] === 'string' && msg !== undefined && msg !== null) {
+        msg = this[msgPrefixSym] + msg
+      }
       this[writeSym](o, format(msg, formatParams, this[formatOptsSym]), level)
     } else {
-      this[writeSym](null, format(o === undefined ? n.shift() : o, n, this[formatOptsSym]), level)
+      let msg = o === undefined ? n.shift() : o
+
+      // We do not use a coercive check for `msg` as it is
+      // measurably slower than the explicit checks.
+      if (typeof this[msgPrefixSym] === 'string' && msg !== undefined && msg !== null) {
+        msg = this[msgPrefixSym] + msg
+      }
+      this[writeSym](null, format(msg, n, this[formatOptsSym]), level)
     }
   }
 }
diff --git a/pino.d.ts b/pino.d.ts
index 8ac3ec4..7382ae9 100644
--- a/pino.d.ts
+++ b/pino.d.ts
@@ -588,6 +588,11 @@ declare namespace pino {
             log?: (object: Record<string, unknown>) => Record<string, unknown>;
         };
 
+        /**
+         * A string that would be prefixed to every message (and child message)
+         */
+        msgPrefix?: string
+
         /**
          * An object mapping to hook functions. Hook functions allow for customizing internal logger operations.
          * Hook functions must be synchronous functions.
@@ -628,6 +633,7 @@ declare namespace pino {
             log?: (object: object) => object;
         };
         redact?: string[] | redactOptions;
+        msgPrefix?: string
     }
 
     /**
diff --git a/pino.js b/pino.js
index c16a745..63500e4 100644
--- a/pino.js
+++ b/pino.js
@@ -40,7 +40,8 @@ const {
   formattersSym,
   hooksSym,
   nestedKeyStrSym,
-  mixinMergeStrategySym
+  mixinMergeStrategySym,
+  msgPrefixSym
 } = symbols
 const { epochTime, nullTime } = time
 const { pid } = process
@@ -103,7 +104,8 @@ function pino (...args) {
     hooks,
     depthLimit,
     edgeLimit,
-    onChild
+    onChild,
+    msgPrefix
   } = opts
 
   const stringifySafe = configure({
@@ -150,6 +152,7 @@ function pino (...args) {
 
   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"`)
+  if (msgPrefix && typeof msgPrefix !== 'string') throw Error(`Unknown msgPrefix type "${typeof msgPrefix}" - expected "string"`)
 
   assertDefaultLevelFound(level, customLevels, useOnlyCustomLevels)
   const levels = mappings(customLevels, useOnlyCustomLevels)
@@ -177,7 +180,8 @@ function pino (...args) {
     [formattersSym]: allFormatters,
     [hooksSym]: hooks,
     silent: noop,
-    onChild
+    onChild,
+    [msgPrefixSym]: msgPrefix
   })
 
   Object.setPrototypeOf(instance, proto())


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index e8310d6..c8a6962 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -751,3 +751,74 @@ test('Should invoke `onChild` with the newly created child', async ({ equal }) =
   }).child({ foo: 'bar' })
   equal(child, innerChild)
 })
+
+test('logger message should have the prefix message that defined in the logger creation', async ({ equal }) => {
+  const stream = sink()
+  const logger = pino({
+    msgPrefix: 'My name is Bond '
+  }, stream)
+  logger.info('James Bond')
+  const { msg } = await once(stream, 'data')
+  equal(msg, 'My name is Bond James Bond')
+})
+
+test('child message should have the prefix message that defined in the child creation', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino(stream)
+  const child = instance.child({}, { msgPrefix: 'My name is Bond ' })
+  child.info('James Bond')
+  const { msg } = await once(stream, 'data')
+  equal(msg, 'My name is Bond James Bond')
+})
+
+test('child message should have the prefix message that defined in the child creation when logging with log meta', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino(stream)
+  const child = instance.child({}, { msgPrefix: 'My name is Bond ' })
+  child.info({ hello: 'world' }, 'James Bond')
+  const { msg, hello } = await once(stream, 'data')
+  equal(hello, 'world')
+  equal(msg, 'My name is Bond James Bond')
+})
+
+test('logged message should not have the prefix when not providing any message', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino(stream)
+  const child = instance.child({}, { msgPrefix: 'This should not be shown ' })
+  child.info({ hello: 'world' })
+  const { msg, hello } = await once(stream, 'data')
+  equal(hello, 'world')
+  equal(msg, undefined)
+})
+
+test('child message should append parent prefix to current prefix that defined in the child creation', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino({
+    msgPrefix: 'My name is Bond '
+  }, stream)
+  const child = instance.child({}, { msgPrefix: 'James ' })
+  child.info('Bond')
+  const { msg } = await once(stream, 'data')
+  equal(msg, 'My name is Bond James Bond')
+})
+
+test('child message should inherent parent prefix', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino({
+    msgPrefix: 'My name is Bond '
+  }, stream)
+  const child = instance.child({})
+  child.info('James Bond')
+  const { msg } = await once(stream, 'data')
+  equal(msg, 'My name is Bond James Bond')
+})
+
+test('grandchild message should inherent parent prefix', async ({ equal }) => {
+  const stream = sink()
+  const instance = pino(stream)
+  const child = instance.child({}, { msgPrefix: 'My name is Bond ' })
+  const grandchild = child.child({})
+  grandchild.info('James Bond')
+  const { msg } = await once(stream, 'data')
+  equal(msg, 'My name is Bond James Bond')
+})