From c6ca472ca1374c1b217063816359315931bbcdb0 Mon Sep 17 00:00:00 2001 From: Tomer <57483589+tomer-w@users.noreply.github.com> Date: Thu, 12 Sep 2024 21:33:05 +0300 Subject: [PATCH] fix: Improve performance when logging is disabled (#23893) * Improve log performance * Bug fix * Revert sample configuration * Align package versions * Revert dependecies version to allow testing * Update package-lock.json * Fix prettier issue * Coverage to 100% * Fix CR comments * remove uneeded changes * Make the same perf optimization to the MQTT messages * Fix MQTT tests * prettier fix * Allow easy mocking of stub logger callTransports function to receive the actual message * cleanup leftover * Fix prettier issues * Finalize logger mock structure and add few lambda log calls * fix prettier issue * Run prettier * Revert "fix prettier issue" This reverts commit b409d538e389ae170f86ab5618b32d3e97992b23. * Update zigbee.ts Fix prettier issue * Fix test issues * Revert await removal --- lib/mqtt.ts | 4 ++-- lib/util/logger.ts | 19 ++++++++++--------- lib/zigbee.ts | 9 ++++++--- test/controller.test.js | 23 ++++++++++++++++++----- test/logger.test.js | 3 +++ test/publish.test.js | 2 +- test/stub/logger.js | 25 ++++++++++++------------- 7 files changed, 52 insertions(+), 33 deletions(-) diff --git a/lib/mqtt.ts b/lib/mqtt.ts index 2d91395dbc..bfafe25887 100644 --- a/lib/mqtt.ts +++ b/lib/mqtt.ts @@ -146,7 +146,7 @@ export default class MQTT { @bind public onMessage(topic: string, message: Buffer): void { // Since we subscribe to zigbee2mqtt/# we also receive the message we send ourselves, skip these. if (!this.publishedTopics.has(topic)) { - logger.debug(`Received MQTT message on '${topic}' with data '${message.toString()}'`, NS); + logger.debug(() => `Received MQTT message on '${topic}' with data '${message.toString()}'`, NS); this.eventBus.emitMQTTMessage({topic, message: message.toString()}); } @@ -197,7 +197,7 @@ export default class MQTT { } if (!skipLog) { - logger.info(`MQTT publish: topic '${topic}', payload '${payload}'`, NS); + logger.info(() => `MQTT publish: topic '${topic}', payload '${payload}'`, NS); } const actualOptions: mqtt.IClientPublishOptions = {...defaultOptions, ...options}; diff --git a/lib/util/logger.ts b/lib/util/logger.ts index 5c1643f64c..055972a88f 100644 --- a/lib/util/logger.ts +++ b/lib/util/logger.ts @@ -190,32 +190,33 @@ class Logger { return this.cachedNamespacedLevels[namespace]; } - private log(level: settings.LogLevel, message: string, namespace: string): void { + private log(level: settings.LogLevel, messageOrLambda: string | (() => string), namespace: string): void { const nsLevel = this.cacheNamespacedLevel(namespace); if (settings.LOG_LEVELS.indexOf(level) <= settings.LOG_LEVELS.indexOf(nsLevel)) { + const message: string = messageOrLambda instanceof Function ? messageOrLambda() : messageOrLambda; this.logger.log(level, `${namespace}: ${message}`); } } - public error(message: string, namespace: string = 'z2m'): void { - this.log('error', message, namespace); + public error(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void { + this.log('error', messageOrLambda, namespace); } - public warning(message: string, namespace: string = 'z2m'): void { - this.log('warning', message, namespace); + public warning(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void { + this.log('warning', messageOrLambda, namespace); } - public info(message: string, namespace: string = 'z2m'): void { - this.log('info', message, namespace); + public info(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void { + this.log('info', messageOrLambda, namespace); } - public debug(message: string, namespace: string = 'z2m'): void { + public debug(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void { if (this.debugNamespaceIgnoreRegex?.test(namespace)) { return; } - this.log('debug', message, namespace); + this.log('debug', messageOrLambda, namespace); } // Cleanup any old log directory. diff --git a/lib/zigbee.ts b/lib/zigbee.ts index d0d9ab7682..2ce66b1080 100644 --- a/lib/zigbee.ts +++ b/lib/zigbee.ts @@ -58,8 +58,10 @@ export default class Zigbee { acceptJoiningDeviceHandler: this.acceptJoiningDeviceHandler, }; - const herdsmanSettingsLog = JSON.stringify(herdsmanSettings).replaceAll(JSON.stringify(herdsmanSettings.network.networkKey), '"HIDDEN"'); - logger.debug(`Using zigbee-herdsman with settings: '${stringify(herdsmanSettingsLog)}'`); + logger.debug( + () => + `Using zigbee-herdsman with settings: '${stringify(JSON.stringify(herdsmanSettings).replaceAll(JSON.stringify(herdsmanSettings.network.networkKey), '"HIDDEN"'))}'`, + ); let startResult; try { @@ -115,7 +117,8 @@ export default class Zigbee { const device = this.resolveDevice(data.device.ieeeAddr)!; await device.resolveDefinition(); logger.debug( - `Received Zigbee message from '${device.name}', type '${data.type}', ` + + () => + `Received Zigbee message from '${device.name}', type '${data.type}', ` + `cluster '${data.cluster}', data '${stringify(data.data)}' from endpoint ${data.endpoint.ID}` + (data['groupID'] !== undefined ? ` with groupID ${data.groupID}` : ``) + (device.zh.type === 'Coordinator' ? `, ignoring since it is from coordinator` : ``), diff --git a/test/controller.test.js b/test/controller.test.js index a77196abe0..b71723c37d 100644 --- a/test/controller.test.js +++ b/test/controller.test.js @@ -325,17 +325,24 @@ describe('Controller', () => { }); it('Handle mqtt message', async () => { + const eventbus = controller.eventBus; + let spyEventbusEmitMQTTMessage = jest.spyOn(eventbus, 'emitMQTTMessage').mockImplementation(); + await controller.start(); logger.debug.mockClear(); await MQTT.events.message('dummytopic', 'dummymessage'); - expect(logger.debug).toHaveBeenCalledWith("Received MQTT message on 'dummytopic' with data 'dummymessage'", LOG_MQTT_NS); + expect(spyEventbusEmitMQTTMessage).toHaveBeenCalledWith({topic: 'dummytopic', message: 'dummymessage'}); + expect(logger.log).toHaveBeenCalledWith('debug', "Received MQTT message on 'dummytopic' with data 'dummymessage'", LOG_MQTT_NS); }); it('Skip MQTT messages on topic we published to', async () => { + const eventbus = controller.eventBus; + let spyEventbusEmitMQTTMessage = jest.spyOn(eventbus, 'emitMQTTMessage').mockImplementation(); + await controller.start(); logger.debug.mockClear(); await MQTT.events.message('zigbee2mqtt/skip-this-topic', 'skipped'); - expect(logger.debug).toHaveBeenCalledWith("Received MQTT message on 'zigbee2mqtt/skip-this-topic' with data 'skipped'", LOG_MQTT_NS); + expect(spyEventbusEmitMQTTMessage).toHaveBeenCalledWith({topic: 'zigbee2mqtt/skip-this-topic', message: 'skipped'}); logger.debug.mockClear(); await controller.mqtt.publish('skip-this-topic', '', {}); await MQTT.events.message('zigbee2mqtt/skip-this-topic', 'skipped'); @@ -355,8 +362,10 @@ describe('Controller', () => { }; await zigbeeHerdsman.events.message(payload); await flushPromises(); - expect(logger.debug).toHaveBeenCalledWith( + expect(logger.log).toHaveBeenCalledWith( + 'debug', `Received Zigbee message from 'bulb', type 'attributeReport', cluster 'genBasic', data '{"modelId":"TRADFRI bulb E27 WS opal 980lm"}' from endpoint 1`, + 'z2m', ); }); @@ -374,8 +383,10 @@ describe('Controller', () => { }; await zigbeeHerdsman.events.message(payload); await flushPromises(); - expect(logger.debug).toHaveBeenCalledWith( + expect(logger.log).toHaveBeenCalledWith( + 'debug', `Received Zigbee message from 'bulb', type 'attributeReport', cluster 'genBasic', data '{"modelId":"TRADFRI bulb E27 WS opal 980lm"}' from endpoint 1 with groupID 0`, + 'z2m', ); }); @@ -964,8 +975,10 @@ describe('Controller', () => { }; await zigbeeHerdsman.events.message(payload); await flushPromises(); - expect(logger.debug).toHaveBeenCalledWith( + expect(logger.log).toHaveBeenCalledWith( + 'debug', `Received Zigbee message from 'Coordinator', type 'attributeReport', cluster 'genBasic', data '{"modelId":null}' from endpoint 1, ignoring since it is from coordinator`, + 'z2m', ); }); diff --git a/test/logger.test.js b/test/logger.test.js index 95a74872c4..81e52d1b21 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -164,6 +164,9 @@ describe('Logger', () => { logger[level]('msg', 'abcd'); expect(logSpy).toHaveBeenLastCalledWith(level, 'abcd: msg'); expect(consoleWriteSpy).toHaveBeenCalledTimes(i++); + logger[level](() => 'func msg', 'abcd'); + expect(logSpy).toHaveBeenLastCalledWith(level, 'abcd: func msg'); + expect(consoleWriteSpy).toHaveBeenCalledTimes(i++); for (const higherLevel of otherLevels.higher) { logger[higherLevel]('higher msg'); diff --git a/test/publish.test.js b/test/publish.test.js index 3d0b129bc3..fe7d370eef 100644 --- a/test/publish.test.js +++ b/test/publish.test.js @@ -600,7 +600,7 @@ describe('Publish', () => { await MQTT.events.message(`zigbee2mqtt/${device.ieeeAddr}/set`, stringify({state: 'OFF'})); await flushPromises(); console.log(logger.error.mock.calls); - expect(logger.error).toHaveBeenCalledWith(`Cannot publish to unsupported device 'button_double_key_interviewing'`); + expect(logger.log).toHaveBeenCalledWith('error', `Cannot publish to unsupported device 'button_double_key_interviewing'`, 'z2m'); }); it('Should log error when device has no such endpoint (via property)', async () => { diff --git a/test/stub/logger.js b/test/stub/logger.js index b9b9346ca2..c03dd45c47 100644 --- a/test/stub/logger.js +++ b/test/stub/logger.js @@ -1,24 +1,23 @@ let level = 'info'; let debugNamespaceIgnore = ''; let namespacedLevels = {}; - let transports = []; - let transportsEnabled = false; -const callTransports = (level, message, namespace) => { - if (transportsEnabled) { - for (const transport of transports) { - transport.log({level, message, namespace}, () => {}); - } - } -}; +const getMessage = (messageOrLambda) => (messageOrLambda instanceof Function ? messageOrLambda() : messageOrLambda); const mock = { + log: jest.fn().mockImplementation((level, message, namespace = 'z2m') => { + if (transportsEnabled) { + for (const transport of transports) { + transport.log({level, message, namespace}, () => {}); + } + } + }), init: jest.fn(), - info: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('info', msg, namespace)), - warning: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('warning', msg, namespace)), - error: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('error', msg, namespace)), - debug: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('debug', msg, namespace)), + info: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('info', getMessage(messageOrLambda), namespace)), + warning: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('warning', getMessage(messageOrLambda), namespace)), + error: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('error', getMessage(messageOrLambda), namespace)), + debug: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('debug', getMessage(messageOrLambda), namespace)), cleanup: jest.fn(), logOutput: jest.fn(), add: (transport) => transports.push(transport),