diff --git a/src/adapter/ember/adapter/emberAdapter.ts b/src/adapter/ember/adapter/emberAdapter.ts index 85b1602d0f..cfe0a94f39 100644 --- 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(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(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(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 index 1dc245ee7b..69aa773450 100644 --- a/src/adapter/ember/ezsp/ezsp.ts +++ b/src/adapter/ember/ezsp/ezsp.ts @@ -2748,7 +2748,8 @@ export class Ezsp extends EventEmitter { */ 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 { */ 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 { 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 { 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 { */ 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 { 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 { */ 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 { 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 { */ 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 { 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 index 17d5737a1b..6c5f1167dc 100644 --- a/src/adapter/ember/uart/ash.ts +++ b/src/adapter/ember/uart/ash.ts @@ -484,7 +484,7 @@ export class UartAsh extends EventEmitter { 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 index 27dbc9fbe1..118d159bca 100644 --- 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 { - 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 index c41cd3c4fa..294ec0bb65 100644 --- 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 index 26fcf7627a..462dcdb707 100644 --- 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 { - 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 index 863d933431..4002db4428 100755 --- 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(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 index b1826e92b7..c4d324589e 100755 --- 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; diff --git a/src/adapter/zboss/adapter/zbossAdapter.ts b/src/adapter/zboss/adapter/zbossAdapter.ts index 04bac728e0..b61fccffbb 100644 --- a/src/adapter/zboss/adapter/zbossAdapter.ts +++ b/src/adapter/zboss/adapter/zbossAdapter.ts @@ -52,7 +52,7 @@ export class ZBOSSAdapter extends Adapter { } private async processMessage(frame: ZBOSSFrame): Promise { - logger.debug(`processMessage: ${JSON.stringify(frame)}`, NS); + logger.debug(() => `processMessage: ${JSON.stringify(frame)}`, NS); if ( frame.type == FrameType.INDICATION && frame.commandId == CommandId.ZDO_DEV_UPDATE_IND && @@ -142,7 +142,7 @@ export class ZBOSSAdapter extends Adapter { public async getCoordinator(): Promise { return this.queue.execute(async () => { const info = await this.driver.getCoordinator(); - logger.debug(`ZBOSS Adapter Coordinator description:\n${JSON.stringify(info)}`, NS); + logger.debug(() => `ZBOSS Adapter Coordinator description:\n${JSON.stringify(info)}`, NS); this.coordinator = { networkAddress: info.networkAddress, manufacturerID: 0, diff --git a/src/adapter/zboss/driver.ts b/src/adapter/zboss/driver.ts index e7e1e643ef..3a07affe2e 100644 --- a/src/adapter/zboss/driver.ts +++ b/src/adapter/zboss/driver.ts @@ -137,7 +137,7 @@ export class ZBOSSDriver extends EventEmitter { private async needsToBeInitialised(options: TsType.NetworkOptions): Promise { let valid = true; this.netInfo = await this.getNetworkInfo(); - logger.debug(`Current network parameters: ${JSON.stringify(this.netInfo)}`, NS); + logger.debug(() => `Current network parameters: ${JSON.stringify(this.netInfo)}`, NS); if (this.netInfo) { valid = valid && this.netInfo.nodeType == DeviceType.COORDINATOR; valid = valid && options.panID == this.netInfo.network.panID; @@ -201,7 +201,7 @@ export class ZBOSSDriver extends EventEmitter { outputClusters: outputClusters, }); - logger.debug(`Adding endpoint: ${JSON.stringify(res)}`, NS); + logger.debug(() => `Adding endpoint: ${JSON.stringify(res)}`, NS); } private getChannelMask(channels: number[]): number { @@ -228,7 +228,7 @@ export class ZBOSSDriver extends EventEmitter { }, 20000, ); - logger.debug(`Forming network: ${JSON.stringify(res)}`, NS); + logger.debug(() => `Forming network: ${JSON.stringify(res)}`, NS); } public async stop(): Promise { @@ -238,7 +238,7 @@ export class ZBOSSDriver extends EventEmitter { } private onFrame(frame: ZBOSSFrame): void { - logger.debug(`<== Frame: ${JSON.stringify(frame)}`, NS); + logger.debug(() => `<== Frame: ${JSON.stringify(frame)}`, NS); const handled = this.waitress.resolve(frame); @@ -252,7 +252,7 @@ export class ZBOSSDriver extends EventEmitter { } public async execCommand(commandId: number, params: KeyValue = {}, timeout: number = 10000): Promise { - logger.debug(`==> ${CommandId[commandId]}(${commandId}): ${JSON.stringify(params)}`, NS); + logger.debug(() => `==> ${CommandId[commandId]}(${commandId}): ${JSON.stringify(params)}`, NS); if (!this.port.portOpen) { throw new Error('Connection not initialized'); @@ -265,7 +265,7 @@ export class ZBOSSDriver extends EventEmitter { this.tsn = (this.tsn + 1) & 255; try { - logger.debug(`==> FRAME: ${JSON.stringify(frame)}`, NS); + logger.debug(() => `==> FRAME: ${JSON.stringify(frame)}`, NS); await this.port.sendFrame(frame); const response = await waiter.start().promise; diff --git a/src/adapter/zboss/uart.ts b/src/adapter/zboss/uart.ts index 1db8d7ec0a..8355ee950c 100644 --- a/src/adapter/zboss/uart.ts +++ b/src/adapter/zboss/uart.ts @@ -217,7 +217,9 @@ export class ZBOSSUart extends EventEmitter { const isFirst = ((pFlags >> 6) & 0x1) === 1; const isLast = ((pFlags >> 7) & 0x1) === 1; logger.debug( - `<-- package type ${pType}, flags ${pFlags.toString(16)}` + `${JSON.stringify({isACK, retransmit, sequence, ACKseq, isFirst, isLast})}`, + () => + `<-- package type ${pType}, flags ${pFlags.toString(16)}` + + `${JSON.stringify({isACK, retransmit, sequence, ACKseq, isFirst, isLast})}`, NS, ); @@ -283,7 +285,8 @@ export class ZBOSSUart extends EventEmitter { const isFirst = ((flags >> 6) & 0x1) === 1; const isLast = ((flags >> 7) & 0x1) === 1; logger.debug( - `--> package type ${ZBOSS_NCP_API_HL}, flags ${flags.toString(16)}` + + () => + `--> package type ${ZBOSS_NCP_API_HL}, flags ${flags.toString(16)}` + `${JSON.stringify({isACK, retransmit, sequence, ACKseq, isFirst, isLast})}`, NS, ); @@ -371,7 +374,8 @@ export class ZBOSSUart extends EventEmitter { const isFirst = ((flags >> 6) & 0x1) === 1; const isLast = ((flags >> 7) & 0x1) === 1; logger.debug( - `--> package type ${ZBOSS_NCP_API_HL}, flags ${flags.toString(16)}` + + () => + `--> package type ${ZBOSS_NCP_API_HL}, flags ${flags.toString(16)}` + `${JSON.stringify({isACK, retransmit, sequence, ACKseq, isFirst, isLast})}`, NS, ); diff --git a/src/adapter/zigate/adapter/zigateAdapter.ts b/src/adapter/zigate/adapter/zigateAdapter.ts index ebfc40bab9..67cb0d2b8f 100644 --- a/src/adapter/zigate/adapter/zigateAdapter.ts +++ b/src/adapter/zigate/adapter/zigateAdapter.ts @@ -111,7 +111,7 @@ class ZiGateAdapter extends Adapter { ieeeAddr: networkResponse.payload.extendedAddress, endpoints: coordinatorEndpoints.slice(), // copy }; - logger.debug(`getCoordinator ${JSON.stringify(response)}`, NS); + logger.debug(() => `getCoordinator ${JSON.stringify(response)}`, NS); return response; } @@ -358,7 +358,7 @@ class ZiGateAdapter extends Adapter { endpoints: epList, }; - logger.debug(`ActiveEndpoints response: ${JSON.stringify(payloadAE)}`, NS); + logger.debug(() => `ActiveEndpoints response: ${JSON.stringify(payloadAE)}`, NS); return payloadAE; } catch (error) { logger.error(`RECEIVING ActiveEndpoints FAILED, ${error}`, NS); @@ -660,7 +660,7 @@ class ZiGateAdapter extends Adapter { dataLength: data.length, data: data, }; - logger.debug(`sendZclFrameToAll ${JSON.stringify(payload)}`, NS); + logger.debug(() => `sendZclFrameToAll ${JSON.stringify(payload)}`, NS); await this.driver.sendCommand(ZiGateCommandCode.RawAPSDataRequest, payload, undefined, {}, true); await Wait(200); @@ -797,7 +797,7 @@ class ZiGateAdapter extends Adapter { } private leaveIndicationListener(data: {ziGateObject: ZiGateObject}): void { - logger.debug(`LeaveIndication ${JSON.stringify(data)}`, NS); + logger.debug(() => `LeaveIndication ${JSON.stringify(data)}`, NS); const payload: Events.DeviceLeavePayload = { networkAddress: data.ziGateObject.payload.extendedAddress, ieeeAddr: data.ziGateObject.payload.extendedAddress, diff --git a/src/adapter/zigate/driver/frame.ts b/src/adapter/zigate/driver/frame.ts index 6b7f298a60..3d78ea9004 100644 --- a/src/adapter/zigate/driver/frame.ts +++ b/src/adapter/zigate/driver/frame.ts @@ -88,7 +88,7 @@ export default class ZiGateFrame { this.buildChunks(decodedFrame); try { - if (this.readMsgCode() !== 0x8001) logger.debug(`${JSON.stringify(this)}`, NS); + if (this.readMsgCode() !== 0x8001) logger.debug(() => `${JSON.stringify(this)}`, NS); } catch (error) { logger.error((error as Error).stack!, NS); } diff --git a/src/adapter/zigate/driver/zigate.ts b/src/adapter/zigate/driver/zigate.ts index cf10cc605e..262a77019b 100644 --- a/src/adapter/zigate/driver/zigate.ts +++ b/src/adapter/zigate/driver/zigate.ts @@ -83,7 +83,8 @@ export default class ZiGate extends EventEmitter { return this.queue.execute(async () => { try { logger.debug( - 'Send command \x1b[32m>>>> ' + + () => + 'Send command \x1b[32m>>>> ' + ZiGateCommandCode[code] + ' 0x' + zeroPad(code) + @@ -92,7 +93,7 @@ export default class ZiGate extends EventEmitter { ); const ziGateObject = ZiGateObject.createRequest(code, payload); const frame = ziGateObject.toZiGateFrame(); - logger.debug(`${JSON.stringify(frame)}`, NS); + logger.debug(() => `${JSON.stringify(frame)}`, NS); const sendBuffer = frame.toBuffer(); logger.debug(`<-- send command ${sendBuffer.toString('hex')}`, NS); @@ -263,7 +264,7 @@ export default class ZiGate extends EventEmitter { private onSerialData(buffer: Buffer): void { try { - // logger.debug(`--- parseNext ${JSON.stringify(buffer)}`, NS); + // logger.debug(() => `--- parseNext ${JSON.stringify(buffer)}`, NS); const frame = new ZiGateFrame(buffer); if (!(frame instanceof ZiGateFrame)) return; // @Todo fix @@ -275,7 +276,7 @@ export default class ZiGate extends EventEmitter { try { const ziGateObject = ZiGateObject.fromZiGateFrame(frame); - logger.debug(`${JSON.stringify(ziGateObject.payload)}`, NS); + logger.debug(() => `${JSON.stringify(ziGateObject.payload)}`, NS); this.waitress.resolve(ziGateObject); switch (code) { diff --git a/src/controller/controller.ts b/src/controller/controller.ts index 091e7e640c..f97e523197 100644 --- a/src/controller/controller.ts +++ b/src/controller/controller.ts @@ -579,7 +579,7 @@ class Controller extends events.EventEmitter { } private async onDeviceJoinedGreenPower(payload: GreenPowerDeviceJoinedPayload): Promise { - logger.debug(`Green power device '${JSON.stringify(payload)}' joined`, NS); + logger.debug(() => `Green power device '${JSON.stringify(payload)}' joined`, NS); // Green power devices don't have an ieeeAddr, the sourceID is unique and static so use this. let ieeeAddr = payload.sourceID.toString(16); diff --git a/src/controller/model/endpoint.ts b/src/controller/model/endpoint.ts index cc8231003c..cf7fc328bb 100644 --- a/src/controller/model/endpoint.ts +++ b/src/controller/model/endpoint.ts @@ -542,7 +542,7 @@ class Endpoint extends Entity { } catch (error) { const err = error as Error; err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + logger.debug(err.stack!, NS); throw error; } } @@ -593,7 +593,7 @@ class Endpoint extends Entity { } catch (error) { const err = error as Error; err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + logger.debug(err.stack!, NS); throw error; } } @@ -714,10 +714,10 @@ class Endpoint extends Entity { optionsWithDefaults.reservedBits, ); - const log = + const createLogMessage = (): string => `CommandResponse ${this.deviceIeeeAddress}/${this.ID} ` + `${cluster.name}.${command.name}(${JSON.stringify(payload)}, ${JSON.stringify(optionsWithDefaults)})`; - logger.debug(log, NS); + logger.debug(createLogMessage, NS); try { await this.sendRequest(frame, optionsWithDefaults, async (f) => { @@ -739,8 +739,8 @@ class Endpoint extends Entity { }); } catch (error) { const err = error as Error; - err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + err.message = `${createLogMessage()} failed (${err.message})`; + logger.debug(err.stack!, NS); throw error; } } @@ -902,10 +902,10 @@ class Endpoint extends Entity { optionsWithDefaults.reservedBits, ); - const log = + const createLogMessage = (): string => `ZCL command ${this.deviceIeeeAddress}/${this.ID} ` + `${cluster.name}.${command.name}(${JSON.stringify(logPayload ? logPayload : payload)}, ${JSON.stringify(optionsWithDefaults)})`; - logger.debug(log, NS); + logger.debug(createLogMessage, NS); try { const result = await this.sendRequest(frame, optionsWithDefaults); @@ -919,8 +919,8 @@ class Endpoint extends Entity { } } catch (error) { const err = error as Error; - err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + err.message = `${createLogMessage()} failed (${err.message})`; + logger.debug(err.stack!, NS); throw error; } } @@ -952,10 +952,12 @@ class Endpoint extends Entity { optionsWithDefaults.reservedBits, ); - const log = - `ZCL command broadcast ${this.deviceIeeeAddress}/${sourceEndpoint} to ${destination}/${endpoint} ` + - `${cluster.name}.${command.name}(${JSON.stringify({payload, optionsWithDefaults})})`; - logger.debug(log, NS); + logger.debug( + () => + `ZCL command broadcast ${this.deviceIeeeAddress}/${sourceEndpoint} to ${destination}/${endpoint} ` + + `${cluster.name}.${command.name}(${JSON.stringify({payload, optionsWithDefaults})})`, + NS, + ); // if endpoint===0xFF ("broadcast endpoint"), deliver to all endpoints supporting cluster, should be avoided whenever possible await Entity.adapter!.sendZclFrameToAll(endpoint, frame, sourceEndpoint, destination); diff --git a/src/controller/model/group.ts b/src/controller/model/group.ts index 0487221712..82cc28daef 100644 --- a/src/controller/model/group.ts +++ b/src/controller/model/group.ts @@ -198,8 +198,9 @@ class Group extends Entity { } } - const log = `Write ${this.groupID} ${cluster.name}(${JSON.stringify(attributes)}, ${JSON.stringify(optionsWithDefaults)})`; - logger.debug(log, NS); + const createLogMessage = (): string => + `Write ${this.groupID} ${cluster.name}(${JSON.stringify(attributes)}, ${JSON.stringify(optionsWithDefaults)})`; + logger.debug(createLogMessage, NS); try { const frame = Zcl.Frame.create( @@ -218,8 +219,8 @@ class Group extends Entity { await Entity.adapter!.sendZclFrameToGroup(this.groupID, frame, optionsWithDefaults.srcEndpoint); } catch (error) { const err = error as Error; - err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + err.message = `${createLogMessage()} failed (${err.message})`; + logger.debug(err.stack!, NS); throw error; } @@ -247,15 +248,16 @@ class Group extends Entity { optionsWithDefaults.reservedBits, ); - const log = `Read ${this.groupID} ${cluster.name}(${JSON.stringify(attributes)}, ${JSON.stringify(optionsWithDefaults)})`; - logger.debug(log, NS); + const createLogMessage = (): string => + `Read ${this.groupID} ${cluster.name}(${JSON.stringify(attributes)}, ${JSON.stringify(optionsWithDefaults)})`; + logger.debug(createLogMessage, NS); try { await Entity.adapter!.sendZclFrameToGroup(this.groupID, frame, optionsWithDefaults.srcEndpoint); } catch (error) { const err = error as Error; - err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + err.message = `${createLogMessage()} failed (${err.message})`; + logger.debug(err.stack!, NS); throw error; } @@ -266,8 +268,8 @@ class Group extends Entity { const cluster = Zcl.Utils.getCluster(clusterKey, undefined, {}); const command = cluster.getCommand(commandKey); - const log = `Command ${this.groupID} ${cluster.name}.${command.name}(${JSON.stringify(payload)})`; - logger.debug(log, NS); + const createLogMessage = (): string => `Command ${this.groupID} ${cluster.name}.${command.name}(${JSON.stringify(payload)})`; + logger.debug(createLogMessage, NS); try { const frame = Zcl.Frame.create( @@ -286,8 +288,8 @@ class Group extends Entity { await Entity.adapter!.sendZclFrameToGroup(this.groupID, frame, optionsWithDefaults.srcEndpoint); } catch (error) { const err = error as Error; - err.message = `${log} failed (${err.message})`; - logger.debug((err as Error).stack!, NS); + err.message = `${createLogMessage()} failed (${err.message})`; + logger.debug(err.stack!, NS); throw error; } diff --git a/src/utils/logger.ts b/src/utils/logger.ts index 6866d3a151..a3611d8441 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -1,15 +1,18 @@ export interface Logger { - debug: (message: string, namespace: string) => void; - info: (message: string, namespace: string) => void; - warning: (message: string, namespace: string) => void; - error: (message: string, namespace: string) => void; + debug: (messageOrLambda: string | (() => string), namespace: string) => void; + info: (messageOrLambda: string | (() => string), namespace: string) => void; + warning: (messageOrLambda: string | (() => string), namespace: string) => void; + error: (messageOrLambda: string | (() => string), namespace: string) => void; } export let logger: Logger = { - debug: (message, namespace) => console.debug(`${namespace}: ${message}`), - info: (message, namespace) => console.info(`${namespace}: ${message}`), - warning: (message, namespace) => console.warn(`${namespace}: ${message}`), - error: (message, namespace) => console.error(`${namespace}: ${message}`), + debug: (messageOrLambda, namespace) => + console.debug(`${namespace}: ${typeof messageOrLambda === 'function' ? messageOrLambda() : messageOrLambda}`), + info: (messageOrLambda, namespace) => console.info(`${namespace}: ${typeof messageOrLambda === 'string' ? messageOrLambda : messageOrLambda()}`), + warning: (messageOrLambda, namespace) => + console.warn(`${namespace}: ${typeof messageOrLambda === 'function' ? messageOrLambda() : messageOrLambda}`), + error: (messageOrLambda, namespace) => + console.error(`${namespace}: ${typeof messageOrLambda === 'function' ? messageOrLambda() : messageOrLambda}`), }; export function setLogger(l: Logger): void { diff --git a/test/adapter/z-stack/znp.test.ts b/test/adapter/z-stack/znp.test.ts index eb30e98bf8..bd25d2b012 100644 --- a/test/adapter/z-stack/znp.test.ts +++ b/test/adapter/z-stack/znp.test.ts @@ -5,8 +5,17 @@ import {Constants as UnpiConstants, Frame as UnpiFrame} from '../../../src/adapt import {Znp, ZpiObject} from '../../../src/adapter/z-stack/znp'; import BuffaloZnp from '../../../src/adapter/z-stack/znp/buffaloZnp'; import ParameterType from '../../../src/adapter/z-stack/znp/parameterType'; +import {logger, setLogger} from '../../../src/utils/logger'; import {duplicateArray, ieeeaAddr1, ieeeaAddr2} from '../../testUtils'; +const mockLogger = { + debug: jest.fn(), + info: jest.fn(), + warning: jest.fn(), + error: jest.fn(), +}; + +const consoleLogger = logger; const mockSerialPortClose = jest.fn().mockImplementation((cb) => (cb ? cb() : null)); const mockSerialPortFlush = jest.fn().mockImplementation((cb) => cb()); const mockSerialPortAsyncFlushAndClose = jest.fn(); @@ -518,7 +527,7 @@ describe('ZNP', () => { } expect(error).toStrictEqual( - new Error("SREQ '--> SYS - osalNvRead - {\"id\":1,\"offset\":2}' failed with status '(0x01: FAILURE)' (expected '(0x00: SUCCESS)')"), + new Error("--> 'SREQ: SYS - osalNvRead - {\"id\":1,\"offset\":2}' failed with status '(0x01: FAILURE)' (expected '(0x00: SUCCESS)')"), ); }); @@ -550,7 +559,7 @@ describe('ZNP', () => { } expect(error).toStrictEqual( - new Error("SREQ '--> SYS - osalNvRead - {\"id\":1,\"offset\":2}' failed with status '(0x01: FAILURE)' (expected '(0x00: SUCCESS)')"), + new Error("--> 'SREQ: SYS - osalNvRead - {\"id\":1,\"offset\":2}' failed with status '(0x01: FAILURE)' (expected '(0x00: SUCCESS)')"), ); }); @@ -1308,4 +1317,9 @@ describe('ZNP', () => { buffalo.read(ParameterType.LIST_ASSOC_DEV, {length: 1}); }).toThrow(`Cannot read LIST_ASSOC_DEV without startIndex option specified`); }); + + it('Coverage logger', async () => { + consoleLogger.warning(() => 'Test warning', 'TestNS'); + consoleLogger.error(() => 'Test error', 'TestNS'); + }); }); diff --git a/test/controller.test.ts b/test/controller.test.ts index a60f891a0a..0e1fe517e5 100755 --- a/test/controller.test.ts +++ b/test/controller.test.ts @@ -26,7 +26,9 @@ const globalSetImmediate = setImmediate; const flushPromises = () => new Promise(globalSetImmediate); const mockLogger = { - debug: jest.fn(), + debug: jest.fn((messageOrLambda) => { + if (typeof messageOrLambda === 'function') messageOrLambda(); + }), info: jest.fn(), warning: jest.fn(), error: jest.fn(),