Repository: pinojs/pino
Pull request #1725 (2023-06-02 20:12:19)

fix: browser respect child logger log level 
This PR addresses #960.

> not yet completed, only a draft

# Goal of this PR:

Child level determines which logs of the child are logged.

# Implementation before this PR

- the `prototype` of `logger` contains the actual log functions which should be used
- the `prototype` log functions are assigned to the `logger` whenever the `setLevel` function is called
- for log functions which level  is to low, `noop` is assigned instead

> problem: only the main `logger` actually changes, even if the level of a child is changed

# What this PR changes

- introduce a property which contains all the base logger functions (only the root logger has it) -> `Symbol('pino.logFuncs')`
  - the base log functions need to be callable independently by the child loggers and this property allows to access them all the time
- introduce a property which contains the hierarchy of the logger (pointing to the parent) -> `Symbol('pino.hierarchy')`
  - whenever a child logs, it needs all bindings as they are prepend to the log arguments.
    before this PR, it was handled via the prototype chain.
- move the responsibility of prepending the bindings into the `set` functions (for changing the log level)
  - as the `set` function is mainly responsible for defining the actual log functions that are usable, it felt like a logical step to also include the binding in it. 
- add a `bindings` property to each child that stores the bindings of the child.
  - this is needed to walk up the hierarchy, get all bindings and then use it to prepend the log arguments.
  - there are restrictions to this property: it is only considered once, when calling the `set` function. 
    so, reassigning it only takes affect if the `level` is changed and then it *only* is updated for this one logger.

# Insights I want to share

There is a specific order in which a log is processed:

1. the outer log function is called with whatever should be logged
2. the bindings are prepended to the arguments
3. the `LOG` function is used to transform the arguments to the desired structure (can be found in `createWrap`)
4. the actual logging function is called with the transformed arguments

Before this PR, the prototype chain was used the ensure that the bindings are prepended one after another.
Now they are collected once and then prepended at once.

Another improvement that comes with this PR as well is, that now in case of `noop` the logger actually does nothing.
Before this PR, it always prepended the bindings and transformed the arguments no matter if the `noop` function was used or not.

> there is a valid case as well and that is if a `transmit` exists, but this is properly handled

Finally, the base log functions are now only once defined in the `setupBaseLogFunctions` instead of in every `set` call.

NicoVogel: I am still not sure if the approach I take actually goes into the right direction.
My guess is that there should be a better way of solving this with the prototype chain, but I have a hard time getting into this mind set, because I never needed to work with prototypes before.

Anyone has a guess here?
mcollina: Yes, I like this approach.
NicoVogel: @mcollina I noticed that I used `feat` in the commit message instead of `fix`. Should I fix this or do you use squash commits anyways?

Furthermore, I am unsure how to proceed with the failing checks.
- the benchmark for `current` (master) failed, but I can't fix that in this PR
- 14 windows failed the installation of dependencies, but I did not touch the dependencies

As for windows 16 and 18, I will try to figure out why this fails

Patch:
diff --git a/browser.js b/browser.js
index 1be837a..f9f8df0 100644
--- a/browser.js
+++ b/browser.js
@@ -16,6 +16,38 @@ const stdSerializers = {
   err: asErrValue,
   errWithCause: asErrValue
 }
+function levelToValue (level, logger) {
+  return level === 'silent'
+    ? Infinity
+    : logger.levels.values[level]
+}
+const baseLogFunctionSymbol = Symbol('pino.logFuncs')
+const hierarchySymbol = Symbol('pino.hierarchy')
+
+const logFallbackMap = {
+  error: 'log',
+  fatal: 'error',
+  warn: 'error',
+  info: 'log',
+  debug: 'log',
+  trace: 'log'
+}
+
+function appendChildLogger (parentLogger, childLogger) {
+  const newEntry = {
+    logger: childLogger,
+    parent: parentLogger[hierarchySymbol]
+  }
+  childLogger[hierarchySymbol] = newEntry
+}
+
+function setupBaseLogFunctions (logger, levels, proto) {
+  const logFunctions = {}
+  levels.forEach(level => {
+    logFunctions[level] = proto[level] ? proto[level] : (_console[level] || _console[logFallbackMap[level] ?? 'log'] || noop)
+  })
+  logger[baseLogFunctionSymbol] = logFunctions
+}
 
 function shouldSerialize (serialize, serializers) {
   if (Array.isArray(serialize)) {
@@ -61,6 +93,10 @@ function pino (opts) {
   const logger = Object.create(proto)
   if (!logger.log) logger.log = noop
 
+  setupBaseLogFunctions(logger, levels, proto)
+  // setup root hierarchy entry
+  appendChildLogger({}, logger)
+
   Object.defineProperty(logger, 'levelVal', {
     get: getLevelVal
   })
@@ -94,9 +130,7 @@ function pino (opts) {
   if (transmit) logger._logEvent = createLogEventShape()
 
   function getLevelVal () {
-    return this.level === 'silent'
-      ? Infinity
-      : this.levels.values[this.level]
+    return levelToValue(this.level, this)
   }
 
   function getLevel () {
@@ -108,15 +142,15 @@ function pino (opts) {
     }
     this._level = level
 
-    set(setOpts, logger, 'error', 'log') // <-- must stay first
-    set(setOpts, logger, 'fatal', 'error')
-    set(setOpts, logger, 'warn', 'error')
-    set(setOpts, logger, 'info', 'log')
-    set(setOpts, logger, 'debug', 'log')
-    set(setOpts, logger, 'trace', 'log')
+    set(this, setOpts, logger, 'error') // <-- must stay first
+    set(this, setOpts, logger, 'fatal')
+    set(this, setOpts, logger, 'warn')
+    set(this, setOpts, logger, 'info')
+    set(this, setOpts, logger, 'debug')
+    set(this, setOpts, logger, 'trace')
 
-    customLevels.forEach(function (level) {
-      set(setOpts, logger, level, 'log')
+    customLevels.forEach((level) => {
+      set(this, setOpts, logger, level)
     })
   }
 
@@ -139,12 +173,10 @@ function pino (opts) {
     }
     function Child (parent) {
       this._childLevel = (parent._childLevel | 0) + 1
-      this.error = bind(parent, bindings, 'error')
-      this.fatal = bind(parent, bindings, 'fatal')
-      this.warn = bind(parent, bindings, 'warn')
-      this.info = bind(parent, bindings, 'info')
-      this.debug = bind(parent, bindings, 'debug')
-      this.trace = bind(parent, bindings, 'trace')
+
+      // make sure bindings are available in the `set` function
+      this.bindings = bindings
+
       if (childSerializers) {
         this.serializers = childSerializers
         this._serialize = childSerialize
@@ -156,7 +188,14 @@ function pino (opts) {
       }
     }
     Child.prototype = this
-    return new Child(this)
+    const newLogger = new Child(this)
+
+    // must happen before the level is assigned
+    appendChildLogger(this, newLogger)
+    // required to actually initialize the logger functions for any given child
+    newLogger.level = this.level
+
+    return newLogger
   }
   return logger
 }
@@ -203,19 +242,54 @@ pino.levels = {
 pino.stdSerializers = stdSerializers
 pino.stdTimeFunctions = Object.assign({}, { nullTime, epochTime, unixTime, isoTime })
 
-function set (opts, logger, level, fallback) {
-  const proto = Object.getPrototypeOf(logger)
-  logger[level] = logger.levelVal > logger.levels.values[level]
+function getBindingChain (logger) {
+  const bindings = []
+  if (logger.bindings) {
+    bindings.push(logger.bindings)
+  }
+
+  // traverse up the tree to get all bindings
+  let hierarchy = logger[hierarchySymbol]
+  while (hierarchy.parent) {
+    hierarchy = hierarchy.parent
+    if (hierarchy.logger.bindings) {
+      bindings.push(hierarchy.logger.bindings)
+    }
+  }
+
+  return bindings.reverse()
+}
+
+function set (self, opts, rootLogger, level) {
+  // override the current log functions with either `noop` or the base log function
+  self[level] = levelToValue(self.level, rootLogger) > levelToValue(level, rootLogger)
     ? noop
-    : (proto[level] ? proto[level] : (_console[level] || _console[fallback] || noop))
+    : rootLogger[baseLogFunctionSymbol][level]
 
-  wrap(opts, logger, level)
+  if (!opts.transmit && self[level] === noop) {
+    return
+  }
+
+  // make sure the log format is correct
+  self[level] = createWrap(self, opts, rootLogger, level)
+
+  // prepend bindings if it is not the root logger
+  const bindings = getBindingChain(self)
+  if (bindings.length === 0) {
+    // early exit in case for rootLogger
+    return
+  }
+  self[level] = prependBindingsInArguments(bindings, self[level])
 }
 
-function wrap (opts, logger, level) {
-  if (!opts.transmit && logger[level] === noop) return
+function prependBindingsInArguments (bindings, logFunc) {
+  return function () {
+    return logFunc.apply(this, [...bindings, ...arguments])
+  }
+}
 
-  logger[level] = (function (write) {
+function createWrap (self, opts, rootLogger, level) {
+  return (function (write) {
     return function LOG () {
       const ts = opts.timestamp()
       const args = new Array(arguments.length)
@@ -229,22 +303,22 @@ function wrap (opts, logger, level) {
       else write.apply(proto, args)
 
       if (opts.transmit) {
-        const transmitLevel = opts.transmit.level || logger.level
-        const transmitValue = logger.levels.values[transmitLevel]
-        const methodValue = logger.levels.values[level]
+        const transmitLevel = opts.transmit.level || self._level
+        const transmitValue = rootLogger.levels.values[transmitLevel]
+        const methodValue = rootLogger.levels.values[level]
         if (methodValue < transmitValue) return
         transmit(this, {
           ts,
           methodLevel: level,
           methodValue,
           transmitLevel,
-          transmitValue: logger.levels.values[opts.transmit.level || logger.level],
+          transmitValue: rootLogger.levels.values[opts.transmit.level || self._level],
           send: opts.transmit.send,
-          val: logger.levelVal
+          val: levelToValue(self._level, rootLogger)
         }, args)
       }
     }
-  })(logger[level])
+  })(self[baseLogFunctionSymbol][level])
 }
 
 function asObject (logger, level, args, ts) {
@@ -283,17 +357,6 @@ function applySerializers (args, serialize, serializers, stdErrSerialize) {
   }
 }
 
-function bind (parent, bindings, level) {
-  return function () {
-    const args = new Array(1 + arguments.length)
-    args[0] = bindings
-    for (var i = 1; i < args.length; i++) {
-      args[i] = arguments[i - 1]
-    }
-    return parent[level].apply(this, args)
-  }
-}
-
 function transmit (logger, opts, args) {
   const send = opts.send
   const ts = opts.ts
diff --git a/docs/transports.md b/docs/transports.md
index 8e48820..94f86c4 100644
--- a/docs/transports.md
+++ b/docs/transports.md
@@ -337,7 +337,7 @@ const pino = require('pino')
 const transport = pino.transport({
   targets: [
     { target: '/absolute/path/to/my-transport.mjs', level: 'error' },
-    { target: 'some-file-transport', options: { destination: '/dev/null' }
+    { target: 'some-file-transport', options: { destination: '/dev/null' } }
   ]
 })
 const logger = pino(transport)
diff --git a/lib/transport.js b/lib/transport.js
index 39de490..d59b897 100644
--- a/lib/transport.js
+++ b/lib/transport.js
@@ -2,7 +2,7 @@
 
 const { createRequire } = require('module')
 const getCallers = require('./caller')
-const { join, isAbsolute } = require('path')
+const { join, isAbsolute, sep } = require('path')
 const sleep = require('atomic-sleep')
 const onExit = require('on-exit-leak-free')
 const ThreadStream = require('thread-stream')
@@ -128,7 +128,11 @@ function transport (fullOptions) {
 
     for (const filePath of callers) {
       try {
-        fixTarget = createRequire(filePath).resolve(origin)
+        const context = filePath === 'node:repl'
+          ? process.cwd() + sep
+          : filePath
+
+        fixTarget = createRequire(context).resolve(origin)
         break
       } catch (err) {
         // Silent catch
diff --git a/package.json b/package.json
index 5b60560..16612cb 100644
--- a/package.json
+++ b/package.json
@@ -65,14 +65,14 @@
     "@types/tap": "^15.0.6",
     "airtap": "4.0.4",
     "benchmark": "^2.1.4",
-    "bole": "^4.0.0",
+    "bole": "^5.0.5",
     "bunyan": "^1.8.14",
     "debug": "^4.3.4",
     "docsify-cli": "^4.4.4",
     "eslint": "^8.17.0",
     "eslint-config-standard": "^17.0.0",
     "eslint-plugin-import": "^2.26.0",
-    "eslint-plugin-n": "^15.2.2",
+    "eslint-plugin-n": "^16.0.1",
     "eslint-plugin-node": "^11.1.0",
     "eslint-plugin-promise": "^6.0.0",
     "execa": "^5.0.0",
@@ -97,7 +97,7 @@
     "through2": "^4.0.0",
     "ts-node": "^10.9.1",
     "tsd": "^0.24.1",
-    "typescript": "^4.8.2",
+    "typescript": "^5.1.3",
     "winston": "^3.7.2"
   },
   "dependencies": {


Test patch:
diff --git a/test/browser-child.test.js b/test/browser-child.test.js
new file mode 100644
index 0000000..0ed1dd5
--- /dev/null
+++ b/test/browser-child.test.js
@@ -0,0 +1,106 @@
+'use strict'
+const test = require('tape')
+const pino = require('../browser')
+
+test('child has parent level', ({ end, same, is }) => {
+  const instance = pino({
+    level: 'error',
+    browser: {}
+  })
+
+  const child = instance.child({})
+
+  same(child.level, instance.level)
+  end()
+})
+
+test('changing child level does not affect parent', ({ end, same, is }) => {
+  const instance = pino({
+    level: 'error',
+    browser: {}
+  })
+
+  const child = instance.child({})
+  child.level = 'info'
+
+  same(instance.level, 'error')
+  end()
+})
+
+test('child should log, if its own level allows it', ({ end, same, is }) => {
+  const expected = [
+    {
+      level: 30,
+      msg: 'this is info'
+    },
+    {
+      level: 40,
+      msg: 'this is warn'
+    },
+    {
+      level: 50,
+      msg: 'this is an error'
+    }
+  ]
+  const instance = pino({
+    level: 'error',
+    browser: {
+      write (actual) {
+        checkLogObjects(is, same, actual, expected.shift())
+      }
+    }
+  })
+
+  const child = instance.child({})
+  child.level = 'info'
+
+  child.debug('this is debug')
+  child.info('this is info')
+  child.warn('this is warn')
+  child.error('this is an error')
+
+  same(expected.length, 0, 'not all messages were read')
+  end()
+})
+
+test('changing child log level should not affect parent log behavior', ({ end, same, is }) => {
+  const expected = [
+    {
+      level: 50,
+      msg: 'this is an error'
+    },
+    {
+      level: 60,
+      msg: 'this is fatal'
+    }
+  ]
+  const instance = pino({
+    level: 'error',
+    browser: {
+      write (actual) {
+        checkLogObjects(is, same, actual, expected.shift())
+      }
+    }
+  })
+
+  const child = instance.child({})
+  child.level = 'info'
+
+  instance.warn('this is warn')
+  instance.error('this is an error')
+  instance.fatal('this is fatal')
+
+  same(expected.length, 0, 'not all messages were read')
+  end()
+})
+
+function checkLogObjects (is, same, actual, expected) {
+  is(actual.time <= Date.now(), true, 'time is greater than Date.now()')
+
+  const actualCopy = Object.assign({}, actual)
+  const expectedCopy = Object.assign({}, expected)
+  delete actualCopy.time
+  delete expectedCopy.time
+
+  same(actualCopy, expectedCopy)
+}
diff --git a/test/transport/repl.test.js b/test/transport/repl.test.js
new file mode 100644
index 0000000..103bead
--- /dev/null
+++ b/test/transport/repl.test.js
@@ -0,0 +1,14 @@
+'use strict'
+
+const { doesNotThrow, test } = require('tap')
+const proxyquire = require('proxyquire')
+
+test('pino.transport resolves targets in REPL', async ({ same }) => {
+  // Arrange
+  const transport = proxyquire('../../lib/transport', {
+    './caller': () => ['node:repl']
+  })
+
+  // Act / Assert
+  doesNotThrow(() => transport({ target: 'pino-pretty' }))
+})