Skip to content

Commit c6ca472

Browse files
tomer-wtomer-w
authored
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
1 parent 0540e4f commit c6ca472

File tree

7 files changed

+52
-33
lines changed

7 files changed

+52
-33
lines changed

‎lib/mqtt.ts

+2-2
Original file line numberDiff line numberDiff line change
@@ -146,7 +146,7 @@ export default class MQTT {
146146
@bind public onMessage(topic: string, message: Buffer): void {
147147
// Since we subscribe to zigbee2mqtt/# we also receive the message we send ourselves, skip these.
148148
if (!this.publishedTopics.has(topic)) {
149-
logger.debug(`Received MQTT message on '${topic}' with data '${message.toString()}'`, NS);
149+
logger.debug(() => `Received MQTT message on '${topic}' with data '${message.toString()}'`, NS);
150150
this.eventBus.emitMQTTMessage({topic, message: message.toString()});
151151
}
152152

@@ -197,7 +197,7 @@ export default class MQTT {
197197
}
198198

199199
if (!skipLog) {
200-
logger.info(`MQTT publish: topic '${topic}', payload '${payload}'`, NS);
200+
logger.info(() => `MQTT publish: topic '${topic}', payload '${payload}'`, NS);
201201
}
202202

203203
const actualOptions: mqtt.IClientPublishOptions = {...defaultOptions, ...options};

‎lib/util/logger.ts

+10-9
Original file line numberDiff line numberDiff line change
@@ -190,32 +190,33 @@ class Logger {
190190
return this.cachedNamespacedLevels[namespace];
191191
}
192192

193-
private log(level: settings.LogLevel, message: string, namespace: string): void {
193+
private log(level: settings.LogLevel, messageOrLambda: string | (() => string), namespace: string): void {
194194
const nsLevel = this.cacheNamespacedLevel(namespace);
195195

196196
if (settings.LOG_LEVELS.indexOf(level) <= settings.LOG_LEVELS.indexOf(nsLevel)) {
197+
const message: string = messageOrLambda instanceof Function ? messageOrLambda() : messageOrLambda;
197198
this.logger.log(level, `${namespace}: ${message}`);
198199
}
199200
}
200201

201-
public error(message: string, namespace: string = 'z2m'): void {
202-
this.log('error', message, namespace);
202+
public error(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void {
203+
this.log('error', messageOrLambda, namespace);
203204
}
204205

205-
public warning(message: string, namespace: string = 'z2m'): void {
206-
this.log('warning', message, namespace);
206+
public warning(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void {
207+
this.log('warning', messageOrLambda, namespace);
207208
}
208209

209-
public info(message: string, namespace: string = 'z2m'): void {
210-
this.log('info', message, namespace);
210+
public info(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void {
211+
this.log('info', messageOrLambda, namespace);
211212
}
212213

213-
public debug(message: string, namespace: string = 'z2m'): void {
214+
public debug(messageOrLambda: string | (() => string), namespace: string = 'z2m'): void {
214215
if (this.debugNamespaceIgnoreRegex?.test(namespace)) {
215216
return;
216217
}
217218

218-
this.log('debug', message, namespace);
219+
this.log('debug', messageOrLambda, namespace);
219220
}
220221

221222
// Cleanup any old log directory.

‎lib/zigbee.ts

+6-3
Original file line numberDiff line numberDiff line change
@@ -58,8 +58,10 @@ export default class Zigbee {
5858
acceptJoiningDeviceHandler: this.acceptJoiningDeviceHandler,
5959
};
6060

61-
const herdsmanSettingsLog = JSON.stringify(herdsmanSettings).replaceAll(JSON.stringify(herdsmanSettings.network.networkKey), '"HIDDEN"');
62-
logger.debug(`Using zigbee-herdsman with settings: '${stringify(herdsmanSettingsLog)}'`);
61+
logger.debug(
62+
() =>
63+
`Using zigbee-herdsman with settings: '${stringify(JSON.stringify(herdsmanSettings).replaceAll(JSON.stringify(herdsmanSettings.network.networkKey), '"HIDDEN"'))}'`,
64+
);
6365

6466
let startResult;
6567
try {
@@ -115,7 +117,8 @@ export default class Zigbee {
115117
const device = this.resolveDevice(data.device.ieeeAddr)!;
116118
await device.resolveDefinition();
117119
logger.debug(
118-
`Received Zigbee message from '${device.name}', type '${data.type}', ` +
120+
() =>
121+
`Received Zigbee message from '${device.name}', type '${data.type}', ` +
119122
`cluster '${data.cluster}', data '${stringify(data.data)}' from endpoint ${data.endpoint.ID}` +
120123
(data['groupID'] !== undefined ? ` with groupID ${data.groupID}` : ``) +
121124
(device.zh.type === 'Coordinator' ? `, ignoring since it is from coordinator` : ``),

‎test/controller.test.js

+18-5
Original file line numberDiff line numberDiff line change
@@ -325,17 +325,24 @@ describe('Controller', () => {
325325
});
326326

327327
it('Handle mqtt message', async () => {
328+
const eventbus = controller.eventBus;
329+
let spyEventbusEmitMQTTMessage = jest.spyOn(eventbus, 'emitMQTTMessage').mockImplementation();
330+
328331
await controller.start();
329332
logger.debug.mockClear();
330333
await MQTT.events.message('dummytopic', 'dummymessage');
331-
expect(logger.debug).toHaveBeenCalledWith("Received MQTT message on 'dummytopic' with data 'dummymessage'", LOG_MQTT_NS);
334+
expect(spyEventbusEmitMQTTMessage).toHaveBeenCalledWith({topic: 'dummytopic', message: 'dummymessage'});
335+
expect(logger.log).toHaveBeenCalledWith('debug', "Received MQTT message on 'dummytopic' with data 'dummymessage'", LOG_MQTT_NS);
332336
});
333337

334338
it('Skip MQTT messages on topic we published to', async () => {
339+
const eventbus = controller.eventBus;
340+
let spyEventbusEmitMQTTMessage = jest.spyOn(eventbus, 'emitMQTTMessage').mockImplementation();
341+
335342
await controller.start();
336343
logger.debug.mockClear();
337344
await MQTT.events.message('zigbee2mqtt/skip-this-topic', 'skipped');
338-
expect(logger.debug).toHaveBeenCalledWith("Received MQTT message on 'zigbee2mqtt/skip-this-topic' with data 'skipped'", LOG_MQTT_NS);
345+
expect(spyEventbusEmitMQTTMessage).toHaveBeenCalledWith({topic: 'zigbee2mqtt/skip-this-topic', message: 'skipped'});
339346
logger.debug.mockClear();
340347
await controller.mqtt.publish('skip-this-topic', '', {});
341348
await MQTT.events.message('zigbee2mqtt/skip-this-topic', 'skipped');
@@ -355,8 +362,10 @@ describe('Controller', () => {
355362
};
356363
await zigbeeHerdsman.events.message(payload);
357364
await flushPromises();
358-
expect(logger.debug).toHaveBeenCalledWith(
365+
expect(logger.log).toHaveBeenCalledWith(
366+
'debug',
359367
`Received Zigbee message from 'bulb', type 'attributeReport', cluster 'genBasic', data '{"modelId":"TRADFRI bulb E27 WS opal 980lm"}' from endpoint 1`,
368+
'z2m',
360369
);
361370
});
362371

@@ -374,8 +383,10 @@ describe('Controller', () => {
374383
};
375384
await zigbeeHerdsman.events.message(payload);
376385
await flushPromises();
377-
expect(logger.debug).toHaveBeenCalledWith(
386+
expect(logger.log).toHaveBeenCalledWith(
387+
'debug',
378388
`Received Zigbee message from 'bulb', type 'attributeReport', cluster 'genBasic', data '{"modelId":"TRADFRI bulb E27 WS opal 980lm"}' from endpoint 1 with groupID 0`,
389+
'z2m',
379390
);
380391
});
381392

@@ -964,8 +975,10 @@ describe('Controller', () => {
964975
};
965976
await zigbeeHerdsman.events.message(payload);
966977
await flushPromises();
967-
expect(logger.debug).toHaveBeenCalledWith(
978+
expect(logger.log).toHaveBeenCalledWith(
979+
'debug',
968980
`Received Zigbee message from 'Coordinator', type 'attributeReport', cluster 'genBasic', data '{"modelId":null}' from endpoint 1, ignoring since it is from coordinator`,
981+
'z2m',
969982
);
970983
});
971984

‎test/logger.test.js

+3
Original file line numberDiff line numberDiff line change
@@ -164,6 +164,9 @@ describe('Logger', () => {
164164
logger[level]('msg', 'abcd');
165165
expect(logSpy).toHaveBeenLastCalledWith(level, 'abcd: msg');
166166
expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
167+
logger[level](() => 'func msg', 'abcd');
168+
expect(logSpy).toHaveBeenLastCalledWith(level, 'abcd: func msg');
169+
expect(consoleWriteSpy).toHaveBeenCalledTimes(i++);
167170

168171
for (const higherLevel of otherLevels.higher) {
169172
logger[higherLevel]('higher msg');

‎test/publish.test.js

+1-1
Original file line numberDiff line numberDiff line change
@@ -600,7 +600,7 @@ describe('Publish', () => {
600600
await MQTT.events.message(`zigbee2mqtt/${device.ieeeAddr}/set`, stringify({state: 'OFF'}));
601601
await flushPromises();
602602
console.log(logger.error.mock.calls);
603-
expect(logger.error).toHaveBeenCalledWith(`Cannot publish to unsupported device 'button_double_key_interviewing'`);
603+
expect(logger.log).toHaveBeenCalledWith('error', `Cannot publish to unsupported device 'button_double_key_interviewing'`, 'z2m');
604604
});
605605

606606
it('Should log error when device has no such endpoint (via property)', async () => {

‎test/stub/logger.js

+12-13
Original file line numberDiff line numberDiff line change
@@ -1,24 +1,23 @@
11
let level = 'info';
22
let debugNamespaceIgnore = '';
33
let namespacedLevels = {};
4-
54
let transports = [];
6-
75
let transportsEnabled = false;
8-
const callTransports = (level, message, namespace) => {
9-
if (transportsEnabled) {
10-
for (const transport of transports) {
11-
transport.log({level, message, namespace}, () => {});
12-
}
13-
}
14-
};
156

7+
const getMessage = (messageOrLambda) => (messageOrLambda instanceof Function ? messageOrLambda() : messageOrLambda);
168
const mock = {
9+
log: jest.fn().mockImplementation((level, message, namespace = 'z2m') => {
10+
if (transportsEnabled) {
11+
for (const transport of transports) {
12+
transport.log({level, message, namespace}, () => {});
13+
}
14+
}
15+
}),
1716
init: jest.fn(),
18-
info: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('info', msg, namespace)),
19-
warning: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('warning', msg, namespace)),
20-
error: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('error', msg, namespace)),
21-
debug: jest.fn().mockImplementation((msg, namespace = 'z2m') => callTransports('debug', msg, namespace)),
17+
info: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('info', getMessage(messageOrLambda), namespace)),
18+
warning: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('warning', getMessage(messageOrLambda), namespace)),
19+
error: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('error', getMessage(messageOrLambda), namespace)),
20+
debug: jest.fn().mockImplementation((messageOrLambda, namespace = 'z2m') => mock.log('debug', getMessage(messageOrLambda), namespace)),
2221
cleanup: jest.fn(),
2322
logOutput: jest.fn(),
2423
add: (transport) => transports.push(transport),

0 commit comments

Comments
 (0)