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 b409d53.

* Update zigbee.ts

Fix prettier issue

* Fix test issues

* Revert await removal

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};

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.

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` : ``),

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',
         );
     });
 

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');

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 () => {

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),