fix: Reduce MQTT publishing by excluding debug logging from bridge/logging (#22066)

* fix: Reduce MQTT publishing by excluding debug logging from `bridge/logging`

* fix tests

* fix

Author: Koenkk

lib/extension/bridge.ts

@@ -13,6 +13,7 @@ import data from '../util/data';
 import JSZip from 'jszip';
 import fs from 'fs';
 import * as zhc from 'zigbee-herdsman-converters';
+import winston from 'winston';
 
 const requestRegex = new RegExp(`${settings.get().mqtt.base_topic}/bridge/request/(.*)`);
 
@@ -28,6 +29,8 @@ export default class Bridge extends Extension {
     private coordinatorVersion: zh.CoordinatorVersion;
     private restartRequired = false;
     private lastJoinedDeviceIeeeAddr: string;
+    private lastBridgeLoggingPayload: string;
+    private logTransport: winston.transport;
     private requestLookup: {[key: string]: (message: KeyValue | string) => Promise<MQTTResponse>};
 
     override async start(): Promise<void> {
@@ -59,15 +62,23 @@ export default class Bridge extends Extension {
         };
 
         const mqtt = this.mqtt;
+        // eslint-disable-next-line @typescript-eslint/no-this-alias
+        const self = this;
         class EventTransport extends Transport {
-            log(info: {message: string, level: string}, callback: () => void): void {
-                const payload = stringify({message: info.message, level: info.level});
-                mqtt.publish(`bridge/logging`, payload, {}, settings.get().mqtt.base_topic, true);
-                callback();
+            log(info: {message: string, level: string}, next: () => void): void {
+                if (info.level !== 'debug') {
+                    const payload = stringify({message: info.message, level: info.level});
+                    if (payload !== self.lastBridgeLoggingPayload) {
+                        self.lastBridgeLoggingPayload = payload;
+                        mqtt.publish(`bridge/logging`, payload, {}, settings.get().mqtt.base_topic, true);
+                    }
+                }
+                next();
             }
         }
 
-        logger.addTransport(new EventTransport());
+        this.logTransport = new EventTransport();
+        logger.addTransport(this.logTransport);
 
         this.zigbee2mqttVersion = await utils.getZigbee2MQTTVersion();
         this.zigbeeHerdsmanVersion = await utils.getDependencyVersion('zigbee-herdsman');
@@ -118,6 +129,11 @@ export default class Bridge extends Extension {
         this.eventBus.onMQTTMessage(this, this.onMQTTMessage);
     }
 
+    override async stop(): Promise<void> {
+        super.stop();
+        logger.removeTransport(this.logTransport);
+    }
+
     @bind async onMQTTMessage(data: eventdata.MQTTMessage): Promise<void> {
         const match = data.topic.match(requestRegex);
         const key = match?.[1]?.toLowerCase();

lib/mqtt.ts

@@ -173,6 +173,7 @@ export default class MQTT {
         this.eventBus.emitMQTTMessagePublished({topic, payload, options: {...defaultOptions, ...options}});
 
         if (!this.isConnected()) {
+            /* istanbul ignore else */
             if (!skipLog) {
                 logger.error(`Not connected to MQTT server!`);
                 logger.error(`Cannot send message: topic: '${topic}', payload: '${payload}`);

lib/util/logger.ts

@@ -119,6 +119,10 @@ function addTransport(transport: winston.transport): void {
     logger.add(transport);
 }
 
+function removeTransport(transport: winston.transport): void {
+    logger.remove(transport);
+}
+
 // TODO refactor Z2M level to 'warning' to simplify logic
 function getLevel(): LogLevel | 'warn' {
     let level = transportsToUse[0].level;
@@ -203,6 +207,6 @@ async function end(): Promise<void> {
 }
 
 export default {
-    init, logOutput, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end,
+    init, logOutput, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end, removeTransport,
     winston: (): winston.Logger => logger,
 };

test/bridge.test.js

@@ -107,13 +107,19 @@ describe('Bridge', () => {
         MQTT.publish.mockClear();
         logger.info.mockClear();
         logger.info("this is a test");
+        logger.info("this is a test"); // Should not publish dupes
         expect(MQTT.publish).toHaveBeenCalledWith(
             'zigbee2mqtt/bridge/logging',
             stringify({message: 'this is a test', level: 'info'}),
           { retain: false, qos: 0 },
           expect.any(Function)
         );
-        expect(logger.info).toHaveBeenCalledTimes(1);
+        expect(MQTT.publish).toHaveBeenCalledTimes(1);
+
+        // Should not publish debug logging
+        MQTT.publish.mockClear();
+        logger.debug("this is a test");
+        expect(MQTT.publish).toHaveBeenCalledTimes(0);
     });
 
     it('Shouldnt log to MQTT when not connected', async () => {

test/logger.test.js

@@ -90,7 +90,7 @@ describe('Logger', () => {
         settings.reRead();
     });
 
-    it('Add transport', () => {
+    it('Add/remove transport', () => {
         class DummyTransport extends Transport {
             log(info, callback) {
             }
@@ -99,8 +99,11 @@ describe('Logger', () => {
         const logger = require('../lib/util/logger').default;
         logger.init();
         expect(logger.winston().transports.length).toBe(2);
-        logger.addTransport(new DummyTransport());
+        const transport = new DummyTransport();
+        logger.addTransport(transport);
         expect(logger.winston().transports.length).toBe(3);
+        logger.removeTransport(transport);
+        expect(logger.winston().transports.length).toBe(2);
     });
 
     it('Logger should be console and file by default', () => {

test/stub/logger.js

@@ -1,6 +1,6 @@
 let level = 'info';
 
-const transports = [];
+let transports = [];
 
 let transportsEnabled = false;
 const callTransports = (level, message, namespace) => {
@@ -21,6 +21,9 @@ const mock = {
     logOutput: jest.fn(),
     add: (transport) => transports.push(transport),
     addTransport: (transport) => transports.push(transport),
+    removeTransport: (transport) => {
+        transports = transports.filter((t) => t !== transport);
+    },
     setLevel: (newLevel) => {level = newLevel},
     getLevel: () => level,
     setTransportsEnabled: (value) => {transportsEnabled = value},