fix(ignore): Improve performance when logging is disabled (#1178)

* Improve logger performance * Bump package version * Beutify the code * Running prettier * Improve lint status * Fixing prettier issues again * More eslint fixes * fix failing unit tests * Get coverage to 100% * Fix eslinter * Fix CR comments * Revert package changes * Revert package-lock.json * rename messageBuilder to createLogMessage
Koenkk · Sep 11, 2024 · f3fc0d7 · f3fc0d7
1 parent 3d4b374
commit f3fc0d7
Show file tree

Hide file tree

Showing 20 changed files with 133 additions and 109 deletions.
diff --git a/src/adapter/ember/adapter/emberAdapter.ts b/src/adapter/ember/adapter/emberAdapter.ts
@@ -512,7 +512,7 @@ export class EmberAdapter extends Adapter {
                                 );
                             }
 
-                            logger.debug(`Registered multicast table entry (${tableIdx}): ${JSON.stringify(multicastEntry)}.`, NS);
+                            logger.debug(() => `Registered multicast table entry (${tableIdx}): ${JSON.stringify(multicastEntry)}.`, NS);
                         });
                     } catch (error) {
                         // remove to allow retry on next occurrence
@@ -538,7 +538,7 @@ export class EmberAdapter extends Adapter {
         try {
             const payload = BuffaloZdo.readResponse(apsFrame.clusterId, messageContents);
 
-            logger.debug(`<~~~ [ZDO ${Zdo.ClusterId[apsFrame.clusterId]} from=${sender} ${payload ? JSON.stringify(payload) : 'OK'}]`, NS);
+            logger.debug(() => `<~~~ [ZDO ${Zdo.ClusterId[apsFrame.clusterId]} from=${sender} ${payload ? JSON.stringify(payload) : 'OK'}]`, NS);
             this.oneWaitress.resolveZDO(sender, apsFrame, payload);
 
             if (apsFrame.clusterId === Zdo.ClusterId.NETWORK_ADDRESS_RESPONSE) {
@@ -759,7 +759,7 @@ export class EmberAdapter extends Adapter {
         this.networkCache.parameters = parameters;
         this.networkCache.eui64 = await this.ezsp.ezspGetEui64();
 
-        logger.debug(`[INIT] Network Ready! ${JSON.stringify(this.networkCache)}`, NS);
+        logger.debug(() => `[INIT] Network Ready! ${JSON.stringify(this.networkCache)}`, NS);
 
         this.watchdogCountersHandle = setInterval(this.watchdogCounters.bind(this), WATCHDOG_COUNTERS_FEED_INTERVAL);
 
@@ -842,7 +842,7 @@ export class EmberAdapter extends Adapter {
                     throw new Error(`Failed to register group '${multicastId}' in multicast table with status=${SLStatus[status]}.`);
                 }
 
-                logger.debug(`Registered multicast table entry (${this.multicastTable.length}): ${JSON.stringify(multicastEntry)}.`, NS);
+                logger.debug(() => `Registered multicast table entry (${this.multicastTable.length}): ${JSON.stringify(multicastEntry)}.`, NS);
                 this.multicastTable.push(multicastEntry.multicastId);
             }
         }
@@ -904,7 +904,7 @@ export class EmberAdapter extends Adapter {
 
             const [npStatus, nodeType, netParams] = await this.ezsp.ezspGetNetworkParameters();
 
-            logger.debug(`[INIT TC] Current adapter network: nodeType=${EmberNodeType[nodeType]} params=${JSON.stringify(netParams)}`, NS);
+            logger.debug(() => `[INIT TC] Current adapter network: nodeType=${EmberNodeType[nodeType]} params=${JSON.stringify(netParams)}`, NS);
 
             if (
                 npStatus === SLStatus.OK &&
@@ -1118,7 +1118,7 @@ export class EmberAdapter extends Adapter {
             channels: ZSpec.ALL_802_15_4_CHANNELS_MASK,
         };
 
-        logger.info(`[INIT FORM] Forming new network with: ${JSON.stringify(netParams)}`, NS);
+        logger.info(() => `[INIT FORM] Forming new network with: ${JSON.stringify(netParams)}`, NS);
 
         status = await this.ezsp.ezspFormNetwork(netParams);
 
@@ -1450,7 +1450,7 @@ export class EmberAdapter extends Adapter {
             logger.warning(`Adapter is running a non-GA version (${EmberVersionType[versionStruct.type]}).`, NS);
         }
 
-        logger.info(`Adapter version info: ${JSON.stringify(this.version)}`, NS);
+        logger.info(() => `Adapter version info: ${JSON.stringify(this.version)}`, NS);
     }
 
     /**
@@ -2472,7 +2472,7 @@ export class EmberAdapter extends Adapter {
         return this.queue.execute<ZclPayload | void>(async () => {
             this.checkInterpanLock();
 
-            logger.debug(`~~~> [ZCL to=${networkAddress} apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
+            logger.debug(() => `~~~> [ZCL to=${networkAddress} apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
 
             for (let i = 1; i <= QUEUE_MAX_SEND_ATTEMPTS; i++) {
                 let status: SLStatus = SLStatus.FAIL;
@@ -2555,7 +2555,7 @@ export class EmberAdapter extends Adapter {
         return this.queue.execute<void>(async () => {
             this.checkInterpanLock();
 
-            logger.debug(`~~~> [ZCL GROUP apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
+            logger.debug(() => `~~~> [ZCL GROUP apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
             // eslint-disable-next-line @typescript-eslint/no-unused-vars
             const [status, messageTag] = await this.ezsp.send(
                 EmberOutgoingMessageType.MULTICAST,
@@ -2597,7 +2597,7 @@ export class EmberAdapter extends Adapter {
         return this.queue.execute<void>(async () => {
             this.checkInterpanLock();
 
-            logger.debug(`~~~> [ZCL BROADCAST apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
+            logger.debug(() => `~~~> [ZCL BROADCAST apsFrame=${JSON.stringify(apsFrame)} header=${JSON.stringify(zclFrame.header)}]`, NS);
             // eslint-disable-next-line @typescript-eslint/no-unused-vars
             const [status, messageTag] = await this.ezsp.send(
                 EmberOutgoingMessageType.BROADCAST,
@@ -2654,7 +2654,7 @@ export class EmberAdapter extends Adapter {
             msgBuffalo.writeUInt16(zclFrame.cluster.ID);
             msgBuffalo.writeUInt16(ZSpec.TOUCHLINK_PROFILE_ID);
 
-            logger.debug(`~~~> [ZCL TOUCHLINK to=${ieeeAddress} header=${JSON.stringify(zclFrame.header)}]`, NS);
+            logger.debug(() => `~~~> [ZCL TOUCHLINK to=${ieeeAddress} header=${JSON.stringify(zclFrame.header)}]`, NS);
             const status = await this.ezsp.ezspSendRawMessage(
                 Buffer.concat([msgBuffalo.getWritten(), zclFrame.toBuffer()]),
                 EmberTransmitPriority.NORMAL,
@@ -2709,7 +2709,7 @@ export class EmberAdapter extends Adapter {
 
             const data = Buffer.concat([msgBuffalo.getWritten(), zclFrame.toBuffer()]);
 
-            logger.debug(`~~~> [ZCL TOUCHLINK BROADCAST header=${JSON.stringify(zclFrame.header)}]`, NS);
+            logger.debug(() => `~~~> [ZCL TOUCHLINK BROADCAST header=${JSON.stringify(zclFrame.header)}]`, NS);
             const status = await this.ezsp.ezspSendRawMessage(data, EmberTransmitPriority.NORMAL, true);
 
             if (status !== SLStatus.OK) {

diff --git a/src/adapter/ember/ezsp/ezsp.ts b/src/adapter/ember/ezsp/ezsp.ts
@@ -2748,7 +2748,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
      */
     ezspNetworkFoundHandler(networkFound: EmberZigbeeNetwork, lastHopLqi: number, lastHopRssi: number): void {
         logger.debug(
-            `ezspNetworkFoundHandler(): callback called with: [networkFound=${JSON.stringify(networkFound)}], [lastHopLqi=${lastHopLqi}], [lastHopRssi=${lastHopRssi}]`,
+            () =>
+                `ezspNetworkFoundHandler(): callback called with: [networkFound=${JSON.stringify(networkFound)}], [lastHopLqi=${lastHopLqi}], [lastHopRssi=${lastHopRssi}]`,
             NS,
         );
     }
@@ -4675,7 +4676,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
      */
     ezspRemoteSetBindingHandler(entry: EmberBindingTableEntry, index: number, policyDecision: SLStatus): void {
         logger.debug(
-            `ezspRemoteSetBindingHandler(): callback called with: [entry=${JSON.stringify(entry)}], [index=${index}], [policyDecision=${SLStatus[policyDecision]}]`,
+            () =>
+                `ezspRemoteSetBindingHandler(): callback called with: [entry=${JSON.stringify(entry)}], [index=${index}], [policyDecision=${SLStatus[policyDecision]}]`,
             NS,
         );
     }
@@ -4973,7 +4975,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
         messageContents?: Buffer,
     ): void {
         logger.debug(
-            `ezspMessageSentHandler(): callback called with: [status=${SLStatus[status]}], [type=${EmberOutgoingMessageType[type]}], ` +
+            () =>
+                `ezspMessageSentHandler(): callback called with: [status=${SLStatus[status]}], [type=${EmberOutgoingMessageType[type]}], ` +
                 `[indexOrDestination=${indexOrDestination}], [apsFrame=${JSON.stringify(apsFrame)}], [messageTag=${messageTag}]` +
                 (messageContents ? `, [messageContents=${messageContents.toString('hex')}]` : ''),
             NS,
@@ -5240,7 +5243,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
         messageContents: Buffer,
     ): void {
         logger.debug(
-            `ezspIncomingMessageHandler(): callback called with: [type=${EmberIncomingMessageType[type]}], [apsFrame=${JSON.stringify(apsFrame)}], ` +
+            () =>
+                `ezspIncomingMessageHandler(): callback called with: [type=${EmberIncomingMessageType[type]}], [apsFrame=${JSON.stringify(apsFrame)}], ` +
                 `[packetInfo:${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
             NS,
         );
@@ -5757,7 +5761,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
      */
     ezspMacPassthroughMessageHandler(messageType: EmberMacPassthroughType, packetInfo: EmberRxPacketInfo, messageContents: Buffer): void {
         logger.debug(
-            `ezspMacPassthroughMessageHandler(): callback called with: [messageType=${messageType}], [packetInfo=${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
+            () =>
+                `ezspMacPassthroughMessageHandler(): callback called with: [messageType=${messageType}], [packetInfo=${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
             NS,
         );
     }
@@ -5778,7 +5783,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
         messageContents: Buffer,
     ): void {
         logger.debug(
-            `ezspMacFilterMatchMessageHandler(): callback called with: [filterIndexMatch=${filterIndexMatch}], [legacyPassthroughType=${legacyPassthroughType}], ` +
+            () =>
+                `ezspMacFilterMatchMessageHandler(): callback called with: [filterIndexMatch=${filterIndexMatch}], [legacyPassthroughType=${legacyPassthroughType}], ` +
                 `[packetInfo=${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
             NS,
         );
@@ -7727,7 +7733,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
      */
     ezspIncomingBootloadMessageHandler(longId: EUI64, packetInfo: EmberRxPacketInfo, messageContents: Buffer): void {
         logger.debug(
-            `ezspIncomingBootloadMessageHandler(): callback called with: [longId=${longId}], [packetInfo=${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
+            () =>
+                `ezspIncomingBootloadMessageHandler(): callback called with: [longId=${longId}], [packetInfo=${JSON.stringify(packetInfo)}], [messageContents=${messageContents.toString('hex')}]`,
             NS,
         );
     }
@@ -8080,7 +8087,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
         packetInfo: EmberRxPacketInfo,
     ): void {
         logger.debug(
-            `ezspZllNetworkFoundHandler(): callback called with: [networkInfo=${networkInfo}], [isDeviceInfoNull=${isDeviceInfoNull}], [deviceInfo=${deviceInfo}], [packetInfo=${JSON.stringify(packetInfo)}]`,
+            () =>
+                `ezspZllNetworkFoundHandler(): callback called with: [networkInfo=${networkInfo}], [isDeviceInfoNull=${isDeviceInfoNull}], [deviceInfo=${deviceInfo}], [packetInfo=${JSON.stringify(packetInfo)}]`,
             NS,
         );
     }
@@ -8103,7 +8111,7 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
      */
     ezspZllAddressAssignmentHandler(addressInfo: EmberZllAddressAssignment, packetInfo: EmberRxPacketInfo): void {
         logger.debug(
-            `ezspZllAddressAssignmentHandler(): callback called with: [addressInfo=${addressInfo}], [packetInfo=${JSON.stringify(packetInfo)}]`,
+            () => `ezspZllAddressAssignmentHandler(): callback called with: [addressInfo=${addressInfo}], [packetInfo=${JSON.stringify(packetInfo)}]`,
             NS,
         );
     }
@@ -8511,7 +8519,8 @@ export class Ezsp extends EventEmitter<EmberEzspEventMap> {
         gpdCommandPayload: Buffer,
     ): void {
         logger.debug(
-            `ezspGpepIncomingMessageHandler(): callback called with: [status=${EmberGPStatus[status] ?? status}], [gpdLink=${gpdLink}], ` +
+            () =>
+                `ezspGpepIncomingMessageHandler(): callback called with: [status=${EmberGPStatus[status] ?? status}], [gpdLink=${gpdLink}], ` +
                 `[sequenceNumber=${sequenceNumber}], [addr=${JSON.stringify(addr)}], [gpdfSecurityLevel=${EmberGpSecurityLevel[gpdfSecurityLevel]}], ` +
                 `[gpdfSecurityKeyType=${EmberGpKeyType[gpdfSecurityKeyType]}], [autoCommissioning=${autoCommissioning}], ` +
                 `[bidirectionalInfo=${bidirectionalInfo}], [gpdSecurityFrameCounter=${gpdSecurityFrameCounter}], [gpdCommandId=${gpdCommandId}], ` +

diff --git a/src/adapter/ember/uart/ash.ts b/src/adapter/ember/uart/ash.ts
@@ -484,7 +484,7 @@ export class UartAsh extends EventEmitter<UartAshEventMap> {
                 serialOpts.binding = this.portOptions.binding;
             }
 
-            logger.debug(`Opening serial port with ${JSON.stringify(serialOpts)}`, NS);
+            logger.debug(() => `Opening serial port with ${JSON.stringify(serialOpts)}`, NS);
             this.serialPort = new SerialPort(serialOpts);
 
             this.writer.pipe(this.serialPort);

diff --git a/src/adapter/ezsp/adapter/ezspAdapter.ts b/src/adapter/ezsp/adapter/ezspAdapter.ts
@@ -73,7 +73,7 @@ class EZSPAdapter extends Adapter {
     }
 
     private async processMessage(frame: EmberIncomingMessage): Promise<void> {
-        logger.debug(`processMessage: ${JSON.stringify(frame)}`, NS);
+        logger.debug(() => `processMessage: ${JSON.stringify(frame)}`, NS);
         if (frame.apsFrame.profileId == 0) {
             if (frame.apsFrame.clusterId == EmberZDOCmd.Device_annce && frame.apsFrame.destinationEndpoint == 0) {
                 let nwk, rst, ieee;

diff --git a/src/adapter/ezsp/driver/driver.ts b/src/adapter/ezsp/driver/driver.ts
@@ -412,7 +412,7 @@ export class Driver extends EventEmitter {
                 const status = frame.status;
                 if (status != 0) {
                     // send failure
-                    logger.debug(`Delivery failed for ${JSON.stringify(frame)}.`, NS);
+                    logger.debug(() => `Delivery failed for ${JSON.stringify(frame)}.`, NS);
                 } else {
                     // send success
                     // If there was a message to the group and this group is not known,
@@ -734,7 +734,7 @@ export class Driver extends EventEmitter {
         const requestName = EmberZDOCmd.valueName(EmberZDOCmd, requestCmd);
         const responseName = EmberZDOCmd.valueName(EmberZDOCmd, responseCmd);
 
-        logger.debug(`ZDO ${requestName} params: ${JSON.stringify(params)}`, NS);
+        logger.debug(() => `ZDO ${requestName} params: ${JSON.stringify(params)}`, NS);
 
         const frame = this.makeApsFrame(requestCmd as number, false);
         const payload = this.makeZDOframe(requestCmd as number, {transId: frame.sequence, ...params});
@@ -749,7 +749,7 @@ export class Driver extends EventEmitter {
 
             const response = await waiter.start().promise;
 
-            logger.debug(`${responseName}  frame: ${JSON.stringify(response.payload)}`, NS);
+            logger.debug(() => `${responseName}  frame: ${JSON.stringify(response.payload)}`, NS);
 
             const result = new EZSPZDOResponseFrameData(responseCmd as number, response.payload);
 
@@ -830,7 +830,7 @@ export class Driver extends EventEmitter {
             inputClusterList: inputClusters,
             outputClusterList: outputClusters,
         });
-        logger.debug(`Ezsp adding endpoint: ${JSON.stringify(res)}`, NS);
+        logger.debug(() => `Ezsp adding endpoint: ${JSON.stringify(res)}`, NS);
     }
 
     public waitFor(

diff --git a/src/adapter/ezsp/driver/ezsp.ts b/src/adapter/ezsp/driver/ezsp.ts
@@ -434,7 +434,7 @@ export class Ezsp extends EventEmitter {
             return;
         }
 
-        logger.debug(`<== 0x${frameId.toString(16)}: ${JSON.stringify(frm)}`, NS);
+        logger.debug(() => `<== 0x${frameId.toString(16)}: ${JSON.stringify(frm)}`, NS);
 
         const handled = this.waitress.resolve({
             frameId,
@@ -633,7 +633,7 @@ export class Ezsp extends EventEmitter {
     private makeFrame(name: string, params: ParamsDesc | undefined, seq: number): Buffer {
         const frmData = new EZSPFrameData(name, true, params);
 
-        logger.debug(`==> ${JSON.stringify(frmData)}`, NS);
+        logger.debug(() => `==> ${JSON.stringify(frmData)}`, NS);
 
         const frame = [seq & 255];
 
@@ -653,7 +653,7 @@ export class Ezsp extends EventEmitter {
     }
 
     public async execCommand(name: string, params?: ParamsDesc): Promise<EZSPFrameData> {
-        logger.debug(`==> ${name}: ${JSON.stringify(params)}`, NS);
+        logger.debug(() => `==> ${name}: ${JSON.stringify(params)}`, NS);
 
         if (!this.serialDriver.isInitialized()) {
             throw new Error('Connection not initialized');

diff --git a/src/adapter/z-stack/znp/znp.ts b/src/adapter/z-stack/znp/znp.ts
@@ -69,26 +69,10 @@ class Znp extends events.EventEmitter {
         this.unpiParser = new UnpiParser();
     }
 
-    private log(type: Type, message: string): void {
-        if (type === Type.SRSP) {
-            logger.debug(`SRSP: ${message}`, NS);
-        } else if (type === Type.AREQ) {
-            logger.debug(`AREQ: ${message}`, NS);
-        } else {
-            /* istanbul ignore else */
-            if (type === Type.SREQ) {
-                logger.debug(`SREQ: ${message}`, NS);
-            } else {
-                throw new Error(`Unknown type '${type}'`);
-            }
-        }
-    }
-
     private onUnpiParsed(frame: UnpiFrame): void {
         try {
             const object = ZpiObject.fromUnpiFrame(frame);
-            const message = `<-- ${Subsystem[object.subsystem]} - ${object.command} - ${JSON.stringify(object.payload)}`;
-            this.log(object.type, message);
+            logger.debug(() => `<-- ${object}`, NS);
             this.waitress.resolve(object);
             this.emit('received', object);
         } catch (error) {
@@ -286,10 +270,9 @@ class Znp extends events.EventEmitter {
         }
 
         const object = ZpiObject.createRequest(subsystem, command, payload);
-        const message = `--> ${Subsystem[object.subsystem]} - ${object.command} - ${JSON.stringify(payload)}`;
 
         return this.queue.execute<ZpiObject | void>(async () => {
-            this.log(object.type, message);
+            logger.debug(() => `--> ${object}`, NS);
 
             const frame = object.toUnpiFrame();
 
@@ -304,7 +287,7 @@ class Znp extends events.EventEmitter {
                     }
 
                     throw new Error(
-                        `SREQ '${message}' failed with status '${statusDescription(
+                        `--> '${object}' failed with status '${statusDescription(
                             result.payload.status,
                         )}' (expected '${expectedStatuses.map(statusDescription)}')`,
                     );

diff --git a/src/adapter/z-stack/znp/zpiObject.ts b/src/adapter/z-stack/znp/zpiObject.ts
@@ -131,6 +131,10 @@ class ZpiObject {
             (this.command === 'resetReq' && this.subsystem === Subsystem.SYS) || (this.command === 'systemReset' && this.subsystem === Subsystem.SAPI)
         );
     }
+
+    public toString(): string {
+        return `${Type[this.type]}: ${Subsystem[this.subsystem]} - ${this.command} - ${JSON.stringify(this.payload)}`;
+    }
 }
 
 export default ZpiObject;