From 881037c3711e1a1c8458960e242ca47f80dc2a60 Mon Sep 17 00:00:00 2001 From: ghoz Date: Tue, 4 Jun 2024 20:17:35 +0200 Subject: [PATCH] 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 | 38 ++++++++++++++++++---- test/logger.test.js | 79 +++++++++++++++++++++++++++++++++++++++++---- 2 files changed, 104 insertions(+), 13 deletions(-) diff --git a/lib/util/logger.ts b/lib/util/logger.ts index dace3d9c4e..1ecd5fdc1c 100644 --- a/lib/util/logger.ts +++ b/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; + private cachedNamespacedLevels: Record; 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 { @@ -155,13 +157,35 @@ class Logger { public setNamespacedLevels(nsLevels: Record): 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}`); } } diff --git a/test/logger.test.js b/test/logger.test.js index 25b17c94fc..f3c52bb749 100644 --- a/test/logger.test.js +++ b/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}`)); + }); });