[Feature] configure output both by log level and by logger name -dynamically

[geonanorch]

I use both pino and pino-debug. At the moment in a given module I have to:

const log = pino.child({ name: '/lib/mymodule' });
const debug = require('debug')('/lib/mymodule');
 . . . .
log.info('some important notice for mymodule');
log.debug('unfiltered debug entry');
 . . . .
debug('filterable debug entry');

The 2 require above hint at duplication, and even if debug is not enabled for /lib/mymodule (DEBUG=), the generic log.info() and log.debug() calls will still output (depending on the logger's level of course).

I understand that pino-debug's goal is to integrate with the debug module, therefore I am raising this issue under pino itself to suggest:

• implement the same filtering logic for pino loggers and child loggers as in the debug module (in other words: orthogonal to the log level, log generation is also filterable by logger name)
• ensure that the current filtering (level+name) can be adjusted at any time by calling a static method with a map parameter similar to that of pino-debug

Such a feature would:

1. avoid me having to require debug for new code, going 100% pino
2. allow to selectively turn on/off logging by modules (or even by function)
3. unify behavior between pino and debug/pino-debug

[mcollina]

This is an interesting use case, and the use of env variables keeps coming up. We have always resisted to this. It's currently implementable with some gymnastic involved, but maybe we could streamline this for pino-debug.

I'm generically against reacting to env variables from a logging lib point of view.

@davidmarkclements @jsumners @watson @marcbachmann any other thoughts?

[jsumners]

I abhor environment variables.

@geonanorch for new code, why not just drop debug? See https://github.com/jsumners/abstract-logging for an example of a way to support using any logger that isn't debug.

[jsumners]

As for enabling and disabling logs based on name... I think that would add too much overhead to core. It could easily be done in a transport.

You might also be able to make use of pino-multistream for such a scenario, but the transport route is the best way to go.

[geonanorch]

@mcollina thanks for the interest. I did not intend to suggest using environment variables, that is something which can easily be implemented by the client code when instantiating pino (sorry, mentioned DEBUG because that is what debug uses). My proposition is that filtering by name in addition to level might be useful; typical scenario (on top of coveringdebug's functionality): I want to enable debug to track down a bug, but only for selected modules in order to limit volume and production impact. To put it differently, I would like to be able to call (at any time) a function setFilter() on a (parent) pino logger:

logger.setFilter({ 
    'mymodule': 'debug',      // this will affect a child logger named 'mymodule'
    'mythermodule': 'trace',  // even more details required for that other module
    '*': 'info'               // default logging level as set through '.level'
});

instead of just:

logger.level = 'debug';

@jsumners

• re env. variables fair enough! I certainly do not like them hard-coded in libraries
• about dropping debug: that is exactly what I am trying to do! Right now I have to use it because pino does not filter by name (I will check your suggestions though)
• to preserve performance I thought that the same approach could be used for name-filtering as for level-filtering: replace logging function by noop() when logging should not occur (implies keeping track of loggers' children)

[mcollina]

@geonanorch that is currently not possible in the current architecture, as the father maintain no link to its children.

[jsumners]

With your example of setFilter I better understand the desire. pino-arborsculpture combined with a transport might be able to solve your problem.

[davidmarkclements]

yay someone's using pino-debug 🎉

so we're talking about filtering child logs based on log level AND namespace matching

even though, yes, noops increase performance, I can't currently see a performant way to do this in-process

What about this (app level) pattern:

const DEBUG = process.env.DEBUG || ''
const log = pino.child({ 
  name: '/lib/mymodule',
  level: DEBUG.includes('/lib/mymodule') ? 'debug' : 'info'
});
 . . . .
log.info('some important notice for mymodule');
log.debug('filterable debug entry');

This doesn't cater to wildcards etc. but you could make a minimal version of https://github.com/visionmedia/debug/blob/master/src/debug.js#L138-L156 to get the same namespace processing

[geonanorch]

@mcollina understood. Pushing the child to an array as it get created would be enough? The filtering checks can be stolen from debug. If my need becomes more urgent maybe I'll get back to this issue and contribute some code, best way to show my gratitude for the pino family I guess!

@jsumners I admit, my initial description is a bit difficult to follow. Thank you for the pino-arborsculpture hint (spotted and recommended to someone else earlier today)

@davidmarkclements yes (excepted that like you mentioned in the corresponding issue debug is currently broken) and exactly, 2 orthogonal dimensions to filtering –that means that whatever implementation approach works for log level should also work for namespace... Thank you for the workaround tip!

[geonanorch]

OK, I could not resist and added a filtering capabiltiy for your consideration (based on 4.0.3):

the level property can then be assigned a map { pattern: loglevel } alternatively to the usual log level, e.g.:

var currentLevels = {
    'mymodule': 'debug',
    '*': 'info'
}
var logger = pino({
  level: currentLevels
})
 . . . . .
currentLevels.myothermodule = 'debug';
logger.level = currentLevels;

The change is backward-compatible and does not impact logging performance. As far as I can tell all tests pass (running this under Windows, 2 tests fail already on the original 4.0.3).

output of git -U0 lib/tools.js:

diff --git a/lib/tools.js b/lib/tools.js
index 8a8261c..c6dfb90 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -33,0 +34,2 @@ function applyOptions (opts) {
+  this.levelMap = opts.levelMap
+  this.children = opts.children
@@ -120,0 +123,12 @@ function genLog (z) {
+function byPrecision (b, a) {
+  var aix = a.indexOf('*')
+  var bix = b.indexOf('*')
+  if (aix === -1 && bix === -1) return 0
+  if (~aix && ~bix) {
+    if (aix > bix) return -1
+    if (aix < bix) return 1
+    return a.length < b.length ? 1 : (a.length === b.length ? 0 : -1)
+  }
+  return ~bix ? -1 : 1
+}
+
@@ -126,0 +141 @@ module.exports = {
+  byPrecision: byPrecision,

output of git -U0 pino.js:

diff --git a/pino.js b/pino.js
index 98c4361..9158c59 100644
--- a/pino.js
+++ b/pino.js
@@ -60,0 +61,2 @@ function pino (opts, stream) {
+  iopts.levelMap = Object(null)
+  iopts.children = []
@@ -120 +122 @@ Object.defineProperty(Pino.prototype, 'levelVal', {
-    if (typeof num === 'string') { return this._setLevel(num) }
+    if (typeof num !== 'number') { return this._setLevel(num) }
@@ -138,0 +141,12 @@ Pino.prototype._setLevel = function _setLevel (level) {
+  if (typeof level === 'object') {
+    this.levelMap = level  // remember for future offspring
+    Object.keys(level).sort(tools.byPrecision).map((pattern) => {
+      const regexp = new RegExp('^' + pattern.replace(/\*/g, '.*?') + '$')
+      this.children.map((child) => {
+        if (child.name && regexp.test(child.name)) child._setLevel(level[pattern])
+      })
+      if (regexp.test(this.name)) this._setLevel(level[pattern])
+    })
+    return
+  }
+
@@ -215,0 +230,7 @@ Pino.prototype.child = function child (bindings) {
+  let l = bindings.level || this.level
+  const level = this.levelMap
+  Object.keys(level).sort(tools.byPrecision).map((pattern) => {
+    const regexp = new RegExp('^' + pattern.replace(/\*/g, '.*?') + '$')
+    if (bindings.name && regexp.test(bindings.name)) l = level[pattern]
+  })
+
@@ -217 +238 @@ Pino.prototype.child = function child (bindings) {
-    level: bindings.level || this.level,
+    level: l,
@@ -218,0 +240 @@ Pino.prototype.child = function child (bindings) {
+    levelMap: this.levelMap,
@@ -226,0 +249 @@ Pino.prototype.child = function child (bindings) {
+    children: [],
@@ -232,0 +256 @@ Pino.prototype.child = function child (bindings) {
+  this.children.push(_child)

[jsumners]

1. Put it in a PR so that it is easier to read
2. Include benchmark results

Personally, I still think this would be better downstream.

[geonanorch]

Closing, follow-up (benchmark + PR) in issue #208.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.