feat: Unified logging across z2m/zh/zhc (#21984)

* Unified logging across z2m/zh/zhc

* Updates

---------

Co-authored-by: Koen Kanters <koenkanters94@gmail.com>

lib/controller.ts

@@ -8,7 +8,8 @@ import utils from './util/utils';
 import stringify from 'json-stable-stringify-without-jsonify';
 import assert from 'assert';
 import bind from 'bind-decorator';
-import * as zhc from 'zigbee-herdsman-converters';
+import {setLogger as zhcSetLogger} from 'zigbee-herdsman-converters';
+import {setLogger as zhSetLogger} from 'zigbee-herdsman';
 
 // Extensions
 import ExtensionFrontend from './extension/frontend';
@@ -60,6 +61,8 @@ export class Controller {
 
     constructor(restartCallback: () => void, exitCallback: (code: number, restart: boolean) => void) {
         logger.init();
+        zhSetLogger(logger);
+        zhcSetLogger(logger);
         this.eventBus = new EventBus();
         this.zigbee = new Zigbee(this.eventBus);
         this.mqtt = new MQTT(this.eventBus);
@@ -92,8 +95,6 @@ export class Controller {
             /* istanbul ignore next */
             settings.get().advanced.soft_reset_timeout !== 0 && new ExtensionSoftReset(...this.extensionArgs),
         ].filter((n) => n);
-
-        zhc.setLogger(logger);
     }
 
     async start(): Promise<void> {
@@ -138,9 +139,9 @@ export class Controller {
         // Enable zigbee join
         try {
             if (settings.get().permit_join) {
-                logger.warn('`permit_join` set to  `true` in configuration.yaml.');
+                logger.warning('`permit_join` set to  `true` in configuration.yaml.');
-                logger.warn('Allowing new devices to join.');
+                logger.warning('Allowing new devices to join.');
-                logger.warn('Set `permit_join` to `false` once you joined all devices.');
+                logger.warning('Set `permit_join` to `false` once you joined all devices.');
             }
 
             await this.zigbee.permitJoin(settings.get().permit_join);

lib/extension/availability.ts

@@ -87,7 +87,7 @@ export default class Availability extends Extension {
                 logger.debug(`Successfully pinged '${device.name}' (attempt ${i + 1}/${attempts})`);
                 break;
             } catch (error) {
-                logger.warn(`Failed to ping '${device.name}' (attempt ${i + 1}/${attempts}, ${error.message})`);
+                logger.warning(`Failed to ping '${device.name}' (attempt ${i + 1}/${attempts}, ${error.message})`);
                 // Try again in 3 seconds.
                 const lastAttempt = i - 1 === attempts;
                 !lastAttempt && await utils.sleep(3);

lib/extension/bind.ts

@@ -394,7 +394,7 @@ export default class Bind extends Extension {
                     await endpoint.configureReporting(bind.cluster.name, items);
                     logger.info(`Successfully setup reporting for '${entity}' cluster '${bind.cluster.name}'`);
                 } catch (error) {
-                    logger.warn(`Failed to setup reporting for '${entity}' cluster '${bind.cluster.name}'`);
+                    logger.warning(`Failed to setup reporting for '${entity}' cluster '${bind.cluster.name}'`);
                 }
             }
         }
@@ -436,7 +436,7 @@ export default class Bind extends Extension {
                     await endpoint.configureReporting(cluster, items);
                     logger.info(`Successfully disabled reporting for '${entity}' cluster '${cluster}'`);
                 } catch (error) {
-                    logger.warn(`Failed to disable reporting for '${entity}' cluster '${cluster}'`);
+                    logger.warning(`Failed to disable reporting for '${entity}' cluster '${cluster}'`);
                 }
             }
 

lib/extension/configure.ts

@@ -35,7 +35,7 @@ export default class Configure extends Extension {
             }
 
             if (!device.definition || !device.definition.configure) {
-                logger.warn(`Skipping configure of '${device.name}', device does not require this.`);
+                logger.warning(`Skipping configure of '${device.name}', device does not require this.`);
                 return;
             }
 

lib/extension/homeassistant.ts

@@ -128,7 +128,7 @@ export default class HomeAssistant extends Extension {
 
     override async start(): Promise<void> {
         if (!settings.get().advanced.cache_state) {
-            logger.warn('In order for Home Assistant integration to work properly set `cache_state: true');
+            logger.warning('In order for Home Assistant integration to work properly set `cache_state: true');
         }
 
         this.zigbee2MQTTVersion = (await utils.getZigbee2MQTTVersion(false)).version;

lib/extension/legacy/bridgeLegacy.ts

@@ -445,7 +445,7 @@ export default class BridgeLegacy extends Extension {
                 stringify({type: `touchlink`, message: 'reset_success', meta: {status: 'success'}}),
             );
         } else {
-            logger.warn('Failed to factory reset device through Touchlink');
+            logger.warning('Failed to factory reset device through Touchlink');
             this.mqtt.publish(
                 'bridge/log',
                 stringify({type: `touchlink`, message: 'reset_failed', meta: {status: 'failed'}}),

lib/extension/legacy/deviceGroupMembership.ts

@@ -36,7 +36,7 @@ export default class DeviceGroupMembership extends Extension {
         );
 
         if (!response) {
-            logger.warn(`Couldn't get group membership of ${device.ieeeAddr}`);
+            logger.warning(`Couldn't get group membership of ${device.ieeeAddr}`);
             return;
         }
 

lib/extension/legacy/softReset.ts

@@ -39,16 +39,16 @@ export default class SoftReset extends Extension {
     }
 
     private async handleTimeout(): Promise<void> {
-        logger.warn('Soft reset timeout triggered');
+        logger.warning('Soft reset timeout triggered');
 
         try {
             await this.zigbee.reset('soft');
-            logger.warn('Soft reset ZNP due to timeout');
+            logger.warning('Soft reset ZNP due to timeout');
         } catch (error) {
-            logger.warn('Soft reset failed, trying stop/start');
+            logger.warning('Soft reset failed, trying stop/start');
 
             await this.zigbee.stop();
-            logger.warn('Zigbee stopped');
+            logger.warning('Zigbee stopped');
 
             try {
                 await this.zigbee.start();

lib/util/logger.ts

@@ -7,20 +7,8 @@ import fx from 'mkdir-recursive';
 import {rimrafSync} from 'rimraf';
 import assert from 'assert';
 
-const colorizer = winston.format.colorize();
+const LOG_LEVELS = ['error', 'warning', 'info', 'debug'] as const;
-
+type LogLevel = typeof LOG_LEVELS[number];
-type Z2MLogLevel = 'warn' | 'debug' | 'info' | 'error';
-type WinstonLogLevel = 'warning' | 'debug' | 'info' | 'error';
-
-const z2mToWinstonLevel = (level: Z2MLogLevel): WinstonLogLevel => level === 'warn' ? 'warning' : level;
-const winstonToZ2mLevel = (level: WinstonLogLevel): Z2MLogLevel => level === 'warning' ? 'warn' : level;
-
-const levelWithCompensatedLength: {[s: string]: string} = {
-    'info': 'info ',
-    'error': 'error',
-    'warn': 'warn ',
-    'debug': 'debug',
-};
 
 let logger: winston.Logger;
 let fileTransport : winston.transport;
@@ -32,14 +20,36 @@ let transportsToUse: winston.transport[];
 function init(): void {
     // What transports to enable
     output = settings.get().advanced.log_output;
-
     // Directory to log to
     const timestamp = moment(Date.now()).format('YYYY-MM-DD.HH-mm-ss');
     directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', timestamp);
     logFilename = settings.get().advanced.log_file.replace('%TIMESTAMP%', timestamp);
+    // Determine the log level.
+    const settingLevel = settings.get().advanced.log_level;
+    // workaround for syslog<>npm level conflict
+    const level = settingLevel === 'warn' ? 'warning' : settingLevel;
+
+    assert(LOG_LEVELS.includes(level), `'${level}' is not valid log_level, use one of '${LOG_LEVELS.join(', ')}'`);
+
+    const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format);
+
+    // Setup default console logger
+    transportsToUse = [
+        new winston.transports.Console({
+            level,
+            silent: !output.includes('console'),
+            // winston.config.syslog.levels sets 'warning' as 'red'
+            format: winston.format.combine(
+                winston.format.colorize({colors: {debug: 'blue', info: 'green', warning: 'yellow', error: 'red'}}),
+                winston.format.printf(/* istanbul ignore next */(info) => {
+                    return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
+                }),
+            ),
+        }),
+    ];
 
-    // Make sure that log directory exists when not logging to stdout only
     if (output.includes('file')) {
+        // Make sure that log directory exists when not logging to stdout only
         fx.mkdirSync(directory);
 
         if (settings.get().advanced.log_symlink_current) {
@@ -51,62 +61,24 @@ function init(): void {
             }
             fs.symlinkSync(actual, current);
         }
-    }
 
-    // Determine the log level.
+        // Add file logger when enabled
-    const z2mLevel = settings.get().advanced.log_level;
+        // NOTE: the initiation of the logger, even when not added as transport tries to create the logging directory
-    const validLevels = ['info', 'error', 'warn', 'debug'];
+        const transportFileOptions: KeyValue = {
-    assert(validLevels.includes(z2mLevel),
+            filename: path.join(directory, logFilename),
-        `'${z2mLevel}' is not valid log_level, use one of '${validLevels.join(', ')}'`);
+            json: false,
-    const level = z2mToWinstonLevel(z2mLevel);
-
-    const timestampFormat = (): string => moment().format(settings.get().advanced.timestamp_format);
-
-    // Setup default console logger
-    transportsToUse = [
-        new winston.transports.Console({
             level,
-            silent: !output.includes('console'),
+            format: winston.format.printf(/* istanbul ignore next */(info) => {
-            format: winston.format.combine(
+                return `[${info.timestamp}] ${info.level}: \t${info.namespace}: ${info.message}`;
-                winston.format.timestamp({format: timestampFormat}),
-                winston.format.printf(/* istanbul ignore next */(info) => {
-                    const {timestamp, level, message} = info;
-                    const l = winstonToZ2mLevel(level as WinstonLogLevel);
-
-                    const plainPrefix = `Zigbee2MQTT:${levelWithCompensatedLength[l]}`;
-                    let prefix = plainPrefix;
-                    if (process.stdout.isTTY) {
-                        prefix = colorizer.colorize(l, plainPrefix);
-                    }
-                    return `${prefix} ${timestamp.split('.')[0]}: ${message}`;
-                }),
-            ),
-        }),
-    ];
-
-    // Add file logger when enabled
-    // NOTE: the initiation of the logger, even when not added as transport tries to create the logging directory
-    const transportFileOptions: KeyValue = {
-        filename: path.join(directory, logFilename),
-        json: false,
-        level,
-        format: winston.format.combine(
-            winston.format.timestamp({format: timestampFormat}),
-            winston.format.printf(/* istanbul ignore next */(info) => {
-                const {timestamp, level, message} = info;
-                const l = winstonToZ2mLevel(level as WinstonLogLevel);
-                return `${levelWithCompensatedLength[l]} ${timestamp.split('.')[0]}: ${message}`;
             }),
-        ),
+        };
-    };
 
-    if (settings.get().advanced.log_rotation) {
+        if (settings.get().advanced.log_rotation) {
-        transportFileOptions.tailable = true;
+            transportFileOptions.tailable = true;
-        transportFileOptions.maxFiles = 3; // Keep last 3 files
+            transportFileOptions.maxFiles = 3; // Keep last 3 files
-        transportFileOptions.maxsize = 10000000; // 10MB
+            transportFileOptions.maxsize = 10000000; // 10MB
-    }
+        }
 
-    if (output.includes('file')) {
         fileTransport = new winston.transports.File(transportFileOptions);
         transportsToUse.push(fileTransport);
     }
@@ -115,19 +87,78 @@ function init(): void {
     if (output.includes('syslog')) {
         // eslint-disable-next-line
         require('winston-syslog').Syslog;
+
         const options: KeyValue = {
             app_name: 'Zigbee2MQTT',
             format: winston.format.printf(/* istanbul ignore next */(info) => {
-                return `${info.message}`;
+                return `${info.namespace}: ${info.message}`;
             }),
             ...settings.get().advanced.log_syslog,
         };
-        if (options.hasOwnProperty('type')) options.type = options.type.toString();
+
-        // @ts-ignore
+        if (options.hasOwnProperty('type')) {
+            options.type = options.type.toString();
+        }
+
+        // @ts-expect-error custom transport
         transportsToUse.push(new winston.transports.Syslog(options));
     }
 
-    logger = winston.createLogger({transports: transportsToUse, levels: winston.config.syslog.levels});
+    logger = winston.createLogger({
+        format: winston.format.combine(
+            winston.format.errors({stack: true}),
+            winston.format.timestamp({format: timestampFormat}),
+        ),
+        transports: transportsToUse,
+        levels: winston.config.syslog.levels,
+    });
+}
+
+function addTransport(transport: winston.transport): void {
+    transport.level = transportsToUse[0].level;
+    logger.add(transport);
+}
+
+// TODO refactor Z2M level to 'warning' to simplify logic
+function getLevel(): LogLevel | 'warn' {
+    let level = transportsToUse[0].level;
+
+    if (level === 'warning') {
+        level = 'warn';
+    }
+
+    return transportsToUse[0].level as LogLevel | 'warn';
+}
+
+function setLevel(level: LogLevel | 'warn'): void {
+    if (level === 'warn') {
+        level = 'warning';
+    }
+
+    logger.transports.forEach((transport) => transport.level = level);
+}
+
+function warning(message: string, namespace: string = 'z2m'): void {
+    // @ts-expect-error syslog level
+    logger.warning(message, {namespace});
+}
+
+function info(message: string, namespace: string = 'z2m'): void {
+    logger.info(message, {namespace});
+}
+
+function debug(message: string, namespace: string = 'z2m'): void {
+    logger.debug(message, {namespace});
+}
+
+function error(message: string, namespace: string = 'z2m'): void {
+    logger.error(message, {namespace});
+}
+
+// Print to user what logging is enabled
+function logOutput(): void {
+    const filename = output.includes('file') ? ` (filename: ${logFilename})` : ``;
+    info(`Logging to ${output.join(', ')}${filename}.`);
 }
 
 // Cleanup any old log directory.
@@ -143,61 +174,12 @@ function cleanup(): void {
         directories.sort((a: KeyValue, b: KeyValue) => b.birth - a.birth);
         directories = directories.slice(10, directories.length);
         directories.forEach((dir) => {
-            logger.debug(`Removing old log directory '${dir.path}'`);
+            debug(`Removing old log directory '${dir.path}'`);
             rimrafSync(dir.path);
         });
     }
 }
 
-// Print to user what logging is enabled
-function logOutput(): void {
-    if (output.includes('file')) {
-        if (output.includes('console')) {
-            logger.info(`Logging to console and directory: '${directory}' filename: ${logFilename}`);
-        } else {
-            logger.info(`Logging to directory: '${directory}' filename: ${logFilename}`);
-        }
-        cleanup();
-    } else if (output.includes('console')) {
-        logger.info(`Logging to console only'`);
-    }
-}
-
-function addTransport(transport: winston.transport): void {
-    transport.level = transportsToUse[0].level;
-    logger.add(transport);
-}
-
-function getLevel(): Z2MLogLevel {
-    return winstonToZ2mLevel(transportsToUse[0].level as WinstonLogLevel);
-}
-
-function setLevel(level: Z2MLogLevel): void {
-    logger.transports.forEach((transport) => transport.level = z2mToWinstonLevel(level as Z2MLogLevel));
-}
-
-function warn(message: string): void {
-    // @ts-expect-error
-    logger.warning(message);
-}
-
-function warning(message: string): void {
-    // @ts-expect-error
-    logger.warning(message);
-}
-
-function info(message: string): void {
-    logger.info(message);
-}
-
-function debug(message: string): void {
-    logger.debug(message);
-}
-
-function error(message: string): void {
-    logger.error(message);
-}
-
 // Workaround for https://github.com/winstonjs/winston/issues/1629.
 // https://github.com/Koenkk/zigbee2mqtt/pull/10905
 /* istanbul ignore next */
@@ -221,6 +203,6 @@ async function end(): Promise<void> {
 }
 
 export default {
-    init, logOutput, warn, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end,
+    init, logOutput, warning, error, info, debug, setLevel, getLevel, cleanup, addTransport, end,
     winston: (): winston.Logger => logger,
 };

lib/util/settings.ts

@@ -80,7 +80,7 @@ const defaults: RecursivePartial<Settings> = {
         log_symlink_current: false,
         log_output: ['console', 'file'],
         log_directory: path.join(data.getPath(), 'log', '%TIMESTAMP%'),
-        log_file: 'log.txt',
+        log_file: 'log.log',
         log_level: /* istanbul ignore next */ process.env.DEBUG ? 'debug' : 'info',
         log_syslog: {},
         pan_id: 0x1a62,

lib/zigbee.ts

@@ -58,7 +58,7 @@ export default class Zigbee {
 
         let startResult;
         try {
-            this.herdsman = new Controller(herdsmanSettings, logger);
+            this.herdsman = new Controller(herdsmanSettings);
             startResult = await this.herdsman.start();
         } catch (error) {
             logger.error(`Error while starting zigbee-herdsman`);
@@ -103,7 +103,7 @@ export default class Zigbee {
         });
         this.herdsman.on('deviceLeave', (data: ZHEvents.DeviceLeavePayload) => {
             const name = settings.getDevice(data.ieeeAddr)?.friendly_name || data.ieeeAddr;
-            logger.warn(`Device '${name}' left the network`);
+            logger.warning(`Device '${name}' left the network`);
             this.eventBus.emitDeviceLeave({ieeeAddr: data.ieeeAddr, name});
         });
         this.herdsman.on('message', async (data: ZHEvents.MessagePayload) => {
@@ -134,11 +134,11 @@ export default class Zigbee {
             };
             if (passlist.length > 0) {
                 if (!passlist.includes(device.ieeeAddr)) {
-                    logger.warn(`Device which is not on passlist connected (${device.ieeeAddr}), removing...`);
+                    logger.warning(`Device which is not on passlist connected (${device.ieeeAddr}), removing...`);
                     await remove(device);
                 }
             } else if (blocklist.includes(device.ieeeAddr)) {
-                logger.warn(`Device on blocklist is connected (${device.ieeeAddr}), removing...`);
+                logger.warning(`Device on blocklist is connected (${device.ieeeAddr}), removing...`);
                 await remove(device);
             }
         }
@@ -162,7 +162,7 @@ export default class Zigbee {
                 const {vendor, description, model} = data.device.definition;
                 logger.info(`Device '${name}' is supported, identified as: ${vendor} ${description} (${model})`);
             } else {
-                logger.warn(`Device '${name}' with Zigbee model '${data.device.zh.modelID}' and manufacturer name ` +
+                logger.warning(`Device '${name}' with Zigbee model '${data.device.zh.modelID}' and manufacturer name ` +
                     `'${data.device.zh.manufacturerName}' is NOT supported, ` +
                     // eslint-disable-next-line max-len
                     `please follow https://www.zigbee2mqtt.io/advanced/support-new-devices/01_support_new_devices.html`);

test/availability.test.js

@@ -10,7 +10,7 @@ import Availability from '../lib/extension/availability';
 import flushPromises from './lib/flushPromises';
 import stringify from 'json-stable-stringify-without-jsonify';
 
-const mocks = [MQTT.publish, logger.warn, logger.debug];
+const mocks = [MQTT.publish, logger.warning, logger.debug];
 const devices = zigbeeHerdsman.devices;
 zigbeeHerdsman.returnDevices.push(
     ...[devices.bulb_color.ieeeAddr, devices.bulb_color_2.ieeeAddr, devices.coordinator.ieeeAddr, devices.remote.ieeeAddr])

test/configure.test.js

@@ -8,7 +8,7 @@ const flushPromises = require('./lib/flushPromises');
 const wait = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
 const stringify = require('json-stable-stringify-without-jsonify');
 
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 
 describe('Configure', () => {
     let controller;
@@ -202,7 +202,7 @@ describe('Configure', () => {
     it('Legacy api: Should skip reconfigure when device does not require this', async () => {
         await MQTT.events.message('zigbee2mqtt/bridge/configure', '0x0017882104a44559');
         await flushPromises();
-        expect(logger.warn).toHaveBeenCalledWith(`Skipping configure of 'TS0601_thermostat', device does not require this.`)
+        expect(logger.warning).toHaveBeenCalledWith(`Skipping configure of 'TS0601_thermostat', device does not require this.`)
     });
 
     it('Should not configure when interview not completed', async () => {

test/controller.test.js

@@ -53,7 +53,7 @@ describe('Controller', () => {
 
     it('Start controller', async () => {
         await controller.start();
-        expect(zigbeeHerdsman.constructor).toHaveBeenCalledWith({"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]},"databasePath":path.join(data.mockDir, "database.db"), "databaseBackupPath":path.join(data.mockDir, "database.db.backup"),"backupPath":path.join(data.mockDir, "coordinator_backup.json"),"acceptJoiningDeviceHandler": expect.any(Function),adapter: {concurrent: null, delay: null, disableLED: false}, "serialPort":{"baudRate":undefined,"rtscts":undefined,"path":"/dev/dummy"}}, logger);
+        expect(zigbeeHerdsman.constructor).toHaveBeenCalledWith({"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]},"databasePath":path.join(data.mockDir, "database.db"), "databaseBackupPath":path.join(data.mockDir, "database.db.backup"),"backupPath":path.join(data.mockDir, "coordinator_backup.json"),"acceptJoiningDeviceHandler": expect.any(Function),adapter: {concurrent: null, delay: null, disableLED: false}, "serialPort":{"baudRate":undefined,"rtscts":undefined,"path":"/dev/dummy"}});
         expect(zigbeeHerdsman.start).toHaveBeenCalledTimes(1);
         expect(zigbeeHerdsman.setTransmitPower).toHaveBeenCalledTimes(0);
         expect(zigbeeHerdsman.permitJoin).toHaveBeenCalledTimes(1);

test/homeassistant.test.js

@@ -993,9 +993,9 @@ describe('HomeAssistant extension', () => {
 
     it('Should warn when starting with cache_state false', async () => {
         settings.set(['advanced', 'cache_state'], false);
-        logger.warn.mockClear();
+        logger.warning.mockClear();
         await resetExtension();
-        expect(logger.warn).toHaveBeenCalledWith("In order for Home Assistant integration to work properly set `cache_state: true");
+        expect(logger.warning).toHaveBeenCalledWith("In order for Home Assistant integration to work properly set `cache_state: true");
     });
 
     it('Should set missing values to null', async () => {

test/legacy/bridgeLegacy.test.js

@@ -25,7 +25,7 @@ describe('Bridge legacy', () => {
         data.writeDefaultConfiguration();
         settings.reRead();
         logger.info.mockClear();
-        logger.warn.mockClear();
+        logger.warning.mockClear();
     });
 
     afterAll(async () => {
@@ -478,6 +478,6 @@ describe('Bridge legacy', () => {
         MQTT.events.message('zigbee2mqtt/bridge/config/touchlink/factory_reset', '');
         await flushPromises();
         expect(zigbeeHerdsman.touchlinkFactoryResetFirst).toHaveBeenCalledTimes(1);
-        expect(logger.warn).toHaveBeenCalledWith('Failed to factory reset device through Touchlink');
+        expect(logger.warning).toHaveBeenCalledWith('Failed to factory reset device through Touchlink');
     });
 });

test/legacy/report.test.js

@@ -16,7 +16,7 @@ const Controller = require('../../lib/controller');
 const flushPromises = require('../lib/flushPromises');
 const wait = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
 
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 
 describe('Report', () => {
     let controller;

test/logger.test.js

@@ -69,6 +69,25 @@ describe('Logger', () => {
         logger.logOutput();
         logger.setLevel('debug');
         expect(logger.getLevel()).toBe('debug');
+        logger.setLevel('info');
+        expect(logger.getLevel()).toBe('info');
+        logger.setLevel('warning');
+        expect(logger.getLevel()).toBe('warning');
+        logger.setLevel('warn');
+        expect(logger.getLevel()).toBe('warning');
+        logger.setLevel('error');
+        expect(logger.getLevel()).toBe('error');
+    });
+
+    it('Set warning when log level is warn', () => {
+        settings.set(['advanced', 'log_level'], 'warn');
+        settings.reRead();
+        const logger = require('../lib/util/logger').default;
+        logger.init();
+        logger.logOutput();
+        expect(logger.getLevel()).toBe('warning');
+        settings.set(['advanced', 'log_level'], 'info');
+        settings.reRead();
     });
 
     it('Add transport', () => {
@@ -84,15 +103,6 @@ describe('Logger', () => {
         expect(logger.winston().transports.length).toBe(3);
     });
 
-    it('Set and get log level warn <-> warning', () => {
-        const logger = require('../lib/util/logger').default;
-        logger.init();
-        logger.logOutput();
-        logger.setLevel('warn');
-        expect(logger.winston().transports[0].level).toBe('warning');
-        expect(logger.getLevel()).toBe('warn');
-    });
-
     it('Logger should be console and file by default', () => {
         const logger = require('../lib/util/logger').default;
         logger.init();
@@ -164,24 +174,29 @@ describe('Logger', () => {
     it('Log', () => {
         const logger = require('../lib/util/logger').default;
         logger.init();
-        const warn = jest.spyOn(logger.winston(), 'warning');
+        logger.setLevel('debug');
-        logger.warn('warn');
-        expect(warn).toHaveBeenCalledWith('warn');
 
         const debug = jest.spyOn(logger.winston(), 'debug');
         logger.debug('debug');
-        expect(debug).toHaveBeenCalledWith('debug');
+        expect(debug).toHaveBeenCalledWith('debug', {namespace: 'z2m'});
-
+        expect(debug).toHaveBeenCalledTimes(1);
-        const warning = jest.spyOn(logger.winston(), 'warning');
-        logger.warning('warning');
-        expect(warning).toHaveBeenCalledWith('warning');
 
         const info = jest.spyOn(logger.winston(), 'info');
         logger.info('info');
-        expect(info).toHaveBeenCalledWith('info');
+        expect(info).toHaveBeenCalledWith('info', {namespace: 'z2m'});
+        expect(info).toHaveBeenCalledTimes(1);
+
+        const warning = jest.spyOn(logger.winston(), 'warning');
+        logger.warning('warning');
+        expect(warning).toHaveBeenCalledWith('warning', {namespace: 'z2m'});
+        expect(warning).toHaveBeenCalledTimes(1);
 
         const error = jest.spyOn(logger.winston(), 'error');
         logger.error('error');
-        expect(error).toHaveBeenCalledWith('error');
+        expect(error).toHaveBeenCalledWith('error', {namespace: 'z2m'});
+
+        logger.error(new Error('error'));// test for stack=true
+        expect(error).toHaveBeenCalledWith('error', {namespace: 'z2m'});
+        expect(error).toHaveBeenCalledTimes(2);
     });
 });

test/networkMap.test.js

@@ -17,7 +17,7 @@ const MQTT = require('./stub/mqtt');
 const settings = require('../lib/util/settings');
 const Controller = require('../lib/controller');
 const flushPromises = require('./lib/flushPromises');
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 const setTimeoutNative = setTimeout;
 
 describe('Networkmap', () => {

test/onEvent.test.js

@@ -8,7 +8,7 @@ const settings = require('../lib/util/settings');
 const Controller = require('../lib/controller');
 const flushPromises = require('./lib/flushPromises');
 
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 
 const zigbeeHerdsmanConverters = require('zigbee-herdsman-converters');
 const mockOnEvent = jest.fn();

test/publish.test.js

@@ -9,7 +9,7 @@ const settings = require('../lib/util/settings');
 const Controller = require('../lib/controller');
 const flushPromises = require('./lib/flushPromises');
 
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 
 const expectNothingPublished = () => {
     Object.values(zigbeeHerdsman.devices).forEach((d) => {

test/receive.test.js

@@ -8,7 +8,7 @@ const settings = require('../lib/util/settings');
 const Controller = require('../lib/controller');
 const flushPromises = require('./lib/flushPromises');
 
-const mocksClear = [MQTT.publish, logger.warn, logger.debug];
+const mocksClear = [MQTT.publish, logger.warning, logger.debug];
 
 describe('Receive', () => {
     let controller;

test/stub/logger.js

@@ -3,10 +3,10 @@ let level = 'info';
 const transports = [];
 
 let transportsEnabled = false;
-const callTransports = (level, message) => {
+const callTransports = (level, message, namespace) => {
     if (transportsEnabled) {
         for (const transport of transports) {
-            transport.log({level, message}, () => {});
+            transport.log({level, message, namespace}, () => {});
         }
     }
 }
@@ -14,7 +14,7 @@ const callTransports = (level, message) => {
 const mock = {
     init: jest.fn(),
     info: jest.fn().mockImplementation((msg) => callTransports('info', msg)),
-    warn: jest.fn().mockImplementation((msg) => callTransports('warn', msg)),
+    warning: jest.fn().mockImplementation((msg) => callTransports('warning', msg)),
     error: jest.fn().mockImplementation((msg) => callTransports('error', msg)),
     debug: jest.fn().mockImplementation((msg) => callTransports('debug', msg)),
     cleanup: jest.fn(),

test/stub/zigbeeHerdsman.js

@@ -261,6 +261,7 @@ const mock = {
 const mockConstructor = jest.fn().mockImplementation(() => mock);
 
 jest.mock('zigbee-herdsman', () => ({
+    ...jest.requireActual('zigbee-herdsman'),
     Controller: mockConstructor,
     Zcl: {ManufacturerCode: {SIGNIFY_NETHERLANDS_B_V: 4107}},
 }));