Improve performance when logging is disabled

lib/mqtt.ts

@@ -145,7 +145,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()});
  }
 
@@ -196,7 +196,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

@@ -189,32 +189,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.

test/controller.test.js

@@ -1,6 +1,7 @@
 process.env.NOTIFY_SOCKET = 'mocked';
 const data = require('./stub/data');
 const logger = require('./stub/logger');
+const Transport = require('winston-transport');
 const zigbeeHerdsman = require('./stub/zigbeeHerdsman');
 const MQTT = require('./stub/mqtt');
 const path = require('path');
@@ -325,21 +326,47 @@ describe('Controller', () => {
  });
 
  it('Handle mqtt message', async () => {
+ class DummyTransport extends Transport {
+ log(info, callback) {}
+ }
+ const transport = new DummyTransport();
+ logger.setTransportsEnabled(true);
+ let spyTransport = jest.spyOn(transport, 'log').mockImplementation();
+ logger.addTransport(transport);
+
  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(spyTransport).toHaveBeenCalledWith(
+ {level: 'debug', message: "Received MQTT message on 'dummytopic' with data 'dummymessage'", namespace: LOG_MQTT_NS},
+ expect.any(Function),
+ );
+ logger.removeTransport(transport);
+ logger.setTransportsEnabled(false);
  });
 
  it('Skip MQTT messages on topic we published to', async () => {
+ class DummyTransport extends Transport {
+ log(info, callback) {}
+ }
+ const transport = new DummyTransport();
+ logger.setTransportsEnabled(true);
+ let spyTransport = jest.spyOn(transport, 'log').mockImplementation();
+ logger.addTransport(transport);
+
  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(spyTransport).toHaveBeenCalledWith(
+ {level: 'debug', message: "Received MQTT message on 'zigbee2mqtt/skip-this-topic' with data 'skipped'", namespace: LOG_MQTT_NS},
+ expect.any(Function),
+ );
  logger.debug.mockClear();
  await controller.mqtt.publish('skip-this-topic', '', {});
  await MQTT.events.message('zigbee2mqtt/skip-this-topic', 'skipped');
  expect(logger.debug).toHaveBeenCalledTimes(0);
+ logger.removeTransport(transport);
+ logger.setTransportsEnabled(false);
  });
 
  it('On zigbee event message', async () => {

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/stub/logger.js

@@ -5,8 +5,9 @@ let namespacedLevels = {};
 let transports = [];
 
 let transportsEnabled = false;
-const callTransports = (level, message, namespace) => {
+const callTransports = (level, messageOrLambda, namespace) => {
  if (transportsEnabled) {
+ const message = messageOrLambda instanceof Function ? messageOrLambda() : messageOrLambda;
  for (const transport of transports) {
  transport.log({level, message, namespace}, () => {});
  }
@@ -15,10 +16,10 @@ const callTransports = (level, message, namespace) => {
 
 const mock = {
  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') => callTransports('info', messageOrLambda, namespace)),
+ warning: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => callTransports('warning', messageOrLambda, namespace)),
+ error: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => callTransports('error', messageOrLambda, namespace)),
+ debug: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => callTransports('debug', messageOrLambda, namespace)),
  cleanup: jest.fn(),
  logOutput: jest.fn(),
  add: (transport) => transports.push(transport),