Skip to content

Commit

Permalink
feat: Allow hierarchical filtering of logger namespaces (#22859)
Browse files Browse the repository at this point in the history 
* 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>
  • Loading branch information
@ghoz @Nerivec
ghoz and Nerivec authored Jun 4, 2024
1 parent 2b8eaa1 commit 881037c
Show file tree
Hide file tree
Showing 2 changed files with 104 additions and 13 deletions.
38 changes: 31 additions & 7 deletions lib/util/logger.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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[];
Expand All @@ -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
Expand All @@ -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),
Expand Down Expand Up @@ -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}`;
}),
),
}));
Expand All @@ -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}`;
}),
};

Expand All @@ -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,
};

Expand Down Expand Up @@ -147,6 +148,7 @@ class Logger {

public setLevel(level: settings.LogLevel): void {
this.level = level;
this.resetCachedNamespacedLevels();
}

public getNamespacedLevels(): Record<string, settings.LogLevel> {
Expand All @@ -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}`);
}
}

Expand Down
79 changes: 73 additions & 6 deletions test/logger.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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++);
}

Expand All @@ -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);
})

Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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}`));
});
});

0 comments on commit 881037c

Please sign in to comment.