Drilldown noisy logs

[CMCDragonkai]

Specification

There are 2 ways to drill down into noisy logs. The first way is to prevent those non-relevant logs from ever being shown in the first place, the second way is to capture everything and then use a log navigator/filter to find the relevant logs.

For the second way to be effective, we will need #3 to have context around our logs. And the second way is the only way to debug production systems.

The first way however is useful just for local debugging and testing, and an example of this is node's NODE_DEBUG and NODE_DEBUG_NATIVE environment variables and also the https://www.npmjs.com/package/debug package.

Basically you specify modules and submodules using that option:

The character may be used as a wildcard. Suppose for example your library has debuggers named "connect:bodyParser", "connect:compress", "connect:session", instead of listing all three with DEBUG=connect:bodyParser,connect:compress,connect:session, you may simply do DEBUG=connect:, or to run everything using this module simply use DEBUG=*.

You can also exclude specific debuggers by prefixing them with a "-" character. For example, DEBUG=,-connect: would include all debuggers except those starting with "connect:".

In js-logger this should be available programmatically. And we would identify by the logger key path. Because we have a logger hierarchy, it should be possible to configure to only show logs from root.child1.child2. This would be more generic/flexible than focusing on module names. Of course we often use the module/class names as the logger names themselves anyway.

I imagine we could do something like:

logger.setFilter(['root.child1.child2', 'root.child1'])

By default root.child1 would encompass all child loggers under root.child1, so it would be equivalent to module:* in NODE_DEBUG.

Multiple filters can be set, and they can overlap. Before a log gets emitted, it would need to check if the filter allows it to pass through.

Each logger instance can have their own filters applied. But for applications generally, filters should be applied from the root logger down.

We can make use of this in our jest tests, because we often create a test logger to inject into our test objects, and the test logger can have an appropriate filter applied for interactive test debugging.

We could extend the filter to be capable of specialising only for certain levels. By default, it applies to all log levels. But the level filter is a separate axis from this filter, this is a "positional" filter.

Additional context

• https://www.npmjs.com/package/debug
• https://nodejs.org/api/cli.html#node_debugmodule
• We are currently making use of NODE_DEBUG_NATIVE in the new js-db using rocksdb in order to show debug logs of the C++ native addon, js-logger wouldn't actually read these environment variables by itself, the user of the system would need to parse the env variable and apply the proper filters to the js-logger itself.

[CMCDragonkai]

This was requested by @emmacasolin to help debug what's going on in the testnet. It makes sense that this library should have its filter configurable dynamically, however I'm in the opinion that we need better state transition events to allow representational state simulacra available on the frontend, because logs are a lossy serialisation of the underlying state of the target system.

[CMCDragonkai]

At the same time, it would be better for the client to decide how to filter the logs. So log viewers would be more capable. Server side should still generate the logs to avoid losing data.

[CMCDragonkai]

But during quick local debugging this can still be useful.

Will need to decide on what the meaning of filter expressions:

A.*
A.**

Maybe we can do something similar to globbing.

[CMCDragonkai]

I can see that child loggers actually log via the parent loggers. And if they have their own handlers it is also called. It's done through the callHandlers method. So indeed, any child logger is also automatically logging to the parent.

If a filter is applied to a logger, it'd be applied at the callHandlers level. However that results in some wasted computation doing makeRecord.

  protected callHandlers(record: LogRecord, format?: LogFormatter): void {
    for (const handler of this.handlers) {
      handler.handle(record, format);
    }
    if (this.parent) {
      this.parent.callHandlers(record, format);
    }
  }

  Root
┌────────┐
│        │
│ Logger │ callHandlers()
│        │     ▲
└────┬───┘     │
     │         │
     │         │
     │         │
┌────▼───┐     │
│        │     │
│ Logger │ callHandlers()
│        │     ▲
└────┬───┘     │
     │         │
     │         │
     │         │
┌────▼───┐     │
│        │ callHandlers()
│ Logger │     ▲
│        │    log()
└────────┘
  Leaf

[CMCDragonkai]

This was done with a very quick log filtering based on regular expressions:

const logger = new Logger('root');
const interLogger = logger.getChild('inter');
const leaf1Logger = interLogger.getChild('leaf1');
const leaf2Logger = interLogger.getChild('leaf2');
logger.setFilter(/^root\.inter/);
leaf1Logger.info('INFO MESSAGE');
leaf2Logger.info('INFO MESSAGE');
logger.setFilter(/^root\.inter\.leaf1/);
leaf1Logger.info('INFO MESSAGE');
leaf2Logger.info('INFO MESSAGE');
logger.setFilter(/^root\.inter\.leaf2/);
leaf1Logger.info('INFO MESSAGE');
leaf2Logger.info('INFO MESSAGE');

Only to be used for debugging... nothing else.

Nothing in js-logger processes any kind of debug environment variable.

Although regex is so flexible, I'd suggest that any debug filtering like --verbose='.*' should just be taken verbatim and applied to the logger hierarchy.