feat: Allow hierarchical filtering of logger namespaces (#22859)

* POC: Allow hierarchical filtering of logger namespaces

matches the closes defined namespace log level:

advanced:
  log_namespaced_levels:
    'zh:zstack:unpi': info

would also apply to zh:zstack:unpi:write and zh:zstack:unpi:parse

To limit runtime penalty uses the namespacedLevels as a lazy cache

* Move namespace levels to separate cache

Avoid poluting the namespacedLevel in the config / UI
Add cache reset on config time log level change

* Actually use the cache

* Optimize/Cleanup

* Add some namespace hierarchy filter tests

* More coverage.

* Fix #22935

---------

Co-authored-by: Nerivec <62446222+Nerivec@users.noreply.github.com>

lib/util/logger.ts

@@ -7,6 +7,8 @@ import fx from 'mkdir-recursive';
 import {rimrafSync} from 'rimraf';
 import assert from 'assert';
 
+const NAMESPACE_SEPARATOR = ':';
+
 class Logger {
     private level: settings.LogLevel;
     private output: string[];
@@ -15,6 +17,7 @@ class Logger {
     private fileTransport: winston.transports.FileTransportInstance;
     private debugNamespaceIgnoreRegex?: RegExp;
     private namespacedLevels: Record<string, settings.LogLevel>;
+    private cachedNamespacedLevels: Record<string, settings.LogLevel>;
 
     public init(): void {
         // What transports to enable
@@ -25,6 +28,7 @@ class Logger {
         const logFilename = settings.get().advanced.log_file.replace('%TIMESTAMP%', timestamp);
         this.level = settings.get().advanced.log_level;
         this.namespacedLevels = settings.get().advanced.log_namespaced_levels;
+        this.cachedNamespacedLevels = Object.assign({}, this.namespacedLevels);
 
         assert(
             settings.LOG_LEVELS.includes(this.level),
@@ -53,7 +57,7 @@ class Logger {
             format: winston.format.combine(
                 winston.format.colorize({colors: {debug: 'blue', info: 'green', warning: 'yellow', error: 'red'}}),
                 winston.format.printf(/* istanbul ignore next */(info) => {
-                    return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
+                    return `[${info.timestamp}] ${info.level}: \t${info.message}`;
                 }),
             ),
         }));
@@ -80,7 +84,7 @@ class Logger {
             const transportFileOptions: winston.transports.FileTransportOptions = {
                 filename: path.join(this.directory, logFilename),
                 format: winston.format.printf(/* istanbul ignore next */(info) => {
-                    return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
+                    return `[${info.timestamp}] ${info.level}: \t${info.message}`;
                 }),
             };
 
@@ -102,9 +106,6 @@ class Logger {
 
             const options: KeyValue = {
                 app_name: 'Zigbee2MQTT',
-                format: winston.format.printf(/* istanbul ignore next */(info) => {
-                    return `${info.namespace}: ${info.message}`;
-                }),
                 ...settings.get().advanced.log_syslog,
             };
 
@@ -147,6 +148,7 @@ class Logger {
 
     public setLevel(level: settings.LogLevel): void {
         this.level = level;
+        this.resetCachedNamespacedLevels();
     }
 
     public getNamespacedLevels(): Record<string, settings.LogLevel> {
@@ -155,13 +157,35 @@ class Logger {
 
     public setNamespacedLevels(nsLevels: Record<string, settings.LogLevel>): void {
         this.namespacedLevels = nsLevels;
+        this.resetCachedNamespacedLevels();
+    }
+
+    private resetCachedNamespacedLevels(): void {
+        this.cachedNamespacedLevels = Object.assign({}, this.namespacedLevels);
+    }
+
+    private cacheNamespacedLevel(namespace: string) : string {
+        let cached = namespace;
+
+        while (this.cachedNamespacedLevels[namespace] == undefined) {
+            const sep = cached.lastIndexOf(NAMESPACE_SEPARATOR);
+
+            if (sep === -1) {
+                return this.cachedNamespacedLevels[namespace] = this.level;
+            }
+
+            cached = cached.slice(0, sep);
+            this.cachedNamespacedLevels[namespace] = this.cachedNamespacedLevels[cached];
+        }
+
+        return this.cachedNamespacedLevels[namespace];
     }
 
     private log(level: settings.LogLevel, message: string, namespace: string): void {
-        const nsLevel = this.namespacedLevels[namespace] ?? this.level;
+        const nsLevel = this.cacheNamespacedLevel(namespace);
 
         if (settings.LOG_LEVELS.indexOf(level) <= settings.LOG_LEVELS.indexOf(nsLevel)) {
-            this.logger.log(level, message, {namespace});
+            this.logger.log(level, `${namespace}: ${message}`);
         }
     }
 

test/logger.test.js

@@ -161,18 +161,18 @@ describe('Logger', () => {
         let i = 1;
 
         logger[level]('msg');
-        expect(logSpy).toHaveBeenLastCalledWith(level, 'msg', {namespace: 'z2m'});
+        expect(logSpy).toHaveBeenLastCalledWith(level, 'z2m: msg');
         expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
         logger[level]('msg', 'abcd');
-        expect(logSpy).toHaveBeenLastCalledWith(level, 'msg', {namespace: 'abcd'});
+        expect(logSpy).toHaveBeenLastCalledWith(level, 'abcd: msg');
         expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
 
         for (const higherLevel of otherLevels.higher) {
             logger[higherLevel]('higher msg');
-            expect(logSpy).toHaveBeenLastCalledWith(higherLevel, 'higher msg', {namespace: 'z2m'});
+            expect(logSpy).toHaveBeenLastCalledWith(higherLevel, 'z2m: higher msg');
             expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
             logger[higherLevel]('higher msg', 'abcd');
-            expect(logSpy).toHaveBeenLastCalledWith(higherLevel, 'higher msg', {namespace: 'abcd'});
+            expect(logSpy).toHaveBeenLastCalledWith(higherLevel, 'abcd: higher msg');
             expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
         }
 
@@ -193,7 +193,7 @@ describe('Logger', () => {
         const logSpy = jest.spyOn(logger.winston, 'log');
 
         logger.error(new Error('msg'));// test for stack=true
-        expect(logSpy).toHaveBeenLastCalledWith('error', new Error('msg'), {namespace: 'z2m'});
+        expect(logSpy).toHaveBeenLastCalledWith('error', `z2m: ${new Error('msg')}`);
         expect(consoleWriteSpy).toHaveBeenCalledTimes(1);
     })
 
@@ -251,7 +251,7 @@ describe('Logger', () => {
             if (test.match) {
                 expect(logSpy).not.toHaveBeenCalled();
             } else {
-                expect(logSpy).toHaveBeenLastCalledWith('debug', 'Test message', {namespace: test.ns});
+                expect(logSpy).toHaveBeenLastCalledWith('debug', `${test.ns}: Test message`);
             }
 
             logSpy.mockClear();
@@ -304,4 +304,71 @@ describe('Logger', () => {
         expect(logSpy).toHaveBeenCalledTimes(3);
         expect(consoleWriteSpy).toHaveBeenCalledTimes(3);
     });
+
+    it('Logs with namespaced levels hierarchy', () => {
+        const nsLevels = {'zh:zstack': 'debug', 'zh:zstack:unpi:writer': 'error'};
+        let cachedNSLevels = Object.assign({}, nsLevels);
+        logger.setNamespacedLevels(nsLevels);
+        logger.setLevel('warning');
+
+        consoleWriteSpy.mockClear();
+        logger.debug(`--- parseNext [] debug picked from hierarchy`, 'zh:zstack:unpi:parser');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi:parser': 'debug'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(1);
+        logger.warning(`--> frame [36,15] warning explicitely supressed`, 'zh:zstack:unpi:writer');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(cachedNSLevels);
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(1);
+        logger.warning(`Another supressed warning message in a sub namespace`, 'zh:zstack:unpi:writer:sub:ns');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi:writer:sub:ns': 'error'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(1);
+        logger.error(`but error should go through`, 'zh:zstack:unpi:writer:another:sub:ns');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi:writer:another:sub:ns': 'error'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(2);
+        logger.warning(`new unconfigured namespace warning`, 'z2m:mqtt');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'z2m:mqtt': 'warning'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(3);
+        logger.info(`cached unconfigured namespace info should be supressed`, 'z2m:mqtt');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(cachedNSLevels);
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(3);
+
+        logger.setLevel('info');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(cachedNSLevels = Object.assign({}, nsLevels));
+        logger.info(`unconfigured namespace info should now pass after default level change and cache reset`, 'z2m:mqtt');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'z2m:mqtt': 'info'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(4);
+        logger.error(`configured namespace hierachy should still work after the cache reset`, 'zh:zstack:unpi:writer:another:sub:ns');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi:writer:another:sub:ns': 'error'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(5);
+
+        logger.setNamespacedLevels({'zh:zstack': 'warning'})
+        expect(logger.cachedNamespacedLevels).toStrictEqual(cachedNSLevels = {'zh:zstack': 'warning'});
+        logger.error(`error logged`, 'zh:zstack:unpi:writer');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi:writer': 'warning'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(6);
+        logger.debug(`debug suppressed`, 'zh:zstack:unpi');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack:unpi': 'warning'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(6);
+        logger.warning(`warning logged`, 'zh:zstack');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'zh:zstack': 'warning'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(7);
+        logger.info(`unconfigured namespace`, 'z2m:mqtt');
+        expect(logger.cachedNamespacedLevels).toStrictEqual(Object.assign(cachedNSLevels, {'z2m:mqtt': 'info'}));
+        expect(consoleWriteSpy).toHaveBeenCalledTimes(8);
+    });
+
+    it('Ignores SPLAT chars', () => {
+        logger.setLevel('debug');
+
+        const logSpy = jest.spyOn(logger.winston, 'log');
+        consoleWriteSpy.mockClear();
+
+        let net_map = '%d';
+        logger.debug(net_map, 'z2m:mqtt');
+        expect(logSpy).toHaveBeenLastCalledWith('debug', `z2m:mqtt: ${net_map}`);
+        expect(consoleWriteSpy.mock.calls[0][0]).toMatch(new RegExp(`^.*\tz2m:mqtt: ${net_map}`));
+        net_map = 'anything %s goes here';
+        logger.debug(net_map, 'z2m:test');
+        expect(logSpy).toHaveBeenLastCalledWith('debug', `z2m:test: ${net_map}`);
+        expect(consoleWriteSpy.mock.calls[1][0]).toMatch(new RegExp(`^.*\tz2m:test: ${net_map}`));
+    });
 });