fix: browser respect child logger log level (#1725)

* test: add browser child level tests

* feat: child level is independent of parent logger

Author: NicoVogel

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

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)
+}