Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

POC: Allow hierarchical filtering of logger namespaces #22859

Merged
merged 7 commits into from
Jun 4, 2024
Merged

POC: Allow hierarchical filtering of logger namespaces #22859

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
dbde825
POC: Allow hierarchical filtering of logger namespaces
ghoz May 31, 2024
87540a8
Move namespace levels to separate cache
ghoz May 31, 2024
e813cf1
Actually use the cache
ghoz Jun 1, 2024
0caeb07
Optimize/Cleanup
Nerivec Jun 2, 2024
803c76b
Add some namespace hierarchy filter tests
ghoz Jun 3, 2024
8cce8a3
More coverage.
Nerivec Jun 4, 2024
827e18e
Fix #22935
Nerivec Jun 4, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
38 changes: 31 additions & 7 deletions lib/util/logger.ts
View file
Open in desktop
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) => {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why was this removed? I think this causes #23241

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems it might not output the message without expressly returning it with printf?

format: winston.format.printf((info) => info.message),

Strange that it's undefined though, I would think it would be the stringified json of info param as default if not message.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ghoz could you comment on this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could, but I would not have much of interest to say ...
I see it has been removed when going for the winston hotpath directly
827e18e#diff-be38649fab0f205ab799e4de3d3b56ad7d54397f525e8f370cda402efcece524L109
but I'm not familiar with this low level to be honest...

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't have a syslog enabled system to test it out, but I'd suggest reverting this hunk...
@Nerivec do you remember why it was removed ?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Confirmed. It works using:

            const options: KeyValue = {
                app_name: 'Zigbee2MQTT',
                format: winston.format.printf((info) => info.message),
                ...settings.get().advanced.log_syslog,
            };

Not sure why it doesn't output json by default (might be the combine during logger init), but since we don't want json anyway, definitely a bit too much "cleanup" in my last commit here 😅
We might want to add a test to cover this codepath (would have to hijack way above syslog though I guess).

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];
Nerivec marked this conversation as resolved.
Show resolved Hide resolved
}

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);
Nerivec marked this conversation as resolved.
Show resolved Hide resolved

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
Open in desktop
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}`));
});
});